本文,记录一下重复试验的过程,以及自己的一些心得。
下载 代码
在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%
分析一下 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 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%
因为 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]
在 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,发现确实正则的瓶颈点消除了。


环境: go 1.12.5, mac Intel(R) Core(TM) i7-8850H CPU @ 2.60GHz 6Core
go tool trace 能够跟踪捕获各种执行中的事件,例如 Goroutine 的创建/阻塞/解除阻塞,Syscall 的进入/退出/阻止,GC 事件,Heap 的大小改变,Processor 启动/停止等等

