Go系统性能绕坑工具与方法 - 基于实例的带逛

作者：lni  github.com/lni

业内的共识是Go语言简单易用且一般水平的工程师也能写出较不错的性能。而通过分享相关工具的使用，把较不错的性能升格为过硬的高性能，正是本文的目的。

CPU性能分析

Dragonboat早期版本里，在系统每秒处理100万个写请求的时候CPU基本就被浪费殆尽。事后分析得知，具体成因来自各个不同组件，有自身实现的问题、有踩anti-pattern的坑、也有runtime本身实现不合理之处。作为实现者，面对相对较新的这样一个自带runtime的语言，很难直观从代码本身判断CPU资源的使用情况。

此时，Go内建的CPU性能分析工具可直观的对每行代码的CPU耗时做出统计。在程序中，使用下述runtime/pprof包的方法可以方便的控制CPU性能分析数据捕捉的启动与停止，启停间隔之间的CPU性能分析数据便被捕捉下来供后续分析使用：

func StartCPUProfile(w io.Writer) error func StopCPUProfile() 

比如，StartCPUProfile被给予了一个指向名为cpu.pprof的文件的io.Writer，那么所捕获的数据将被保存在cpu.pprof这一文件中。使用下述命令行命令，可以使用Go内建的pprof工具打开已保存的性能分析数据文件以浏览所捕获的性能细节：

go tool pprof cpu.pprof 

以Dragonboat早期版本的getCluster()方法为例，打开了上述数据分析文件后，可使用list命令列出该方法的具体性能数据。从本例的输出可见，锁操作是性能问题所在，它耗时巨大。

(pprof) list getCluster 20ms 618:func (nh *NodeHost) getCluster(clusterID uint64) (*node, bool) { 3.85s 619: nh.clusterMu.RLock() 640ms 620: v, ok := nh.clusterMu.clusters[clusterID] 1.37s 621: nh.clusterMu.RUnlock() 10ms 622: return v, ok . 623:} 

在上述工具中，可以通过下列命令列出程序耗时前20排名的函数与方法：

(pprof) top20 -cum 

针对输出列表所提及的函数与方法，逐一通过上述list命令，分析其具体CPU耗时的语句，可以方便的定位发现系统中性能异常的部分。

稍进阶的用法里，通过查看系统runtime里内存分配、栈处理、chan读写等等相关函数方法的CPU占用，更可进一步了解runtime、内存使用与核心内建类型等的使用性能情况。以Dragonboat在持续处理写请求时候的内存使用为例，下面的数据是用以分配一个指定字节数的对象mallocgc的CPU耗时，可见它并不是瓶颈：

cum cum% 0.13s 1.95% runtime.mallocgc 

使用net/http/pprof包，可通过web UI方式访问类似性能分析数据，本文基于命令行模式，不对web UI方式做具体介绍，具体web UI模式的用法可参考这里。

CPU profiling应该是最直接了当的性能分析与优化手段，Dragonboat应用本文所介绍的性能分析方法，内存内状态机可在单插22核中档志强上达到千万以上每秒的写性能，500万每秒的P999写延迟在5ms以内。具体优化结果请点这里，也欢迎点star/fork支持。

堆分配分析

与CPU性能分析一样，首先需要收集堆性能数据。在程序退出前，调用runtime/pprof包的WriteHeapProfile()方法，将堆性能数据保存至指定的文件，比如mem.pprof。

func WriteHeapProfile(w io.Writer) error 

使用下列命令行程序打开该性能数据文件：

go tool pprof -alloc_space mem.pprof 

然后使用list命令，可以列出希望查询的函数与方法的内存使用情况。下列函数就是目前Dragonboat尚未做分配优化的部分：

(pprof) list saveRaftState 0 843.29MB (flat, cum) 1.83% of Total . . 104: } . . 105: r.recordSnapshot(wb, ud) . . 106: r.setMaxIndex(wb, ud, ud.Snapshot.Index, ctx) . . 107: } . . 108: } . 840.79MB 109: r.saveEntries(updates, wb, ctx) . . 110: if wb.Count() > 0 { . 2.50MB 111: return r.kvs.CommitWriteBatch(wb) . . 112: } . . 113: return nil . . 114:} 

上述命令行命令使用--alloc_space参数，用以显示WriteHeapProfile()调用时所有已分配的含已释放的堆空间数据，所支持的各模式如下：

-inuse_space 未释放空间数 -inuse_objects 未释放对象数 -alloc_space 所有分配空间数 -alloc_objects 所有分配对象数 

未释放数据指示当前堆内存使用情况，可用来查找未按预期被释放的对象或空间。所有分配空间与对象数据，则给出包括未释放与已释放的对象或空间数据，堆对象的分配与回收均有一定CPU代价，该数据间接提示由堆分配带来的CPU性能开销以及对分配器的压力大小。

既然叫heap profile，它记录呈现的是heap的分配情况，这也就同时提供了一种发现逃逸分析问题的途径。当某对象主观认为应该在stack上，可它却出现在上述heap profile里，这就表示程序本身、自我认知、Go编译器的逃逸分析这三者之一肯定有问题。

锁冲突分析

众所周知，频繁的锁冲突和高性能可以说是水火不容。好消息是Go内建的锁冲突分析支持可以方便地发现这样的锁冲突。在程序中，可以通过runtime.SetMutexProfileFraction()来设置采样频率，通过将其设为一个高于0的值来开启锁冲突分析的数据收集。在程序结束前，通过runtime/pprof包的WriterTo方法将数据保存到指定文件：

runtime.SetMutexProfileFraction(int) pprof.Lookup("mutex").WriteTo(io.Writer, int) 

所得到的锁冲突分析数据假设存为mutex.pprof，它可用go tool pprof在命令行打开：

