pprof和gctrace 是golang程序性能分析中经常用到的工具。
本节将根据我最近在工作中遇到的问题，就cpu/内存性能进行分析。
0.背景与解决
有个服务调用了底层的lua脚本库，最后导致机器疯狂扩容，翻了3倍左右，cpu负载很高，当流量上涨时cpu可以达到60%以上,平均都在35%以上。
但是内存非常低，10%左右。因此，重点考虑减少cpu开销。本文将从pprof分析、火焰图分析、trance分析等角度一一看看问题以及待优化的点。
优化后的cpu/time/memo都有所下降，cpu直接缩了一倍。
底层lua库不等于应该是~=，服务中直接使用了错误的脚本在线上跑，而对于lua脚本库来说是需要进行预编译成功才会进行缓存，如果失败了，会导致两个问题：
- lua栈不会回归池 -> 导致的问题是sync.Mutex占用cpu时间片
- lua栈不会缓存 -> 导致每次编译，运行时长增大,cpu占用时长 gc标记时增大
以上这两个问题都会导致cpu负载升高!
下面将进入本节硬核的学习与实战!
1.开启pprof
在go代码中开启pprof可以使用下面这种方式：
代码语言：javascript复制package main
import (
"log"
"net/http"
_ "net/http/pprof"
)
func main() {
http.ListenAndServe("0.0.0.0:8888", nil)
}
2.基本使用
pprof有两种交互：命令、web
- 命令：支持top查看占的比较多的cpu/heap等，list functionName 可以进入某个具体的函数 查看分配了多少内存/cpu等信息
cpu分析：
代码语言：javascript复制go tool pprof http://ip:port/debug/pprof/profile?seconds=60
heap分析
代码语言：javascript复制go tool pprof http://ip:port/debug/pprof/heap
trace分析：
代码语言：javascript复制go tool trace http://ip:port/debug/pprof/trace?seconds=10
上面这样会直接进入命令模式，并生成一个本地文件，后面还可以使用本地文件进入web页面。例如：
代码语言：javascript复制go tool pprof -http=:8081 pprof.userinfo_component.alloc_objects.alloc_space.inuse_objects.inuse_space.001.pb.gz
- web模式：会开启端口，web页面可以看到对应的火焰图与graphviz一样的图，比较直观
第一步是生成文件,以trace为例:
wget下载/curl下载
代码语言：javascript复制wget -O trace.out http://ip:port/debug/pprof/trace?seconds=10
curl http://ip:port/debug/pprof/trace?seconds=10 > trace.out
开启监听web端口
代码语言：javascript复制go tool pprof -http=:8081 trace.out
可以修改端口 与 trace.out(替换为文件即可),也可以用精简命令：
代码语言：javascript复制go tool pprof trace.out
4.实战性能分析
4.1 cpu
本次的性能问题体现在cpu上，这里就以cpu入手。
4.1.1 火焰图对比
代码语言：javascript复制./go tool pprof http://ip:port/debug/pprof/profile?seconds=30
- flat：当前函数占用CPU的耗时
- flat：:当前函数占用CPU的耗时百分比
- sun%：函数占用CPU的耗时累计百分比
- cum：当前函数加上调用当前函数的函数占用CPU的总耗时
- cum%：当前函数加上调用当前函数的函数占用CPU的总耗时百分比
- 最后一列：函数名称
可以看到一个很明显的一点是看不到用户函数，全是系统的runtime,特别是第一个scan占了21.62的cpu，当前函数加上调用当前函数的函数占用CPU的总耗时占了45%,这个数字跟前面cpu占用高不谋而合。
接下来看一下火焰图,火焰图在上面基础知识部分提到，可看上面。
火焰图中非常直观的表现了gc标记占用了40% 的cpu，这显然gc存在严重问题!!! 导致原因很有可能就是图中左小角的函数调用/函数本身有问题。
为了突出对比效果，上面两个图优化后如下：
可以看到火焰图部分明显变窄。
用户函数火焰图部分:
图1 优化之前
图2 优化之后
优化前lua占据整个窗口，最为突出的PreCompile部分一直在调用，优化之后可以看到PreComplie没了，左右两侧的其他非lua函数凸显出来了，这两部分就交给其他人优化吧，哈哈~
4.1.2 gctrace分析
Golang，自带gc，在不改动代码的情况下，我们可以设置GODEBUG='gctrace=1'环境变量启动程序，来向标准错误输出打印，查看gc 是否有异常，在启动进程之前设置环境变量
代码语言：javascript复制export GODEBUG=gctrace=1
接下来就是天文了，tail -f xxx.log看gc日志。
这个图涉及到了三色标记法知识了，这里先填坑，了解一下基本的知识即可。
gc 122: 表示第122次GC
@461.181.s: @后面的数字表示程序启动经历的时间
0%: 自程序启动以来花费在 GC 上的时间百分比
0.11 71 0.006 ms: 垃圾回收的时间，分别为STW（stop-the-world）清扫的时间, 并发标记和扫描的时间，STW标记的时间
0.93 43/142/355 0.055 ms cpu, 表示垃圾回收占用cpu时间
355>363->185 MB: 表示堆的大小，gc后堆的大小，存活堆的大小
364 MB goal 整体堆的大小
8 P 使用的处理器数量
可以看到的是，垃圾回收的时间占cpu太长了，标记与扫描时间也很长，证明gc一定有问题!
这里给出优化后的对比图：
可以看到clock与cpu时间均降下来了。
4.1.3 trace分析
上面分析出来gc是有严重问题的，4.1.1节虽然也看到了函数问题，那想再确实是不是lua引起的gc问题呢，此时可以使用trace看看gc过程。
代码语言：javascript复制wget -O trace.out http://ip:port/debug/pprof/trace?seconds=10
go tool trace trace.out
这个图比较复杂，具体看的流程根据自己想分析的内容着手，例如：想看网络耗时，可以看Network blocking profile，这里我比较着重看cpu相关，顺序为：Scheduler latency profile-> Goroutine analysis->View trace
- Scheduler latency profile
图1 优化之前
图2 优化之后
可以非常清楚的看到调度延迟是发生在lua这一块，而优化之后完全没了。
- Goroutine analysis
图1 优化之前
图2 优化之后
可以看到优化之后的gc数量是减少了。
- View trace
图1 优化之前
图2 优化之后
可以看到处理器上的g在优化之前的时间片非常长，点了之后可以看到下面的函数trace,上图也可以看到是lua这一块，优化之后 可以看到时间片非常小了。
4.2 内存
cpu通常与内存是有关系的,这里也在cpu分析完之后，看了一下内存。
代码语言：javascript复制./go tool pprof http://ip:port/debug/pprof/heap
可以看到的是内存开销全在反射了，
内存角度变化不大，主要是拉数据时反射比较多，也看出来反射这一块内存开销还是非常大的，这里的话定位到了代码中：
代码语言：javascript复制func parseConf() {
var s []string
json.Unmarshal(xxx, &x)
}
场景是每次请求都会去拉缓存中的配置，缓存的配置拉到之后丢到这个parseConf函数中，这里疯狂反射unmarshal，内存开销严重。
这里可以优化的点在于可以使用localcache/bigcache减少内存与反射的开销。
本节完
