go pprof实战
1 为什么要进行性能优化
1.1 哪些情况需要进行性能优化
其实关于性能优化的主题，网上已经讨论很多次，这里谈一下我的理解，那么其实核心就是2个点：
- 服务一直高负载，业务增长需要经常扩容
- 架构不能满足业务发展，需要重构，与此同时需要进行服务的压测&性能优化
1.2 性能优化的一般步骤
- 准备阶段：发现系统性能问题，明确优化方向
- 分析阶段：通过各种工具和手段，初步定位瓶颈点
- 调优阶段：根据定位到的瓶颈点，进行性能调优
- 测试阶段：实际验证调优效果，如果不能满足期望要求，那么可能需要重复2-3步骤（如果还不行可能是架构设计存在问题）
1.3 linux常见的性能问题排查工具
linux程序常用的调试工具：
vmstat、iostat、 mpstat、netstat、 sar 、top：查看系统、程序信息等
gprof、perf、perf top：定位到具体函数、调用等
strace、ltrace：系统调用、函数调用、库函数调用等
pstack、ptree、pmap：堆栈信息
dmesg：系统log信息
对于go程序，如果遇到高负载等性能问题推荐使用：perf top、pprof快速定位问题。
1.4 perf top
当前系统的uptime：load average 2.50左右，以下perf top信息中出现_raw_spin_unlock_irqrestore表示系统可能比较“闲’‘，以及有较多的软中断（服务交互）。unknown则是没有加载符号文件，所以没有显示函数名，vdso很可能time相关系统调用。
runtime.scanobject、mallocgc说明可能有较多小对象申请等等。
1.5 go程序性能问题梳理
- 内存泄露
- 内存大量申请释放
- 协程泄露
- 协程数量异常
- 对象数量异常
- 反射使用（gc、内存问题）
- 定时器使用导致的内存泄露
- 以及业务逻辑上的问题
- …
2 pprof分析程序性能问题
2.1 pprof如何收集程序信息
on cpu类型的pprof收集原理：注册settimer系统调用回调，1秒触发100次回调，然后遍历每个线程的堆栈信息并保存生成prof文件。（off cpu则是IO较大的程序）
程序中如下使用，注册pprof监听的端口即可。
import _ "net/http/pprof"
gofunc() {
http.ListenAndServe("0.0.0.0:8080", nil)
}()pprof.go文件的init在DefaultServeMux默认路由上注册了多个handle，分别用来收集cpu、内存等信息
pprof.go
func init() {
http.HandleFunc("/debug/pprof/", Index)
http.HandleFunc("/debug/pprof/cmdline", Cmdline)
http.HandleFunc("/debug/pprof/profile", Profile)
http.HandleFunc("/debug/pprof/symbol", Symbol)
http.HandleFunc("/debug/pprof/trace", Trace)
}对应的handle，定期以固定hz频率收集程序信息到profileBuilder对象中。最终在收集完成返回收集的数据信息，最终web页面展示出来。
type profileBuilder struct {
start time.Time
end time.Time
havePeriod bool
period int64
m profMap
// encoding state
w io.Writer
zw *gzip.Writer
pb protobuf
strings []string
stringMap map[string]int
locs map[uintptr]locInfo
funcs map[string]int
mem []memMap
deck pcDeck
}
// and
runtime.MemProfileRecord // goroutine堆栈信息
runtime.MemStats // 内存数据统计信息2.2 pprof查看程序信息
我们可以使用下面多种方式查看程序的内存、cpu、锁等信息。
// Then use the pprof tool to look at the heap profile:
//
// go tool pprof http://localhost:6060/debug/pprof/heap
//
// Or to look at a 30-second CPU profile:
//
// go tool pprof http://localhost:6060/debug/pprof/profile?seconds=30
//
// Or to look at the goroutine blocking profile, after calling
// runtime.SetBlockProfileRate in your program:
//
// go tool pprof http://localhost:6060/debug/pprof/block
//
// Or to look at the holders of contended mutexes, after calling
// runtime.SetMutexProfileFraction in your program:
//
// go tool pprof http://localhost:6060/debug/pprof/mutex
//
// The package also exports a handler that serves execution trace data
// for the "go tool trace" command. To collect a 5-second execution trace:
//
// wget -O trace.out http://localhost:6060/debug/pprof/trace?seconds=5
// go tool trace trace.out
//
// To view all available profiles, open http://localhost:6060/debug/pprof/
// in your browser.
//
// For a study of the facility in action, visit
//
// https://blog.golang.org/2011/06/profiling-go-programs.html简单的示例，查看goroutine的堆栈、程序的内存信息、gc次数等。
go tool pprof http://localhost:6060/debug/pprof/heap?debug=1
// runtime.MemProfileRecord
heap profile: 71: 35532256 [15150: 492894072] @ heap/1048576
1: 31203328 [1: 31203328] @ 0xc2c83a 0x49ed0a 0x49ecd7 0x49ecd7 0x49ecd7 0x491985 0x4c79c1
# 0xc2c839 git.code.oa.com/tmemesh.io/sidecar.init+0x39 git.code.oa.com/tmemesh.io/sidecar@v0.0.27/report.go:14
# 0x49ed09 runtime.doInit+0x89 /usr/local/go/src/runtime/proc.go:5646
# 0x49ecd6 runtime.doInit+0x56 /usr/local/go/src/runtime/proc.go:5641
# 0x49ecd6 runtime.doInit+0x56 /usr/local/go/src/runtime/proc.go:5641
# 0x49ecd6 runtime.doInit+0x56 /usr/local/go/src/runtime/proc.go:5641
# 0x491984 runtime.main+0x1c4 /usr/local/go/src/runtime/proc.go:191
// runtime.MemStats
# runtime.MemStats
# Alloc = 83374072
# TotalAlloc = 8261199880
# Sys = 216980496
# Lookups = 0
# Mallocs = 102656515
# Frees = 102139727
# HeapAlloc = 83374072
# HeapSys = 199491584
# HeapIdle = 94797824
# HeapInuse = 104693760
...
# NextGC = 163876768
# LastGC = 1618924964269456488
# NumGC = 333
# NumForcedGC = 0
# GCCPUFraction = 0.00011171208329868897
# DebugGC = false
# MaxRSS = 1306337283 投放服务【测试环境压测】
投放服务的主要工作就是给用户投放合适的内容（主播、会员广告）
这里压测srf服务可以使用bm_tools工具，可以很方便的压测qps以及查看服务平均延迟等（下面有示例）
3.1 服务无太多业务逻辑（无真实内容、主播投放）
相当于服务空转的情况下的负载测试，200qps/s，并且无日志打印。当前服务cpu不算很高，查看pprof系统性能消耗。
- 没有明显业务代码占用的cpu
- 但是较多mcall→park_m，说明可能当前环境g很多，park_m则是g切换g0并进行新一次gmp吊打循环
- 6%消耗在gc还算正常
3.2 真实业务数据投放
服务现在会正常投放内容和主播，100qps/s的情况下出现较多超时等异常。这里压测工具可以使用司内的服务压测工具eab，当然也可以使用外部其他的开源压测工具。 这里平均时延达到1.2s，p90超过500ms以上
3.2.1 pprof查看明显瓶颈
因为服务在qps100情况下（测试环境）出现了较多的超时等异常问题，所以我们可以优先使用pprof分析一些程序明显的问题。
如下有大块的cpu统计是消耗异步操作中的，这里很明显是有问题的，非关键路径占用了很多的cpu。
点开查看即可看到相关的业务函数大多都是redis相关操作，这里的逻辑是：每次受到请求后，都会开启约10个goroutine去set记录一些频控信息。
可能的优化点：
- 每次请求后都会创建约10个左右goroutine并发单独set数据，这里可以考虑协程池处理。
- 考虑使用mset合并不同业务数据，减少请求次数。
当然我们是遇到问题查看代码之后才会发现，每次请求都会创建很多goroutine，那么在性能问题排查过程中我们有哪些办法可以判断goroutine数量异常，以及导致的问题。这时候就可以使用trace工具查看。
3.2.2 trace跟踪gc和g调度
pprof简单定位后（包括内存、cpu），其实已经没有特别明显的问题可以发现到，所以可以考虑trace程序查看更细节的问题。
这里我们使用trace生成go trace文件信息查看，相关调度问题。
3.2.3 怎么生成trace文件
curl localhost:/debug/pprof/trace?seconds=10 > trace.out3.2.4 怎么查看trace文件信息
得到trace.out文件后，可以下载到自己电脑，使用如下命令即可使用web打开trace文件信息。
go tool trace trace.out粗略查看gc约5秒触发一次持续1s左右，当前业务确实会有较多的内存申请释放，所以这里可能也会有内存相关的问题，导致gc频繁、持续时间较长。
3.2.5 查看g调度时延
查看network poll接收时间到goroutine处理的时延。目前查看平均250-300ms收到事件才会正常处理，在当前测试环境已经属于服务饱和状态。并且结合业务出现超时等现象，这里可以断定：
- 在服务不扩容的情况下，测试环境qps：100已经达到极限。
- 另外gc属于较为频繁的情况，考虑程序内存方面需要优化。
- 另外待调度的goroutine数量可能太多了，导致调度的延迟很大。
查看此时的Goroutine analysis，来查看当前Goroutine的一些运行信息。可以看到很多goroutine的大部分的时间都会花费在：Sync Block Time（同步阻塞时间），这里我的理解应该是状态通过gopark已经转换为Grunnable，但是实际上没有时间片执行导致的耗时。
3.2.6 查看g数量信息
结合查看pprof以及trace，我们分析除了业务问题、内存问题还可能是goroutine数量有些问题，这里直接查看pprof的“概览“即可看到goroutine、heap等信息。
到此可以定位到，goroutine数量确实是服务性能问题的元凶之一。
可能的优化点：
- 每次请求后都会创建约10个左右goroutine并发单独set数据，这里可以考虑协程池处理。
- 考虑使用mset合并不同业务数据，减少请求次数。
3.2.7 查看内存问题
考虑到trace查看gc较为频繁，所以当前系统应该也有些内存上的问题，这里直接使用pprof给出的是具体函数，我们想要定位到具体某一行该如何操作呢？
go tool pprof http://localhost:30065/debug/pprof/allocs
在上面的操作界面，我们可以使用top列出当前系统内存占用信息。使用list命令列出占用较高函数的详细信息。（这里因为是测试环境，代码在我们开发机，所以提示找不到.go文件）
这里我们需要将go tool工具生成的.pb.gz文件拷贝到开发机，再次使用go tool工具运行既可查看到具体的函数占用信息。
go tool pprof pprof.PhoenixAdSvr.alloc_objects.alloc_space.inuse_objects.inuse_space.027.pb.gz我们可以list查看一下几个明显占用高的函数信息：
如下则是每次服务收到请求，都会创建一个待上报的结构体，这里的make初始化len明显不合理。
另外一个较小的内存申请如下，这里是一个通用的解析上报（使用反射通用处理），暂且认为在当前业务下，不优先处理。
3.2.8 查看内存泄漏问题
内存排查完成后，下一步就是观察这么大量的内存申请释放是否可能存在内存泄露问题。
针对内存泄漏场景，我们可以采集2个时间点的内存数据，对比这段时间哪些内存一直增长。
我们得到2份pb.gz的内存数据可以使用如下命令对比（在开发机器）：
go tool pprof -base
pprof.PhoenixAdSvr.alloc_objects.alloc_space.inuse_objects.inuse_space.027.pb.gz
pprof.Phoen_objects.alloc_space.inuse_objects.inuse_space.028.pb.gz
可以发现确实内存一直增长，但是对于此场景是在有请求时发现内存不断上涨，但是请求下降后内存会逐步恢复，说明当前系统虽然没有内存泄露，但是确实存在内存瓶颈，在当前qps下，业务处理后的内存释放跟不上内存申请的速度，最终会导致OOM。
如下RES在已经升到了1G，但是在请求下降后逐步恢复。
总结
根据以上的测试结果，目前系统需要做以下几个优化点：
- 下发频控设置上，启动了较多goroutine，并且单独set数据，这里需要考虑如何将不同操作合并下发。
- 另外在处理下发上报时，为了防止由于系统负载问题导致，goroutine暴增，从而雪崩的问题，考虑下发上报使用pool组件处理。
- 内存申请异常问题需要减少、更新其他的监控上报方式。
3.3 修复以上问题继续压测
主要使用池化减少goroutine数量，另外不合理的内存申请大小也需要修改。
3.3.1 池化
根据业务特点设置不同的pool以及routiune大小。这里使用的组件：
5k star持续维护值得使用
https://github.com/panjf2000/ants池化的原理大概如下（图来自README.md）：
3.3.2 解决过大的内存申请
上报slice大小设置合理即可（当前业务更换了上报方式，这段代码可以删除）
3.3.3 IO业务读写合并
因为每次set的key和value结构不太一样，所以经过池化、内存问题解决，这里暂时先不需要合并set写入。
3.4 优化后压测
3.4.1 压测结论
在上面3个点（其实是2个点）修改后，服务性能有了明显提升，之前测试环境在相同环境100qps/s的情况下，会出现较多的超时问题，p90达到1s左右，并且有较大的内存问题。
升级之后，qps在测试环境能稳定在200qps情况下无超时，并且p90稳定30-40ms以内。另外提升到qps300仅出现少量超时。
3.4.2 pprof查看火焰图
可以看到异步任务由之前的占用70%cpu，下降到30%，有较大的优化效果。
内存效果更加明显，稳定运行一段时间，内存无明显增长。内存问题得到解决。
3.4.3 trace查看调度
首先协程数量大大减少。
由于内存申请释放较少，在qps是原来3倍的情况下，此时的gc触发时间延长到8s，对于当前业务，算是比较合理的执行gc间隔。
最后查看Goroutine analysis分析，Goroutine基本没有太多的同步阻塞等非正常状态。
3.5 总结
经过上面bm、pprof、trace的结果，我们可以判断，此时系统优化已经达到比较好的效果（性能提升3倍+）继续深入优化的成本较高，并且收益较小。
总结一下解决性能问题的方法：
pprof简单定位后（包括内存、cpu），其实已经没有特别明显的问题可以发现到，所以可以考虑trace程序查看更细节的问题。
这里我们使用trace生成go trace文件信息查看，相关调度问题。
4 投放服务【现网压测】
经过以上的问题修改，以及测试环境压测，已经可以说是基本可用了，所以为了保证上线没问题，我们必须要进行现网压测，只有最真实的数据才更有说服力。（然后发现了很多问题）
4.1 好的开始
会员业务属于较为简单的业务在1000qps下，p97为50ms，并且cpu、机器负载都很低。完全可用。
4.2 再次异常
但是直播场景压测，尝试500qps/s去压测服务，但是服务顺便被“打爆”，出现大量超时，并且内存急剧增长，短短几分钟RES达到：5G+。
所以马上保存trace、打开pprof分析性能问题。
简单看了下当前的top信息，cpu大约200+，内存RES占用的了5G。
4.2.1 CPU元凶
打开pprof，很明显大量cpu消耗在sidecar路由上，因为设置频控数据是有放大的，所以可能仅频控数据设置，单机都可能达到约3000qps/s请求redis，此时sidecar寻址消耗是比较明显的，根据我们业务特点，此时还是使用配置文件，使用l5寻址方式去访问redis。
4.2.2 内存元凶
上面top分析RES占用巨大，所以肯定还有内存问题，这里我还是使用pprof查看具体那一行代码有问题。
所以查看代码，我们发现还是由于初始化slice不合理导致，这里是根据最大开播主播设置的1个较大的值，所以还是业务代码不合理导致这个问题。
4.2.3 胜利的曙光？
通过修复上面的问题，然后编译→发布后再次观察。
此时内存没有明显的增长，并且开始运行也没太多的延迟。
好像就这样结束了？
4.2.4 一波三折
然而，上个了厕所回来之后，发现延迟开始增加，有点雪崩的意思。。。此时平均时延达到了1.5s！这时候的现象就是运行了一段时候之后，程序逐渐雪崩。
再次打开pprof、trace继续跟踪。。。
此时由于上面优化，使用配置文件的寻址，修改不合理的slice设置，我们从pprof并没有发现明显的性能问题。
但是注意到此时gc占用接近整体的25%，那么此时我们就需要考虑，代码是否涉及到大量小内存申请（池化）、以及反射（比如fmt、json）。
从内存问题角度出发，trace代码后我们发现，一些问题比如json、以及上报部分的反射使用。
所以这里比较快的解决方案是：
- 更换更高效的json库
- 上报简单写，不使用反射
更换了下面这个json库：github.com/json-iterator/go
以及做了代码调整，取消使用反射（最简单的才是最快的）
4.2.5 如释重负
经过上面的修改后，马上编译→发布服务，在500qps情况下压测！
这次的结果就很ok，运行很长一段时间，基本p90在100-200ms之间，可以满足基本业务需求。
此时服务的cpu较高，但是可以满足使用需求。
我们此时再次pprof查看内存情况，结果还是很ok的，内存问题暂时解决。
4.2.6 机器负载
此次压测的投放服务和内容服务是混布的（2个即将发布的服务），互相难免有些影响，上线后独立部署预计投放服务的qps会高很多。
查看一下机器的负载记录，当前机器仅有少量其他业务，基本在我们测试过程中，机器已经达到极限。
4.2.7 实际上线
业务低峰期cpu：130
发布后cpu：40
4.3 总结
go pprof确实强大，可以很方便的定为问题。另外在优化过程中主要还是考虑 cpu和内存问题，io、锁等问题可能较少。
通常可能遇到的问题：
- 初始化不合理
- 并发较多，没有做合并
- routine过多，没有管理
- 反射对内存、cpu的影响
- 另外考虑池化解决小内存申请过多
- g调度延迟问题
- 等等
最重要的是关键服务一定要压测，一定要在真实环境压测！！！
5 内容服务【外网压测】
这个服务主要是给投放服务提供内容（主播、广告），也就是投放服务调用内容服务。此服务会执行一些频控、流量控制等操作。
在业务低峰期此时cpu比投放服务高的多（2倍），肯定存在一些瓶颈需要优化。
这里内容服务遇到的问题和投放服务稍有不同，例如：gc频繁，这里记录一下gc频繁等问题的排查思路，和上面文章做一些互补。
这里先简单看一下pprof的cpu、内存、routine等方面的问题。
5.1 查看CPU问题
程序在运行大约30分钟后，我们pprof查看CPU发现有很明显问题的：
- 有些明显的“业务”类型函数调用次数很多（例如判断2个slice中重复的元素）。
- 另外gc项也有些占用（gcbackxxx），理论上业务服务qps较高时，gc占用不会特别明显才对。
5.2 查看内存问题
程序在运行大约30分钟后，我们pprof查看内存发现有些和CPU维度不一样的问题：
- 某些case在短时存在大量的内存申请、释放问题。
5.3 查看gc问题
这里trace之后，可以比较明显的发现gc的次数太多，1s基本会有2次左右的gc。
5.4 初步结论
通过以上分析，这里可以发现几个明显的问题需要取解决：
- “业务”函数（例如判断2个slice中重复的元素）调用过度，这里需要查看有没有不合理的地方。
- 内存申请过度，这里需要有没有不合理，或者需要考虑池化。
- gc过于频繁一般也是和内存关系比较大，所以需要优先排查内存问题。
除了业务函数方面，在内存上我们可以看一下具体代码，内存分配的情况：
这里主要是一些临时变量的申请和释放，这里有两方面的问题：
- map[string]int，这里string类型是否考虑可以使用无内存、gc扫描的基本类型，例如int64。
- map[int]int，这种结构是否可以使用slice代替，这也是官方pprof示例中给出的优化方向。
5.5 解决问题
5.5.1 业务函数问题
这里是匹配2个slice数据，检查1个slice的值是否存在于另一个slice，时间复杂度为O(nm)
这里一般2个优化：
- 可以先排序其中1个slice，然后根据另一个slice迭代二分查找，复杂度降为：O(n)+O(m)*O(logn)。
- 另外从业务手段上是否可以不比较，修改部分逻辑减少无效的计算。（最终优化逻辑，不比较也可以满足要求）
5.5.2 字符串key构造问题
这里本地存储gcache是每个主播的一些频控数据信息，key构造的很复杂是一个比较大的字符串，这里可以如下优化一下：
这里优化直接使用主播id即可。
- 本地内存查询，只需要简单的主播id查询数据即可，节省了很多字符串拼接所需的内存。
- 另外减少fmt类型的key构造，在qps高以及内部访问放大的情况下，这里的优化还是有必要的，例如使用stringbuilder等。
5.5.3 临时变量申请问题
这里也是业务逻辑需要注意的，if条件中可能只有一小部分用户访问会进入，这里稍大的临时变量没有必要每次都需要申请，另外申请的cap大小也应该是可预估的。
修改前：
修改后：
另外为了解决map[string]int64，中指针类型对于gc的影响，这里修改类型为普通类型，无指针引用的map[int64]int64类型。可以参考bigcache中的优化。
5.5.4 大块内存申请问题
这里可能需要使用pool解决。
但是实际情况是，如果使用了map作为池，pool的老map数据还需要清理，这里简单做了benchmark，这里的测试方法是，pool每次申请2000大小的map[int]int，然后做一些简单操作后重新put进入pool中。
这里的结果是不使用pool的map效率更高！
经过上面的benchmark分析，以及使用map对象pool比较繁琐，故这里暂不修改。
5.5.5 优化对比
优化前：
优化后：
性能大约提升了60%+
5.5.6 优化结论
结论梳理：
- 根据以上优化结果，我们提升了60%的性能
- 实际的gc间隔也延长了，大约减少25%的gc次数
查看trace图其中gc间隔延迟，查看火焰图在cpu方面已经没有明显的业务瓶颈，但是内存瓶颈依然存在，因为存在较多的内存申请释放，但是目前没有很好的优化手段。
5.5.7 优化结论
这里总结一下上面的优化手段：
- 对于map，如果存在大量的临时变量使用，那么我们优先考虑是否可以避免这些map对gc的影响，比如把key和value设置为非指针的普通类型，比如：int（bigcache优化手段之一）。
- 在cpu密集计算的过程中，有效减少计算时间复杂度是很好的手动，比如：复杂度O(nm）降为O(n)+O(m)*O(logn)。
- 在string类型拼接的过程中，如果存在大量调用，我们可以考虑更高效的字符串拼接方法，比如：stringbuilde代替fmt。
- 极端的如果string可以作为key，那么我们业务是否可以考虑使用int等基本类型作为key，这里我们在使用内存缓存查询某些数据，尽可能的设计简单。
- 另外减少无效的内存申请，无效的循环等也是一个业务优化手段。
- 等等…
6 go优化建议
6.1 将多个小对象合并成一个大的对象
6.2 减少不必要的指针间接引用，多使用copy引用
例如使用bytes.Buffer代替*bytes.Buffer，因为使用指针时，会分配2个对象来完成引用。
6.3 局部变量逃逸时，将其聚合起来
这一点理论跟1相同，核心在于减少object的分配，减少gc的压力。例如，以下代码
for k, v := range m {
k, v := k, v // copy for capturing by the goroutine
go func() {
// use k and v
}()
}可以修改为:
for k, v := range m {
x := struct{ k, v string }{k, v} // copy for capturing by the goroutine
go func() {
// use x.k and x.v
}()
}修改后，逃逸的对象变为了x，将k，v2个对象减少为1个对象。
6.4 []byte的预分配
当我们比较清楚的知道[]byte会到底使用多少字节，我们就可以采用一个数组来预分配这段内存。例如:
type X struct {
buf []byte
bufArray [16]byte // Buf usually does not grow beyond 16 bytes.
}
func MakeX() *X {
x := &X{}
// Preinitialize buf with the backing array.
x.buf = x.bufArray[:0]
return x
}6.5 尽可能使用字节数少的类型
当我们的一些const或者计数字段不需要太大的字节数时，我们通常可以将其声明为int8类型。
6.6 减少不必要的指针引用
当一个对象不包含任何指针（注意：strings，slices，maps 和chans包含隐含的指针），时，对gc的扫描影响很小。比如，1GB byte 的slice事实上只包含有限的几个object，不会影响垃圾收集时间。因此，我们可以尽可能的减少指针的引用。
6.7 使用sync.Pool来缓存常用的对象
6.8 使用slice代替map
https://software.intel.com/content/www/us/en/develop/blogs/debugging-performance-issues-in-go-programs.html
https://blog.golang.org/pprof
QQ音乐招聘Android/ios客户端开发，点击左下方“查看原文”投递简历～
也可将简历发送至邮箱：tmezp@tencent.com
腾讯云开发者
