从0到1上手硬核性能分析(多图文)

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可以使用下面这种方式：

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分析：

go tool pprof http://ip:port/debug/pprof/profile\?seconds\=60

heap分析

go tool pprof http://ip:port/debug/pprof/heap

trace分析：

go tool trace http://ip:port/debug/pprof/trace?seconds=10

上面这样会直接进入命令模式，并生成一个本地文件，后面还可以使用本地文件进入web页面。例如：

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下载

wget -O trace.out http://ip:port/debug/pprof/trace?seconds=10

curl http://ip:port/debug/pprof/trace?seconds=10 > trace.out

开启监听web端口

go tool pprof -http=:8081 trace.out

可以修改端口 与 trace.out(替换为文件即可),也可以用精简命令：

go tool pprof trace.out

4.实战性能分析

4.1 cpu

本次的性能问题体现在cpu上，这里就以cpu入手。

4.1.1 火焰图对比

./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 是否有异常，在启动进程之前设置环境变量

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过程。

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分析完之后，看了一下内存。

./go tool pprof http://ip:port/debug/pprof/heap

可以看到的是内存开销全在反射了，

内存角度变化不大，主要是拉数据时反射比较多，也看出来反射这一块内存开销还是非常大的，这里的话定位到了代码中：

func parseConf() {
  var s []string
  json.Unmarshal(xxx, &x)
}

场景是每次请求都会去拉缓存中的配置，缓存的配置拉到之后丢到这个parseConf函数中，这里疯狂反射unmarshal，内存开销严重。

这里可以优化的点在于可以使用localcache/bigcache减少内存与反射的开销。

本节完