基准测试

testing包

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
func add(x, y int) int {
return x + y
}
// 控制执行次数
// 测试工具会逐步调整b.N的值,知道单词执行的累计时间超过了`-benchtime`,默认为1s
// output
// ~ go test -bench . -benchmem -run=NONE
// testing: warning: no tests to run
// 1
// BenchmarkAdd-4          100
// 10000
// 1000000
// 100000000
// 2000000000
// 2000000000               0.36 ns/op            0 B/op          0 allocs/op
// PASS
// ok      _/Users/wuzhenxing/Documents/dev/golang/bench   0.771s
func BenchmarkAdd(b *testing.B) {
println(b.N)
for i := 0; i < b.N; i++ {
_ = add(1, 2)
}
}
// 控制计时器的开关
// 比如在测试函数中某些操作不需要计入基准测试的时间,可以停止,开启,重置Timer等操作
func BenchmarkAddV2(b *testing.B) {
time.Sleep(time.Second)
b.ResetTimer() // 重置Timer
for i := 0; i < b.N; i++ {
_ = add(1, 2)
if i == 1 {
b.StopTimer() // 暂停Timer
time.Sleep(time.Second)
b.StartTimer() // 开始Timer
}
}
}

testing提供了一些工具,主要有b.N, b.StartTimer(), b.StopTimer()等。用于控制基准测试的执行次数,以及计时器。

基准测试工具

基准测试使用go test来运行。一些常用的参数如下:

1
2
3
4
5
-bench regexp regexp可以是任何正则表达式,表示需要运行的基准测试函数。一般可以使用`-bench .`来执行当前目录下所有的基准测试
-benchmen 在输出内容中包含基准测试的内存分配统计信息
-benchtime t t表示执行单个测试函数的累积耗时上限,默认是`1s`
-cpuprofile out 输出cpu profile到指定的路径,可以使用pprof查看
-memprofile out 输出内存profile到指定路径,可以使用pprof查看

比如我们可以执行入下的命令来执行基准测试:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
➜  bench go test -bench . --benchmem -cpuprofile cpu.prof
testing: warning: no tests to run
BenchmarkAdd-4          2000000000               0.36 ns/op            0 B/op          0 allocs/op
PASS
ok      _/Users/wuzhenxing/Documents/dev/golang/bench   0.769s
➜  bench ls # 目录下会生成bench.test的二进制文件和cpu.prof的文件
bench.test    bench_test.go cpu.prof
➜  bench go test -bench . --benchmem -memprofile mem.prof
testing: warning: no tests to run
BenchmarkAdd-4          2000000000               0.37 ns/op            0 B/op          0 allocs/op
PASS
ok      _/Users/wuzhenxing/Documents/dev/golang/bench   0.800s
➜  bench ls # 目录下会生成bench.test的二进制文件和mem.prof的文件
bench.test    bench_test.go mem.prof

pprof

pprof是go提供的性能分析工具,可以分析cpu profile, memory profile,heap profile, block profile等信息。

cpu profile

在基准测试中,我们已经知道怎么生成cpu.prof文件。然后可以利用go tool pprof工具来查看。

1
2
3
4
# usage: pprof [options] [binary] <profile source> ...
# 另外的一个函数生成的基准测试文件
go tool pprof stats.test cpu.prof

使用上面的命令可以得到如下的结果:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
(pprof) top10
1750ms of 2160ms total (81.02%)
Dropped 33 nodes (cum <= 10.80ms)
Showing top 10 nodes out of 54 (cum >= 60ms)
      flat  flat%   sum%        cum   cum%
     560ms 25.93% 25.93%      560ms 25.93%  runtime.mach_semaphore_signal
     290ms 13.43% 39.35%     1320ms 61.11%  runtime.mallocgc
     260ms 12.04% 51.39%      260ms 12.04%  runtime.heapBitsSetType
     190ms  8.80% 60.19%     1220ms 56.48%  runtime.growslice
     110ms  5.09% 65.28%     1280ms 59.26%  github.com/domac/playflame/stats.addTagsToName
      70ms  3.24% 68.52%       70ms  3.24%  runtime.mach_semaphore_wait
      70ms  3.24% 71.76%      280ms 12.96%  runtime.makeslice
      70ms  3.24% 75.00%       70ms  3.24%  runtime.mapaccess2_faststr
      70ms  3.24% 78.24%       70ms  3.24%  runtime.memmove
      60ms  2.78% 81.02%       60ms  2.78%  runtime.memclr

top命令可以查看每个函数的耗时。比如top10可以查看最好时的10个函数。

现在解释一下每一列的意思。