go tool pprof mutex.pprof 

同样使用list命令，可以查看各个函数与方法的锁冲突情况。下图是在Dragonboat中，使用锁冲突分析以后，通过加大shard数量改善锁冲突的实例。改善前：

(pprof) list nextKey . . 260:func (k *keyGenerator) nextKey() uint64 { . . 261: k.randMu.Lock() . . 262: v := k.rand.Uint64() . 5.33ms 263: k.randMu.Unlock() . . 264: return v . . 265:} . . 662:func (p *pendingProposal) nextKey(clientID uint64) uint64 { . 5.33ms 663: return p.keyg[clientID%p.ps].nextKey() . . 664:} 

增多shard数以减少冲突后：

(pprof) list nextKey . . 260:func (k *keyGenerator) nextKey() uint64 { . . 261: k.randMu.Lock() . . 262: v := k.rand.Uint64() . 2.69ms 263: k.randMu.Unlock() . . 264: return v . . 265:} . . 662:func (p *pendingProposal) nextKey(clientID uint64) uint64 { . 2.69ms 663: return p.keyg[clientID%p.ps].nextKey() . . 664:} 

火焰图分析

有圈内专业人士认为Raft论文是过去十年分布式系统方向最重要论文，个人认为，性能分析方面能获此殊荣的是Brendan Gregg的火焰图含其种类繁多的各变种（dtrace是14年前发布的）。Go 1.11内建了对火焰图的支持：

使用net/http/pprof包的web UI可以方便的直接查看火焰图

火焰图提供了一种最直观的CPU性能分析数据的呈现方式。下图是Dragonboat曾遇到过的性能问题，在系统空闲的情况下CPU占用依旧较高。根据火焰图提示，显著的CPU资源被在反复的调度切换时被浪费，这使得问题很快的定位到runtime本身。

需要指出，Brendan Gregg网站上给出的自行抓取采样数据文件然后渲染出一个火焰图svg的方法由于其通用可扩展特性，能通过各种小技巧实现各种变种火焰图，因此推荐采用Brendan Gregg网站给出的方法。本文标题图片的火焰图就是这样一个例子，它是Dragonboat的内存访问延迟分布情况，它显示runtime部分（图中最右侧）内存性能做的不好，蓝色表示延迟较高，暗示了未来基于runtime改进用户程序性能得到透明提升的空间依旧较大。

Benchmark性能分析

Go自带官方的benchmark跑分库，可以对自己的软件构建跑分测试，方便在不同环境对性能进行方便的分析。Dragonboat中，从内存分配的延迟与带宽、Raft的单节点并发读写性能与Raft Log的落盘性能等等，均自带跑分测试，多次发现Go的Runtime变化带来的性能恶化。

Benchmark的另一大主要用途是可以通过设置命令行开关，在不改变任何代码的情况下，方便地获取前述的cpu.pprof、mem.pprof和mutex.pprof之类性能分析数据，供go tool pprof工具使用。

比如下述命令将运行名为BenchmarkOne的这一跑分测试项，并分别将其运行过程的CPU、堆分配性能分析数据以及锁冲突分析数据保存在cpu.pprof、mem.pprof与mutex.pprof中。

go test -v -run ^$ -bench=BenchmarkOne -cpuprofile cpu.pprof go test -v -run ^$ -bench=BenchmarkOne -memprofile mem.pprof go test -v -run ^$ -bench=BenchmarkOne -mutexprofile mutex.pprof 

在一个大规模Go系统里，建议对所有性能攸关部分抽象出其benchmark跑分测试用例，一来这是continuous integration在nightly build的时候应该测试、追踪的，同时它提供本文所述的各类性能分析的无侵入式入口。

GC性能分析

Go的GC性能其实到最近也是一直被人无端攻击的，一大原因正是对很多用户来说存在量化分析GC性能的盲点。事实上，GC性能的分析已经很方便。

使用runtime包的ReadMemStats()方法可以获得系统MemStats数据，其中GCCPUFraction项是一个介于0-1.0之间的代表程序启动至今write barrier以外GC占用CPU时间的百分比数。Dragonboat该项始终在0.005（0.5%）左右。

GC的Stop-the-World停顿需要停止所有应用goroutine的运行，等于将整个应用暂时停止下来以供GC完成它的工作。这样的停顿会直接影响请求响应延迟的离散度，对99.9%与99.99% percentile延迟性能影响较大。通过MemStats数据的PauseNs项，可以获取每个GC周期的Stop-the-World停顿的上限。Dragonboat在Go 1.11和Go1.12的GC停顿图如下，250微秒的停顿上限已很不错：

最后，最粗暴但简单有效的一点就是可以在测试跑分的时候完全关闭GC，以此对比性能上的提升，这一部分的性能差异正是被GC所消耗掉的。如果性能变化不大，那么GC便显然不是性能的瓶颈。在Dragonboat中，关闭GC已经基本无法观察到明显的吞吐率上的提高。

总结

感谢阅读本干货软文，如果您还没有试用过开源的多组高性能Raft库Dragonboat，欢迎您试用并给予反馈。

本文介绍了各个Go内建性能分析工具的用法，试图以此勾划出一个较大规模Go系统多方面性能分析与优化的方法。综合而言：

1. Go提供了强大的内建性能分析工具，无须第三方工具即可完成各种常规性能分析。
2. 性能优化应以性能分析结果为基础，性能分析则必须以可靠工具提供的客观数据为导向。
3. 系统地考虑问题，如频繁的内存分配与回收损耗的是CPU资源，使用testing这个内建的测试包所构建的测试用例常常会是很好的系统性能分析的入口。

篇幅关系，Go内建的trace支持本文没有涉及，将在后续文章中单独列出探讨。