验证一下 Go 代码 23x 性能提升过程

Question

缘起

1. 文章1 Good Code vs Bad Code in Golang 中，通过调整代码，达到了30%的性能提升。
2. 文章2 Go code refactoring : the 23x performance hunt 中，通过各种分析以及重构，最终达到了23倍的性能飞跃。

本文，记录一下重复试验的过程，以及自己的一些心得。

验证 30% 性能提升

下载 代码

在bad目录下运行 go test -bench=. > ../bad.bench

在good目录下运行 go test -bench=. > ../good.bench

安装benchcmp go get golang.org/x/tools/cmd/benchcmp

比较性能提升，确实性能提升了 30%。

$ benchcmp bad.bench good.bench
benchmark                         old ns/op     new ns/op     delta
BenchmarkParseAdexpMessage-12     52698         36878         -30.02%

验证 23 倍性能提升

v3 消除 go 关键字的使用

分析一下 CPU 的使用情况： go test -bench=. -cpuprofile profile_cpu.out

查看结果: go tool pprof profile_cpu.out，大量时间是在线程等待。

$ go tool pprof profile_cpu.out
Type: cpu
Time: Jun 7, 2019 at 10:29am (CST)
Duration: 2.51s, Total samples = 7.31s (291.47%)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top10
Showing nodes accounting for 7.16s, 97.95% of 7.31s total
Dropped 68 nodes (cum <= 0.04s)
Showing top 10 nodes out of 47
      flat  flat%   sum%        cum   cum%
     3.63s 49.66% 49.66%      3.63s 49.66%  runtime.pthread_cond_wait
     2.62s 35.84% 85.50%      2.62s 35.84%  runtime.pthread_cond_signal
     0.55s  7.52% 93.02%      0.55s  7.52%  runtime.usleep
     0.23s  3.15% 96.17%      0.23s  3.15%  indexbytebody
     0.08s  1.09% 97.26%      0.08s  1.09%  runtime.pthread_cond_timedwait_relative_np
     0.04s  0.55% 97.81%      0.04s  0.55%  runtime.nanotime
     0.01s  0.14% 97.95%      0.56s  7.66%  runtime.runqgrab
         0     0% 97.95%      0.23s  3.15%  bytes.Index
         0     0% 97.95%      0.23s  3.15%  bytes.IndexByte
         0     0% 97.95%      0.29s  3.97%  golang-learn/GitHub/golang-good-code-bad-code/good.mapLine
(pprof) exit

换种方式，开启 web 看，go tool pprof -http=":8081" profile_trace.out

跟踪图：

火焰图：

TOP 图：

调度跟踪 go test -bench=. -trace profile_trace.out

go tool trace 可以向你揭示：Go 程序运行中的所有的运行时事件。 这种工具是 Go 生态系统中用于诊断性能问题时（如延迟，并行化和竞争异常）最有用的工具之一。详见深入浅出 Go trace

go tool trace  profile_trace.out

goroutine 数量情况（创建了大量的 goroutines）：

调度情况（大量时间在 idle 和任务切换）：

好了，去除 go mapLine(line, ch) 中 go 关键字的使用，然后再运行基准测试。go test -bench=. > ../v3.bench，然后性能提升 17%

 # bingoo @ bingodeMacBook-Pro in ~/GitHub/golang-good-code-bad-code on git:master x [16:29:25]
 $ benchcmp good.bench v3.bench
 benchmark                         old ns/op     new ns/op     delta
 BenchmarkParseAdexpMessage-12     35683         29452         -17.46%

v4 消除 channel 的使用

因为 v3 把 go 关键字去掉了，所以 channel 也没啥用途了，也直接去掉。然后再对比，又获得进一步 8%，累计 48% 的性能提升。

# bingoo @ bingodeMacBook-Pro in ~/GitHub/golang-good-code-bad-code on git:master x [16:31:43]
$ cp -r v3 v4

# bingoo @ bingodeMacBook-Pro in ~/GitHub/golang-good-code-bad-code on git:master x [16:31:47]
$ cd v4/

# bingoo @ bingodeMacBook-Pro in ~/GitHub/golang-good-code-bad-code/v4 on git:master x [16:35:18]
$ go test -bench=. > ../v4.bench

# bingoo @ bingodeMacBook-Pro in ~/GitHub/golang-good-code-bad-code/v4 on git:master x [16:35:27]
$ cd ../
# bingoo @ bingodeMacBook-Pro in ~/GitHub/golang-good-code-bad-code on git:master x [16:35:44]
$ benchcmp v3.bench v4.bench
benchmark                         old ns/op     new ns/op     delta
BenchmarkParseAdexpMessage-12     29452         27028         -8.23%

# bingoo @ bingodeMacBook-Pro in ~/GitHub/golang-good-code-bad-code on git:master x [16:36:14]
$ benchcmp bad.bench  v4.bench
benchmark                         old ns/op     new ns/op     delta
BenchmarkParseAdexpMessage-12     52698         27028         -48.71%

# bingoo @ bingodeMacBook-Pro in ~/GitHub/golang-good-code-bad-code on git:master x [16:36:21]

v5 去除正则匹配版本

在 v4 的基础上，再看一下 trace 和 cpu 的情况：

单协程情况下，始终只有一个线程在干活：

找到新的瓶颈点，parseComplexToken 的 (*Regexp)，FindAll 占据了 0.32s/0.47s=68% 的时间：

正则是一个很方便用来提取数据的工具，强大有时候又可能成为性能杀手。本例子中的正则 -.[^-]*，很简单，可以换成普通的操作来完成。尝试一下：

# bingoo @ bingodeMacBook-Pro in ~/GitHub/golang-good-code-bad-code/v5 on git:master x [17:03:15]
$ go test ./...
ok  	golang-learn/GitHub/golang-good-code-bad-code/v5	0.013s

# bingoo @ bingodeMacBook-Pro in ~/GitHub/golang-good-code-bad-code/v5 on git:master x [17:04:42]
$ go test -bench=. > ../v5.bench

# bingoo @ bingodeMacBook-Pro in ~/GitHub/golang-good-code-bad-code/v5 on git:master x [17:05:00]
$ cd ../

# bingoo @ bingodeMacBook-Pro in ~/GitHub/golang-good-code-bad-code on git:master x [17:05:04]
$ benchcmp v4.bench v5.bench
benchmark                         old ns/op     new ns/op     delta
BenchmarkParseAdexpMessage-12     27028         12622         -53.30%

# bingoo @ bingodeMacBook-Pro in ~/GitHub/golang-good-code-bad-code on git:master x [17:05:19]
$ benchcmp bad.bench  v5.bench
benchmark                         old ns/op     new ns/op     delta
BenchmarkParseAdexpMessage-12     52698         12622         -76.05%

这下子获得进一步53%，累计 76% 的性能提升了。再回头看一下 cpu profile，发现确实正则的瓶颈点消除了。

使用自定义 lex/parser，并结合并发机制，最终性能提升大概在12倍左右。

环境: go 1.12.5, mac Intel(R) Core(TM) i7-8850H CPU @ 2.60GHz 6Core

更多参考

1、 Golang 大杀器之跟踪剖析 trace

go tool trace 能够跟踪捕获各种执行中的事件，例如 Goroutine 的创建/阻塞/解除阻塞，Syscall 的进入/退出/阻止，GC 事件，Heap 的大小改变，Processor 启动/停止等等