在默认情况下,Go语言的运行时系统会以100 Hz的的频率对CPU使用情况进行取样。也就是说每秒取样100次,即每10毫秒会取样一次。为什么使用这个频率呢?因为100 Hz既足够产生有用的数据,又不至于让系统产生停顿。并且100这个数上也很容易做换算,比如把总取样计数换算为每秒的取样数。实际上,这里所说的对CPU使用情况的取样就是对当前的Goroutine的堆栈上的程序计数器的取样。由此,我们就可以从样本记录中分析出哪些代码是计算时间最长或者说最耗CPU资源的部分了。

  1. 第一列:第一列表示取样点落在该函数里的总数(不包括调用其他函数)。比如github.com/domac/playflame/stats.addTagsToName这个函数,总共执行时间为110ms,那么总的抽样点数为11次,占总共的5.9%(共2160ms,216次)。
  2. 第二列:落在该函数里取样点占总取样点的百分比。
  3. 第三列:top10的默认排序是按第一列排序,也就是按每个函数的执行时间进行排序。第三列的意思是前几行加起来的执行时间占总共执行时间的多少。比如第三行的第三列,表示前三行函数的执行时间加起来占总共执行时间的51.39%。
  4. 第四列:第四列表示取样点落在该函数里和它直接调用,间接调用的的函数里的总数。比如github.com/domac/playflame/stats.addTagsToName这个函数,总时间为1280ms,表示该函数的执行时间加上该函数调用的其他函数的执行时间共1280ms。
  5. 第五列:第四列的时间占总时间的百分比.

top10的输出里我们至少可以知道每个函数的执行时间占比以及每个函数的调用栈的执行时间的占比。如果某个函数自身的执行时间过长,那说明这个函数是否有逻辑错误,是否需要拆分。如果某个函数的调用栈的执行时间过长,是否是因为调用了过多的不需要的函数。

有了初步认识之后,我们可以使用图形化的界面来分析整个函数的执行过程。在这之前,我们需要安装Graphviz。在mac上可以使用:

1
brew install Graphviz

安装好之后,我们可以使用web命令查看。

1
(pprof) web

在上图中,我们就可以对函数的总调用过程有个比较直观的了解。现在对图中的一些箭头,方框做一个解释:

  1. 每个方框代表每个函数本身的执行时间,即第一列的数据,方框越大,说明该函数本身执行时间越长。每个方框里有两行数据,第一行表示该函数本身执行时间,第二行表示该函数的调用栈(该函数以及该函数调用的其他函数)执行总时间。
  2. 箭头表示该函数调用下一个函数所占用的时间,箭头越粗,表示调用函数占用时间越长。

可以看出,图形化的数据主要还是top命令里的数据。只是更直观了点。

查看局部信息

当然,如果我们可能觉得整个太庞大了,会影响我们的判断,我们有事只需要看关注的函数的执行情况。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
(pprof) top addTagsToName
1030ms of 2160ms total (47.69%)
Showing top 10 nodes out of 42 (cum >= 1280ms)
      flat  flat%   sum%        cum   cum%
     280ms 12.96% 12.96%      620ms 28.70%  runtime.mallocgc
     160ms  7.41% 20.37%      160ms  7.41%  runtime.heapBitsSetType
     130ms  6.02% 26.39%      460ms 21.30%  runtime.growslice
     110ms  5.09% 31.48%     1280ms 59.26%  github.com/domac/playflame/stats.addTagsToName
      70ms  3.24% 34.72%      280ms 12.96%  runtime.makeslice
      70ms  3.24% 37.96%       70ms  3.24%  runtime.mapaccess2_faststr
      70ms  3.24% 41.20%       70ms  3.24%  runtime.memmove
      60ms  2.78% 43.98%       60ms  2.78%  runtime.memclr
      40ms  1.85% 45.83%      360ms 16.67%  github.com/domac/playflame/stats.BenchmarkAddTagsToName
      40ms  1.85% 47.69%     1280ms 59.26%  github.com/domac/playflame/stats.TestAddTagsToName

我们可以指定一个函数,这样就会只看到该函数整个调用链的执行情况。

这个可能看起来没啥区别,用web看就清楚很多了。

1
(pprof) web addTagsToName

在上图中,我们就只看到了包含addTagsToName这个函数的调用链的信息了。

list

