性能随机下降

Question

我是 Go 的新手，最近有一些事情让我很困惑。

我有一段代码（下面发布的简化版本），我试图测量它的性能。我用两种方式做到了这一点：1）带有测试包的基准 2）手动记录时间

运行基准输出结果

30000 55603 ns/op

这很好，但是...当我对同一函数执行 30k 次运行并记录每次迭代的时间时，我得到如下输出：

test took 0 ns test took 0 ns ... ~10 records all the same test took 1000100 ns test took 0 ns test took 0 ns ... lots of zeroes again test took 0 ns test took 1000000 ns test took 0 ns ...

计算表明平均值确实 55603 ns/op 正如基准所声称的那样。

好吧，我说过，我在优化性能方面不是那么擅长，在所有硬核编译器的东西中也不擅长，但我猜这可能是随机垃圾收集？所以我打开 gc 日志，确保它显示一些输出，然后关闭 gc 以保持良好的 aaand...没有垃圾收集，但我看到了相同的图片 - 有些迭代需要一百万倍的时间（？）。

我对所有这一切的理解有 99% 是错误的，也许有人能给我指出正确的方向，或者有人确切地知道到底发生了什么？ :)

P.S。此外，对我来说，不到一纳秒 (0 ns) 有点令人惊讶，这似乎太快了，但程序确实提供了计算结果，所以我不知道该想些什么了。 T_T

编辑 1：回答 Kenny Grant 的问题：我使用 goroutines 来实现值的排序生成器以具有惰性，现在我删除了它们并简化了代码。这个问题现在不那么频繁了，但它仍然可以重现。游乐场 link：https://play.golang.org/p/UQMgtT4Jrf 有趣的是，这不会发生在操场上，但仍然会发生在我的机器上。

编辑 2：我是运行在 win7 x64 上运行 1.9

编辑 3：感谢回复，我现在知道这段代码无法在操场上正常工作。我将在此处重新发布代码片段，以免我们丢失它。 :)

type PrefType string
var types []PrefType = []PrefType{
    "TYPE1", "TYPE2", "TYPE3", "TYPE4", "TYPE5", "TYPE6",
}

func GetKeys(key string) []string {
    var result []string
    for _, t := range types {
        rr := doCalculations(t)
        for _, k := range rr {
            result = append(result, key + "." + k)
        }
    }
    return result
}

func doCalculations(prefType PrefType) []string {
    return []string{ string(prefType) + "something", string(prefType) + "else" }
}

func test() {
    start := time.Now()
    keysPrioritized := GetKeys("spec_key")
    for _, k := range keysPrioritized {
        _ = fmt.Sprint(k)
    }
    fmt.Printf("test took %v ns\n", time.Since(start).Nanoseconds())
}

func main() {
    for i := 0; i < 30000; i++  {
        test()
    }
}

这是我机器上的输出：

编辑 4：我在笔记本电脑上使用 Ubuntu 17.04 进行了相同的尝试，输出是合理的，没有零和数百万。似乎是 compiler/runtime 库中的 Windows 特定问题。如果有人可以在他们的机器上验证这一点（Win 7/8/10），那就太好了。

Answer 1

最好消除 GC，因为显然记录它会干扰计时。操场上的时间 pkg 是假的，所以这在那里行不通。在本地尝试使用您提供的代码，我没有得到 0 ns 的时间，看起来它正在按预期工作。

你当然应该期待时间上的一些变化——当我尝试它时，结果都在同一个数量级内（非常小的时间 0.000003779 秒），但即使你运行 30 次，偶尔也会出现短暂的波动，有时会增加一倍 - 但是运行在此分辨率下的计时不太可能为您提供可靠的结果，因为它取决于计算机上运行的其他内容，内存布局等。最好尝试长时间运行以这种方式进行操作，而不是像这样的非常短的时间，并计算大量操作的时间并对其进行平均 - 这就是基准测试工具为您提供这么多次运行的平均值的原因。

由于操作的时间安排非常短，而且差别不大，我认为这是所提供代码的正常行为。 0ns 结果是错误的，但可能是您之前使用 goroutines 的结果，没有代码很难判断，因为您提供的代码不会给出该结果。

Answer 2

在 Windows，对于如此短的持续时间，您没有足够精确的时间戳。 Linux 具有更精确的时间戳。根据设计，Go 基准测试运行至少一秒钟。 Go1.9+使用单调（m）值来计算时长。

在 Windows:

timedur.go:

package main

import (
    "fmt"
    "os"
    "time"
)

type PrefType string

var types []PrefType = []PrefType{
    "TYPE1", "TYPE2", "TYPE3", "TYPE4", "TYPE5", "TYPE6",
}

func GetKeys(key string) []string {
    var result []string
    for _, t := range types {
        rr := doCalculations(t)
        for _, k := range rr {
            result = append(result, key+"."+k)
        }
    }
    return result
}

func doCalculations(prefType PrefType) []string {
    return []string{string(prefType) + "something", string(prefType) + "else"}
}

func test() {
    start := time.Now()
    keysPrioritized := GetKeys("spec_key")
    for _, k := range keysPrioritized {
        _ = fmt.Sprint(k)
    }
    end := time.Now()
    fmt.Printf("test took %v ns\n", time.Since(start).Nanoseconds())
    fmt.Println(start)
    fmt.Println(end)
    if end.Sub(start) < time.Microsecond {
        os.Exit(1)
    }
}

func main() {
    for i := 0; i < 30000; i++ {
        test()
    }
}

输出：

>go run timedur.go
test took 1026000 ns
2017-09-02 14:21:58.1488675 -0700 PDT m=+0.010003700
2017-09-02 14:21:58.1498935 -0700 PDT m=+0.011029700
test took 0 ns
2017-09-02 14:21:58.1538658 -0700 PDT m=+0.015002000
2017-09-02 14:21:58.1538658 -0700 PDT m=+0.015002000
exit status 1
>

在 Linux:

输出：

$ go run timedur.go
test took 113641 ns
2017-09-02 14:52:02.917175333 +0000 UTC m=+0.001041249
2017-09-02 14:52:02.917287569 +0000 UTC m=+0.001153717
test took 23614 ns
2017-09-02 14:52:02.917600301 +0000 UTC m=+0.001466208
2017-09-02 14:52:02.917623585 +0000 UTC m=+0.001489354
test took 22814 ns
2017-09-02 14:52:02.917726364 +0000 UTC m=+0.001592236
2017-09-02 14:52:02.917748805 +0000 UTC m=+0.001614575
test took 21139 ns
2017-09-02 14:52:02.917818409 +0000 UTC m=+0.001684292
2017-09-02 14:52:02.917839184 +0000 UTC m=+0.001704954
test took 21478 ns
2017-09-02 14:52:02.917911899 +0000 UTC m=+0.001777712
2017-09-02 14:52:02.917932944 +0000 UTC m=+0.001798712
test took 31032 ns
<SNIP>

结果具有可比性。它们运行在同一台机器上，双引导 Windows 10 和 Ubuntu 16.04.

性能随机下降

Random drop in performance

windows

performance

benchmarking

go