性能随机下降

3
我在Go方面还是个新手,最近有些问题让我感到困惑。
我有一段代码(下面是简化版本),我试图对它进行性能测量。我有两种方法:1)使用测试包进行基准测试 2)手动记录时间
运行基准测试输出结果:
30000 55603 ns/op 这很好,但是……当我运行相同函数的30k次并为每个迭代记录时间时,我得到了这样的输出:
test took 0 ns test took 0 ns ... ~10条记录都一样 test took 1000100 ns test took 0 ns test took 0 ns ... 又是很多零 test took 0 ns test took 1000000 ns test took 0 ns
通过计算,可以发现平均值确实是55603 ns/op,就像基准测试所说的那样。
我说,“好吧,我不太擅长优化性能,也不太懂所有的编译器核心知识,但我猜可能是随机垃圾回收?所以我打开了gc日志,确保它有输出,然后彻底关闭了gc......没有垃圾回收,但我看到了同样的情况——有些迭代需要花费一百万倍的时间(?)。”
99%的可能是我的理解哪里出了问题,也许有人可以指点我正确的方向,或者有人确切知道到底发生了什么?:)
另外,对我来说,小于一纳秒(0 ns)有些惊讶,这似乎太快了,但程序确实提供了计算结果,所以我不知道该怎么想了。
编辑1:回答Kenny Grant的问题:我使用goroutine实现了“值生成器”,以实现“懒惰”,现在我已经将它们删除并简化了代码。问题现在少得多了,但仍然可以重现。 Playground链接:https://play.golang.org/p/UQMgtT4Jrf 有趣的是,在playground上没有出现这种情况,但在我的机器上仍然存在。
编辑2:我在win7 x64上运行Go 1.9
编辑3:感谢回复,现在我知道这段代码在playground上无法正常工作。我会在这里重新发布代码片段,以便我们不会失去它。
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笔记本上尝试过相同的操作,输出合理,没有零和百万。看起来这是编译器/运行时库在Windows上的特定问题。如果有人能在他们的机器上验证这个问题(Win 7/8/10),那就太好了。


你应该能够使用代码的较短版本并在此处发布以重现问题。如果没有代码,很难猜测可能出现的问题,最有可能的问题是您的记录代码没有执行您想要的操作或网络停顿。您是否正在使用goroutines? - Kenny Grant
@KennyGrant 好的,稍等一下。 - Nestor Sokil
@KennyGrant 请查看编辑。 - Nestor Sokil
在你的修改之后,现在我很好奇如果你试着运行30次,你会得到什么输出结果?如果是相同的话,如果你使用fmt.Println(k)而不是fmt.Sprint,会得到什么?我不能再重现了,但有希望其他人可以现在我们有代码。 - Kenny Grant
@KennyGrant 打印这些值实际上是我在原始代码中所做的。现在再试一次——没有任何变化。此外,运行30个迭代大多数情况下只会得到0ns,但有时它会输出约10^6 ns。 - Nestor Sokil
2个回答

2
在Windows系统中,由于时间戳不够精确,无法测量如此短暂的持续时间;而Linux系统则拥有更精确的时间戳。Go基准测试设计为至少运行1秒钟。从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。


感谢您的努力。输出结果非常易于理解。 :) - Nestor Sokil
但是,您认为这是否应该报告,还是它是一个特定于平台的问题,无法解决? - Nestor Sokil
1
@NestorSokil:这不是硬件问题。结果来自同一台机器。这是Microsoft Windows操作系统的问题。Linux没有这个问题。Go知道这个问题,并至少运行Go基准测试一秒钟。运行nano基准测试确实是你的问题。 - peterSO
另一个不运行纳米基准测试的原因是摩尔定律。我必须在一台旧而缓慢的笔记本电脑上运行程序,偶尔才能达到零以上。在一台最新款的i7桌面电脑上,我从未达到过零以上。 - peterSO

1
最好消除GC,因为显然记录日志会干扰计时。Playground上的时间包是假的,所以这里不起作用。在本地尝试,使用您提供的代码,我没有得到0纳秒的时间,看起来它正在按照预期工作。
当然,你应该期望一些时间上的变化-当我尝试时,结果都在同一数量级内(非常小的时间为0.000003779秒),但有时会有偶尔的波动,即使你运行30次,有时会增加一倍-但是在这种分辨率下运行计时器不太可能给你可靠的结果,因为它取决于计算机上运行的其他内容、内存布局等。最好尝试用这种方式计时长时间运行的操作,而不是像这个例子那样计时非常短的时间,并计时大量操作并对它们进行平均处理-这就是为什么基准测试工具会给出许多运行的平均值。
由于计时是针对非常短时间的操作,而且差异不大,我认为这是提供的代码的正常行为。0ns的结果是错误的,但可能是由于之前使用了goroutines的结果,如果没有代码很难判断,因为您提供的代码没有给出该结果。

谢谢您的回答。您所说的很有道理,但正如我之前所说,即使是我发布的代码版本,问题对我来说仍然存在。我确实明白在这种情况下所有数字都相对较小,但我仍然觉得这个问题非常奇怪,并且事实上它在别人的机器上不会发生... :-/ - Nestor Sokil
也许你可以编辑一下问题,加上你看到的代码行数,不用管 goroutine 的事情——你是说你看到了一些操作计时为 0ns 吗?我在你发布的代码中没有看到这样的情况。一些变化是可以预料的,0ns 的时间很奇怪,可能是一个 bug。 - Kenny Grant
是的,我确实看到了我给你的片段的0ns输出。我会更新问题并附上截图。 - Nestor Sokil
如果你能让其他人在Windows上测试,你可能能够确认存在问题(我正在Mac OS X上测试)。此外,我会进一步减少你的测试用例 - 你能否在不进行复杂操作的情况下重现这个问题?如果可以,就排除GetKeys等因素。 - Kenny Grant
这个 https://play.golang.org/p/VOk93p0M_6 是代码的最简版本,但我仍然得到了零和百万。 - Nestor Sokil
无法在Ubuntu 17.04上重现。 - Nestor Sokil

网页内容由stack overflow 提供, 点击上面的
可以查看英文原文,
原文链接