比如我们找到了一个函数,发现它的执行时间异常,所以想看看它的每一行的执行时间是怎么样的,我们可以使用list

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
ROUTINE ======================== github.com/domac/playflame/stats.addTagsToName in /Users/wuzhenxing/Documents/repos/go_projects/src/github.com/domac/playflame/stats/reporter.go
     110ms      1.28s (flat, cum) 59.26% of Total
         .          .     41:}
         .          .     42:
         .          .     43:func addTagsToName(name string, tags map[string]string) string {
         .          .     44:   // The format we want is: host.endpoint.os.browser
         .          .     45:   // if there's no host tag, then we don't use it.
         .       30ms     46:   keyOrder := make([]string, 0, 4)
         .          .     47:   if _, ok := tags["host"]; ok {
      20ms       20ms     48:           keyOrder = append(keyOrder, "host")
         .          .     49:   }
      10ms      250ms     50:   keyOrder = append(keyOrder, "endpoint", "os", "browser")
         .          .     51:
         .          .     52:   // We tried to pool the object, but perf didn't get better.
         .          .     53:   // It's most likely due to use of defer, which itself has non-trivial overhead.
      20ms      480ms     54:   buf := bufPool.Get().(*bytes.Buffer)
         .          .     55:   buf.Reset()
         .       40ms     56:   defer bufPool.Put(buf)
         .          .     57:   //buf := &bytes.Buffer{}
         .          .     58:   buf.WriteString(name)
         .          .     59:   for _, k := range keyOrder {
         .          .     60:           buf.WriteByte('.')
         .          .     61:
         .          .     62:           v, ok := tags[k]
         .          .     63:           if !ok || v == "" {
         .          .     64:                   buf.WriteString("no-")
         .          .     65:                   buf.WriteString(k)
         .          .     66:                   continue
         .          .     67:           }
         .          .     68:
         .          .     69:           writeClean(buf, v)
         .          .     70:   }
         .          .     71:
      60ms      460ms     72:   return buf.String()
         .          .     73:}
         .          .     74:
         .          .     75:// writeClean cleans value (e.g. replaces special characters with '-') and
         .          .     76:// writes out the cleaned value to buf.
         .          .     77:func writeClean(buf *bytes.Buffer, value string) {

这样我们就能知道函数的整体的执行情况了,第一列的数组表示改行的执行时间,第二列表示改行的总执行时间。

当然我们可以使用weblist在浏览器中进行查看。

1
(pprof) weblist addTagsToName

在浏览器中,我们可以看到命令行一样的结果,但是点击每一行能够看到那一行的汇编信息。当然,使用disasm在命令行也可以做到。

火焰图

为了分析不同软件或软件的不同版本使用CPU的情况,相关设计人员通常需要进行函数的堆栈性能分析。相比于定期采样获得数据的方式,利用定时中断来收集程序运行时的PC寄存器值、函数地址以及整个堆栈轨迹更加高效。目前,OProfile、gprof和SystemTap等工具都是采用该方法,给出详细的CPU使用情况报告。然而,这些工具在处理复杂的统计数据时,给出的报告往往过于繁杂、不够直观、不能直接反应分析员所需要的数据。为此,Brendan Gregg开发了专门把采样到的堆栈轨迹(Stack Trace)转化为直观图片显示的工具——Flame Graph(火焰图)。

火焰图既是一个开源工具,也是一种类型的图片。作为一个二维图片,火焰图的X轴代表采样总量,而Y轴代表栈深度。每个框就代表了一个栈里的函数,其宽度代表了所占用的CPU总时间。因此,比较宽的框就表示该函数运行时间较慢或被调用次数较多,从而占用的CPU时间多。通过火焰图,相关设计或分析人员就可以轻松观察到各个应用占用CPU的情况。

火焰图和使用pprof生成的图形相比,我们可以更直观的看到程序各个部分cpu占用的情况。

go-torch

uber公司开源了一个go-torch的项目,用于生成pprof文件的火焰图。

项目地址:https://github.com/uber/go-torch

我们可以使用go get github.com/uber/go-torch的方式安装。

当然之前需要安装一下火焰图的工具。项目地址:https://github.com/brendangregg/FlameGraph.git

使用git clone https://github.com/brendangregg/FlameGraph.git将项目clone到本地,然后将路径添加到PATH.

生成火焰图

1
2
3
➜  stats git:(master) ✗ go-torch stats.test prof.cpu
INFO[13:19:53] Run pprof command: go tool pprof -raw -seconds 30 stats.test prof.cpu
INFO[13:19:53] Writing svg to torch.svg

使用以上命令,就可以将我们的cpu profile文件转换成火焰图。使用浏览器打开默认的torch.svg就可以看到上面的火焰图了。

在上图中,我们选取了一个函数,我们可以看出,横条的长度代表该函数的总执行时间,上面的层级代表该函数的调用栈的深度,每个横条上面的横条,代表该函数调用了其他函数。

如图所示,横条上面的空白区域,表示该函数本身的执行时间,上面的每一根横条长度,代表调用其他函数所占用的总时间。

所以,通过火焰图,我们可以更直观的看到,每个函数在总的执行时间中所占的比重,长度就是执行时间。而且调用栈通过叠加的方式,也可以更清楚的看到调用的关系。如果某一个函数的执行时间过长,超过了预期,我们就可以分析是本身(空白区域)还是调用其他函数的问题。