Golang性能提升：程序员必学技巧

性能分析和优化是所有软件开发人员必备的技能，也是后台大佬们口中津津乐道的话题。

Golang 作为一门“现代化”的语言，原生就包含了强大的性能分析工具 pprof 和 trace。pprof 工具常用于分析资源的使用情况，可以采集程序运行时的多种不同类型的数据（例如 CPU 占用、内存消耗和协程数量等），并对数据进行分析聚合生成的报告。trace 工具则关注程序运行时的事件（例如协程状态切换，GC 的开始和结束、系统调用等等），常用于分析延迟、阻塞和调度等问题。掌握了这两个工具就足以满足大部分 Golang 程序的性能分析需求。

本文将从使用方法、原理和实践三个方面分别介绍 pprof 和 trace 工具。读完本文后，相信你也可以更全面地掌握 pprof 和 trace。废话少说，让我们开始！

01

pprof 工具详解

pprof 是一个用于可视化和分析数据的工具。可以在 Go 程序运行时对多种不同类型的数据进行采样，常用来分析的数据类型有：

• profile：CPU 时间；
• allocs/heap：内存分配；
• goroutine：协程使用情况；

获取采样数据后，pprof 提供了多种不同的分析模式用于数据分析，常用的分析模式有：

• svg 矢量图或火焰图；
• top 按占比由大到小排序分析；
• source 源代码分析；
• peek 调用上下游分析；

接下来按采样数据类型逐一分析。

1.1 profile CPU 分析

1.1.1 生成采样数据

1.1.1.1 代码直接生成

在 main 函数开头直接加入如下代码，程序结束后将得到完整的采样数据文件 CPU.out；该方式常用在工具代码分析场景。

func main() {    f, _ := os.Create("CPU.out")    defer f.Close()    pprof.StartCPUProfile(f)    defer   pprof.StopCPUProfile()    ...}

1.1.1.2 go test 参数生成

执行 go test 时，加上参数 -CPUprofile CPU.out 生成采样数据。

go test -CPUprofile CPU.out . -run=TestFunc

1.1.1.3 通过 http 请求生成

• 启动 http 服务：

在程序主路径上引入 net/http/pprof 包，启动 http 服务。

import (  "net/http"  _ "net/http/pprof")func pprofServerStart() {  go func() {    http.ListenAndServe("127.0.0.1:6060", nil) // 安全起见，使用本地地址进行监听  }()}

引入 pprof 包后，会在默认处理器 DefaultServeMux 上注册 /debug/pprof/profile 接口的路由；调用 ListenAndServe 启动 http 服务，第二个参数传nil使用默认处理器处理请求。考虑安全原因，http 服务的地址和端口建议使用本地地址。

• 请求 http 接口生成采样数据：

使用 go tool pprof 命令访问本地服务的 /debug/pprof/profile 接口，CPU 采样数据会自动保存到 $HOME/pprof/ 目录下，同时也会直接进入分析命令行。

$ go tool pprof http://127.0.0.1:6060/debug/pprof/profile?seconds=30Saved profile in /root/pprof/pprof.demo.samples.CPU.001.pb.gzFile: demoType: CPUTime: Dec 24, 2023 at 11:42am (CST)Duration: 10s, Total samples = 70ms (  0.7%)Entering interactive mode (type "help" for commands, "o" for options)(pprof) 

1.1.2 分析数据

1.1.2.1 打开采样数据

需要将采样数据下载到有源代码的机器上进行分析，在没有源代码的机器上 source 和 peek 模式无效。

有两种方法打开采样数据，命令行和可视化界面。笔者个人更喜欢可视化界面的方式，鼠标点一点就能分析非常方便，本文后续章节都以可视化界面分析为例子进行说明。

• 命令行分析：

直接用 go tool pprof 打开采样文件，输入 top、list（等同于上文说的的source）、peek 等命令进行分析。

$ go tool pprof CPU.out File: bench.testType: CPUTime: Dec 24, 2023 at 10:43am (CST)Duration: 1.96s, Total samples = 1.83s (93.33%)Entering interactive mode (type "help" for commands, "o" for options)(pprof) 

• 可视化界面分析：

使用 go tool pprof -http=ip:port 启动服务。

$ go tool pprof -http=127.0.0.1:9888 CPU.outServing web UI on http://127.0.0.1:9888

浏览器访问 http://127.0.0.1:9888 即可打开可视化界面，其中在 VIEW 菜单包含了常用的分析模式，如下图所示。

1.1.2.2 分析模式一 svg 矢量图

点击 VIEW 菜单下的 Graph 子项，可以生成 svg 矢量图如下图。svg 矢量图很适合从整体上对资源使用情况进行把握，并且还可以辅助分析程序的调用链情况。

图中每一个小的矩形框节点，代表一个函数（或方法），节点的入箭头和出箭头代表调用上游和下游。函数本身+函数下游汇总的 CPU 时间占比越高，矩形框的颜色越深，进入该节点的箭头也越粗。

节点说明如上图，内部包含两部分，上半部分是包名、类名、函数名和匿名函数名等基础信息；下半部分是最多两个统计数据，第一个是函数本身的汇总 CPU 时间，第二个是函数总体（本身+下游调用）的汇总 CPU 时间，统计信息如果没有或很小会省略。

svg 矢量图最上方的搜索框可以使用正则语法过滤特定的节点，搜索后只有调用链中有满足搜索条件的节点才会展示出来。

1.1.2.3 分析模式二 top

点击 VIEW 菜单的 top 子项，可以列出按本身 CPU 时间（即不包含下游）占比从大到小排列的所有函数。

指标说明：

• flat、flat%：函数本身的汇总 CPU 时间或占比。
• sum%：上方所有行的 flat% 累加值。
• cum、cum%：函数总体（本身+下游调用）的汇总 CPU 时间或占比。

同样的，top 模式中也可以在上方搜索框使用正则语法过滤特定的节点。top 的使用场景和 svg 矢量图类似，都是整体上对资源使用情况进行分析。

1.1.2.4 分析模式三 source

点击 VIEW 菜单的 source 子项，进入源码分析模式。svg 或 top 模式的分析颗粒度是函数，而 source 模式的颗粒度是源代码的每一行；除了可以给出函数总体的 flat 和 cum 之外，还给出了每一行代码的 flat 和 cum，这使得我们可以对函数内部逐行深入分析。source 一般都是配合搜索框使用，下图展示了在 source 模式下搜索关键词 chansend1，对 channel 入队的源码分析的结果。

1.1.2.5 分析模式四 peek

点击 VIEW 菜单的 peek 子项，可以在代码行的颗粒度对函数调用上下游进行分析。

Peek 在强大之处在于，它可以量化的分析上下游调用的占比情况。如图中所示，chansend1 节点自身的统计信息是中间的红框；上面的红框列出了所有调用了 chansend1 的代码行及其统计占比，下面的红框则是 chansend1 调用下游的代码行及其统计占比。当在 svg 矢量图或 top 分析中看到一个很重的系统调用节点时，虽然我们无法对系统调用本身进行优化，但是使用 peek 排查调用上游情况，或许我们就会发现一个不合理的系统调用用法。

1.1.3 profile 采样原理分析

1.1.3.1 太长不看版

• 采样性能逼近真实性能：

Go 程序运行中，随机选择一个处于正在执行状态的协程，记录该协程当前的调用栈，这是一次 profile 采样。

我们可以容易的得出这样一个推论，如果某个函数占用了较多的 CPU 时间，那么一次采样中记录到的正在执行的函数就是该函数的概率也相对较大。这个推论反过来也成立，即如果在多次采样中，某个函数出现次数占比较高，那么该函数大概率也占用了较多的 CPU 时间。

因此可以用采样的结果来逼近真实的结果，采样频次越高逼近效果越好。

• profile 怎么做的：

在用户指定的采样周期内，profile 的会按照一定的频率进行采样，随机得到一个协程的调用栈信息；采样频率固定为100，采样间隔为1s/100=10ms；

在分析时，按采样数据的调用栈进行聚合（调用栈计算 hash，hash 值相等就是相同的调用栈），某个调用栈的汇总 CPU 时间就等于该调用栈的采样次数*采样间隔。

调用栈及统计信息有了，按照函数或代码行维度进行进一步聚合，再辅助调用栈的上下游关系，就可以生成 svg 图、peek 和 source 等数据了。

• 性能影响：

分析采样原理的最初的目的，是为了弄清楚 pprof 本身对性能的影响情况，不了解 pprof 采样原理的话，是不敢贸然用在生产环境上的。

这里给直接结论，开启 pprof 采样后，对性能有影响但是非常小，生产环境可以放心使用。

1.1.3.2 源码分析

• 开启采样：

当在代码中引入的 pprof 包后，包内的 init 函数会将 /debug/pprof/profile 路由注册到默认处理器中，处理入口是 Profile 函数。

// net/http/pprof/pprof.gofunc init() {  ...  http.HandleFunc("/debug/pprof/profile", Profile) // 路由注册到Profile进行处理  ...}

在 Profile 函数中，会调用 pprof.StartCPUProfile 来开启采样，按传参 seconds（默认30s）进行 sleep 之后，再调用 pprof.StopCPUProfile 停止采样。

// runtime/mprof.gofunc Profile(w http.ResponseWriter, r *http.Request) {   ...   // 开启采样  if err := pprof.StartCPUProfile(w); err != nil {      ...  }  sleep(r, time.Duration(sec)*time.Second)  // 停止采样  pprof.StopCPUProfile()}}

追踪 StartCPUProfile 函数，其中有两个关键步骤：runtime.SetCPUProfileRate 和 profileWriter。

// runtime/pprof/pprof.gofunc StartCPUProfile(w io.Writer) error {   ...  runtime.SetCPUProfileRate(hz) // hz固定为100  go profileWriter(w)   ...}

runtime.SetCPUProfileRate 最终调用到了 setThreadCPUProfiler 函数，该函数使用 time_create 开启了一个定时器，并设置定时器间隔时间是1s/100=10ms；该定时器会每 10ms 向所在线程定时发送 SIGPROF 信号，代码如下：

// runtime/signal_unix.gofunc setThreadCPUProfiler(hz int32) {     mp := getg().m // 获取当前协程绑定的的线程M   ...  spec := new(itimerspec)  spec.it_value.setNsec(1 + int64(fastrandn(uint32(1e9/hz))))  spec.it_interval.setNsec(1e9 / int64(hz)) // 设置间隔为 100000000/100 纳秒 = 10ms  var timerid int32  var sevp sigevent  sevp.notify = _SIGEV_THREAD_ID  sevp.signo = _SIGPROF // 设置signal类型为SIGPROF  sevp.sigev_notify_thread_id = int32(mp.procid) // 设置signal通知给线程procid  ret := timer_create(_CLOCK_THREAD_CPUTIME_ID, &sevp, &timerid) // 创建定时器   ...  ret = timer_settime(timerid, 0, spec, nil) // 启动定时器   ...}

• SIGPROF 信号处理：

线程收到 SIGPROF 信号中断后，线程关联的处理器P会使用特殊的协程 gsignal 来处理信号。在 Go 主线程启动后到开始调度循环之前，会调用 mstartm0 函数，mstartm0 中则执行了 initsig 来设置所有信号的处理入口。一路追踪 initsig 函数，最终可以在 sighandler 函数中找到处理 SIGPROF 信号的入口 sigprof。

// runtime/signal_unix.gofunc sighandler(sig uint32, info *siginfo, ctxt unsafe.Pointer, gp *g) {   ...     // SIGPROF信号的处理入口  if sig == _SIGPROF {    if !delayedSignal && validSIGPROF(mp, c) {      sigprof(c.sigpc(), c.sigsp(), c.siglr(), gp, mp)    }    return  }}

sigprof 首先会调用 gentraceback 得到当前协程正在执行的调用栈。gentraceback 比较复杂，好在大致流程是比较清晰的。简化后的代码如下图，for循环 max 次，从程序计数器 pc、栈指针 sp、链接寄存器 lr 取出当前协程的 max 层调用栈信息，保存在 pcbuf 中；profile 采样下 max 取值为64，只取64层级的栈信息。

// runtime/traceback.gofunc gentraceback(pc0, sp0, lr0 uintptr, gp *g, skip int, pcbuf *uintptr, max int, callback func(*stkframe, unsafe.Pointer) bool, v unsafe.Pointer, flags uint) int {  ...        // gp是当前协程对象G指针，保存了协程调度的各种信息       if gp.syscallsp != 0 { // 如果当前是系统调用      pc0 = gp.syscallpc // syscallpc程序计数器      sp0 = gp.syscallsp // syscallsp得到栈指针    } else { // 如果是用户代码调用      pc0 = gp.sched.pc // sched.pc程序计数器      sp0 = gp.sched.sp // sched.sp得到栈指针    }  ...  var frame stkframe     frame.pc = pc0 // 从pc0开始  frame.sp = sp0  frame.fp = 0  ...     for n < max { // profile采样时max等于64，栈信息最多取64层级      ...      frame.fp = frame.sp + uintptr(funcspdelta(f, frame.pc, &cache))      ...        pc := frame.pc      ...            (*[1 << 20]uintptr)(unsafe.Pointer(pcbuf))[n] = pc      ...      n++      frame.pc = frame.lr // pc指向lr进入下一个循环      frame.sp = frame.fp      ...   }}

sigprof 接下来调用 traceCPUSample 将得到的采样信息通过 log.write 写入 profBuf 类型的缓冲区中，profBuf 是无锁的并发安全的缓冲区，可供一个读取者和一个写入者高效安全的使用。

// runtime/trace.gofunc traceCPUSample(gp *g, pp *p, stk []uintptr) {  ...  if log := (*profBuf)(atomic.Loadp(unsafe.Pointer(&trace.CPULogWrite))); log != nil {    log.write(nil, now, hdr[:], stk)  }  ...}

至此，程序完成了采样信息的获取和写入了 profBuf 缓冲区。

回过头来看看上文中提到 StartCPUProfile 的另一个关键步骤 go profileWriter，它做的事情比较简单，就是循环从 profBuf 缓冲区中读取数据，并按调用栈进行聚合，缓冲区读到 eof 后，整理聚合的数据并压缩写入到 http 响应中。

// runtime/pprof/pprof.gofunc profileWriter(w io.Writer) {  b := newProfileBuilder(w)  var err error  for {    time.Sleep(100 * time.Millisecond)    // 从profBuf缓冲区读取数据    data, tags, eof := readProfile()    // addCPUData按调用栈聚合数据    if e := b.addCPUData(data, tags); e != nil && err == nil {      ...    }    if eof {      break // eof退出循环    }  }  ...  b.build() // 整理数据并压缩写入到http响应中}

• 关闭采样：

采样时间到期后，StopCPUProfile 函数会调用 runtime.SetCPUProfileRate(0) 将采样频率设置为0，关闭定时器结束采样。

• 性能影响：

profile 采样的本质就是每隔 10ms 时间周期，占用一个协程获取一次当前的调用栈信息，因此对性能的影响非常小，生产环境可以放心使用。

1.1.4 profile 实例分析

本小节中，将以一个 API 网关应用为例介绍 profile 优化方法。

1.1.4.1 优化前的指标情况

网关所有转发的下游全部使用 mock 服务，响应为固定时间和固定大小；使用 jmeter 压测一组3个 API，并发数为1000，迭代次数200，压测网关转发性能。

• 压测结果：总请求数600000，错误率为0%，平均 qps 为3459.8.2/s

Starting standalone test @ 2024 Jan 4 22:38:17 CST (1704379097791)summary = 600000 in 00:02:53 = 3459.8/s Avg:   281 Min:     9 Max:   1128 Err:     0 (0.00%)Tidying up ...    @ 2024 Jan 4 22:41:11 CST (1704379271495)

• 平均 CPU：72.2%

$ dstat -lcmdnt 5---load-avg--- ----total-CPU-usage---- ------memory-usage----- -dsk/total- -net/total- ----system---- 1m   5m  15m |usr sys idl wai hiq siq| used  buff  cach  free| read  writ| recv  send|     time     18.5 27.0 26.8| 52  17  24   1   0   7|26.5G 2451M 31.4G 2232M|1895k 8395k|  96M  116M|04-01 22:38:2620.7 27.3 26.9| 50  19  23   0   0   7|26.5G 2451M 31.4G 2134M|2105k   25M| 101M  116M|04-01 22:38:3123.7 27.8 27.1| 48  19  24   1   0   7|25.9G 2451M 31.4G 2722M|2486k   20M| 102M  121M|04-01 22:38:36...略...62.5 42.9 32.9| 49  16  27   1   0   7|26.1G 2446M 31.7G 2303M|3691k 7273k| 105M  122M|04-01 22:40:5666.1 44.0 33.3| 49  17  26   1   0   7|26.3G 2445M 31.7G 2051M|1539k   30M|  98M  115M|04-01 22:41:0169.8 45.1 33.7| 51  19  23   1   0   6|26.7G 2440M 31.6G 1797M|1410k   66M|  90M  102M|04-01 22:41:06

1.1.4.2 分析过程

• 整体分析：

从 svg 矢量图或 top 分析入手是一个好的选择，以 svg 矢量图分析为例。

我们可以从上图中分析出程序运行的调用链关系，例如 gin(*Context).Next 的循环调用表明，这是一个使用 gin 框架实现的 http 服务；请求经过7个 middleware 中间件后，走到了 ProxyLogicsvr 函数并最终调到了 httputil.ServeHTTP；这个流程符合预期，因为该应用就是基于 gin 框架和 httputil.ServerHttp 的代理能力搭建的网关服务。

httputil.ServerHttp 后续的节点都是 Go 原生代码，暂时不好优化；我们需要关注 ServerHttp 之前的节点，进入 ServeHTTP 节点的总时间只有26.58s，有大量 CPU 时间消耗在了代理转发之前，需要进一步分析。

首先，重点关注颜色较深的自定义函数的节点，这些节点本身或下游占用了较多 CPU 时间，同时又是我们自己写的代码，较容易进行分析和优化。比如 Check***Session 节点，高达15%的采样占比，我们要重点分析。

其次，关注其他颜色较深的节点，这些节点可能是系统调用、Golang 原生或第三方库函数。对于这部分的热点节点，我们需要了解它们的使用场景才能进一步分析。例如 runtime.growslice，这个是 Golang 切片扩容相关函数，我们无法对它本身进行优化，但是通过排查它的调用链，可以看到是否存在 slice 的误用；再例如 runtime.gcBgMarkWorker 节点，是垃圾回收 GC 的标记阶段相关的函数，我们需要针对 GC 情况进行分析。

最后，不妨通读一遍 top 模式下的所有的节点，对找出有问题的节点很有帮助。

• 节点分析：

经过整体分析，我们可以找到很多有嫌疑的节点，我们以上一节中找出的三个节点为例进行说明。

1）业务代码实现效率低

在 source 模式搜索 Check***Session，显示源码分析如下图：

可以看到一个简单的 Debug 级日志打印，居然消耗了 5.69s 的采样时间；本例中的日志级别是 Error，一个 debug 级的日志预期是不会打印的。

分析这一行代码，容易找出原因就是 req.String() 和 rsp.String()，进入 DebugGinCtxf 方法执行之前就会将 req 和 rsp 进行格式化化，导致了不必要的 CPU 开销。

优化为直接传指针，优化完的 source 分析如下，该语句基本没有额外的开销。节点总体采样 CPU 占比也从15%下降到了11.2%。

这是一个很低级的代码效率问题，但是代码 review 时可能会被忽略，而通过 profile 分析就可以进行精准定位。

2）库函数调用不合理

runtime.growslice 节点消耗了 4.81s 采样时间，总占比为4.12%。对这个节点进行分析需要知道 slice 的基本原理，当使用 append 向 slice 填加元素时，如果 slice 的容量不足，则需要将 slice 容量扩大到原来的2倍或者1.25倍（取决于扩容前的 slice 容量大小）。假如 slice 初始化时没有分配合适的容量，可能会导致 slice 进行多次扩容而产生不必要的性能开销。

在 peek 模式搜索 runtime.growslice，会遇到一大堆的数据，耐心的查看列出的所有的调用栈，可以找到下图中的一些有嫌疑的代码位置。

图中分析的 growslice 代码位置位于 runtime/slice.go 的第274行，正是 growslice 内部调用 mallocgc 分配新内存的代码行。可以看到其调用上游有很多的自定义的函数，逐一分析它们发现了多处 slice 初始化容量为0的代码；其中一个例子如下，很明显一开始就可以给 vec 分配足够的容量，从而避免多次的 slice 扩容。

  ...  // 初始容量为0  // 应该改为  // vec := make([]interface{}, 2*len(m.data))  vec := make([]interface{}, 0)  for key, value := range m.data {    vec = append(vec, key, value)  }}

将所有有问题的代码优化掉，再重新分析 peek 如下图，mallocgc 位置的采样 CPU 占比从2.17%下降到了1.54%，几个有问题的调用上游也都不见了。而 growslice 节点总体的 CPU 占比也从4.12%下降到了3.07%。

3）GC 相关优化

runtime.gcBgMarkWorker 节点消耗了9.87%的采样时间。gcBgMarkWorker 是 GC 标记阶段的关键函数，gcBgMarkWorker 占比较高可能是因为 GC 频率较高导致，可以通过调整 GOGC 配置进行优化。

简单展开一下 GOGC 配置，在 Go1.18 版本之后，自动 GC 的触发条件为：

target mem = Live heap + (Live heap + GC roots) * GOGC / 100

其中 Live heap 为上一个周期活跃的堆内存大小，GC roots 我们暂时不管。可以这样简单理解，当 GOGC 为默认值100时，新分配堆内存的数量是上一周期的活跃堆内存的一倍的时候，触发 GC；GOGC 为200时，该倍数关系变为两倍；以此类推。

我们的应用没有使用大量内存，因此可以通过调大 GOGC 配置来降低 GC 的频率，减少 GC 的 CPU 消耗。GOGC 值优化为800，优化后程序内存使用增加了1倍，而 gcBgMarkWorker 的 CPU 占比则降到了1%。

在 trace 工具中也可以对 GC 情况进行分析，将在本文的后半部分进行介绍。

1.1.4.3 优化后的指标情况

上文说明的三个节点的优化预期能减少的 CPU 消耗在10%以上，使用 jmeter 进行压测看一下实际结果。

• 压测结果：总请求数600000，错误率为0%，平均 qps 为3620.7/s

Starting standalone test @ 2024 Jan 4 22:20:26 CST (1704378026473)summary = 600000 in 00:02:46 = 3620.7/s Avg:   269 Min:    13 Max:  974 Err:     0 (0.00%)Tidying up ...    @ 2024 Jan 4 22:23:12 CST (1704378192504)

• 平均 CPU：64.2%

$ dstat -lcmdnt 5---load-avg--- ----total-CPU-usage---- ------memory-usage----- -dsk/total- -net/total- ----system---- 1m   5m  15m |usr sys idl wai hiq siq| used  buff  cach  free| read  writ| recv  send|     time  17.9 23.2 22.2| 38  19  35   1   0   7|27.4G 2462M 31.4G 1313M|3609k   19M| 104M  119M|04-01 22:20:3324.2 24.4 22.6| 37  16  38   1   0   8|27.6G 2462M 31.4G 1081M|1931k 5911k| 112M  128M|04-01 22:20:3824.7 24.5 22.7| 37  17  37   1   0   8|27.6G 2462M 31.4G 1035M|2486k 4523k| 105M  121M|04-01 22:20:43... 略...55.2 36.0 27.1| 39  17  36   1   0   7|27.6G 2466M 31.4G 1030M|3897k 6099k| 108M  124M|04-01 22:22:5854.5 36.2 27.2| 42  17  32   2   0   7|27.8G 2466M 31.3G  845M|2688k   18M| 110M  121M|04-01 22:23:0356.3 36.9 27.5| 48  18  26   1   0   7|28.3G 2467M 31.2G  463M|1942k  109M| 101M  115M|04-01 22:23:08

优化后压测 qps 提升4%，CPU 从72%下降到64%，性能提升也在10%以上，符合预期。

1.1.4.4 总结

大部分的优化措施并不会像本文给出的例子这样简单，可能涉及更复杂的逻辑修改或架构重构；但是分析流程是类似的，先从整体上找出有问题的节点，再具体分析每个问题节点得到瓶颈点和可行的优化方案。

1.2 allocs/heap 分析内存

allocs 和 heap 都可以用于内存分析，Golang 官方文档给出的差别是：allocs 统计的是从程序开始以来所有内存分配的情况（即 alloc_space），而heap统计的是当前存活的对象的内存分配情况（即 inuse_space），但是实测获取的数据都是 inuse_space。本节只讨论使用 heap 进行内存分析。

1.2.1 生成采样数据

1.2.1.1 代码直接生成

在 main 函数开头直接加入如下代码，就可以得到 heap 采样结果 mem.out。

func main() {    f, _ := os.Create("mem.out")    defer f.Close()    runtime.GC() // 手动执行一次GC垃圾回收    if err := pprof.WriteHeapProfile(f); err != nil {        log.Fatal("could not write memory profile: ", err)    }    ...}

1.2.1.2 go test 参数生成

执行 go test 时，可以加上参数 -CPUprofile mem.out 生成 heap 采样数据。

go test -memprofile mem.out . -run=TestFunc

1.2.1.3 通过 http 接口生成

• 启动 http 服务：

与 profile 采样一样，在主路径上引入 net/http/pprof 包，启动 http 服务。

import (  "net/http"  _ "net/http/pprof")func process() {  go func() {    http.ListenAndServe("127.0.0.1:6060", nil) // 安全起见，使用本地地址进行监听  }()    ...}

• 请求 http 接口生成采样数据：

使用 go tool pprof 命令访问本地服务的 /debug/pprof/heap 接口，获得 heap 采样数据保存到 $HOME/pprof/ 目录下，同时也会直接进入分析命令行。

$ go tool pprof http://127.0.0.1:6060/debug/pprof/heap?seconds=30Saved profile in /root/pprof/pprof.demo.alloc_objects.alloc_space.inuse_objects.inuse_space.001.pb.gzFile: demoType: inuse_spaceTime: Dec 30, 2023 at 4:02pm (CST)Duration: 30.09s, Total samples = 0 No samples were found with the default sample value type.Try "sample_index" command to analyze different sample values.Entering interactive mode (type "help" for commands, "o" for options)(pprof) 

1.2.2 通过 http 接口生成

分析 heap 采样数据的方式与 profile 一致，差别是 heap 用于分析当前存活的对象是从哪个调用栈分配出来的以及累计的分配内存有多少，本小节不再赘述具体的分析模式和方法。

1.2.3 heap 采样原理分析

1.2.3.1 太长不看版

• 采样数据的存储结构：

bucket 节点用于保存内存采样数据，bucket 中保存了程序调用栈信息，内存的分配大小、分配次数、回收大小、回收次数等统计信息；一个 bucket 代表程序执行到了某个调用栈并分配了某个大小的内存，不同调用栈或不同的内存大小会保存在不同的 bucket 中。

mbuckets 是一个链表结构，保存所有的内存采样数据，新增 bucket 会添加到 mbuckets 开头，通过 mbuckets 可以遍历整个内存采样 bucket。

buckhash 是一个哈希表结构，用于快速查找某个 bucket 节点，哈希 key 基于调用栈和分配内存大小两个数据进行计算。

mbuckets 和 buckhash 一起，组成了一个可遍历的哈希表存储结构。

• 内存分配过程：

内存分配过程中，每次累积分配 512kb 大小的内存后，下一次内存分配将进行采样，得到当前的调用栈信息和分配内存的大小。

按调用栈信息和分配内存的大小信息在 buckhash 中查找 bucket 节点，如果没找到则创建新的 bucket 节点并添加到 mbuckets 链表开头和添加到 buckhash 哈希表中；

找到 bucket 节点后，在节点中累加分配大小和自增分配次数；

最后还要将本次内存分配得到的对象添加特殊标记，并记录下对象和 bucket 节点的映射关系。

• GC 回收过程：

GC 过程中，回收带有特殊标记的对象时，通过对象映射关系找到 bucket 节点，在节点中累加回收大小和自增回收次数。

• 分析过程：

通过 mbuckets 遍历所有 bucket 节点，就能得到所有的内存分配和回收的调用栈信息以及分配或回收的统计数据。基于这些统计数据，就可以进行后续的各种模式的分析了。

• 性能影响：

heap 采样默认打开，对性能没有影响，生产环境可以放心使用。

1.2.3.2 源码分析

• 数据结构：

bucket、mbuckets、buckhash 定义如下：

// runtime/mprof.gotype bucket struct {  _       sys.NotInHeap  next    *bucket  allnext *bucket  typ     bucketType // memBucket or blockBucket (includes mutexProfile)  hash    uintptr  size    uintptr  nstk    uintptr}const (  buckHashSize = 179999 // 哈希表大小)type buckhashArray [buckHashSize]atomic.UnsafePointer // *bucketvar (  mbuckets atomic.UnsafePointer // 链表头部 *bucket  buckhash atomic.UnsafePointer // 哈希表 [buckHashSize]*bucket buckHashSize为179999)

bucket 结构中，allnext 指针用于指向下一个 bucket 节点，从而可以形成一个链表结构；next 指针也指向一个 bucket 节点，用于哈希表解决冲突使用；size 是节点分配内存大小；nstk 是一大块内存空间的首地址，用于保存节点调用栈信息和内存分配/回收的统计信息，使用时通过地址偏移来寻址，本文不做详细展开。

mbuckets 是 *bucket 类型的指针。

buckhash 则是 [buckHashSize]*bucket 类型的 map，buckHashSize 大小为179999。

• 查找和创建 bucket 节点：

为了更好的理解数据结构，我们将查找和创建 bucket 节点的代码拿出来提前分析，代码如下：

// runtime/mprof.gofunc stkbucket(typ bucketType, size uintptr, stk []uintptr, alloc bool) *bucket {  ...  bh := (*buckhashArray)(buckhash.Load())  // 哈希值h，通过节点调用栈stk和分配内存大小size计算得到  var h uintptr  for _, pc := range stk {    h += pc    h += h << 10    h ^= h >> 6  }  h += size  h += h << 10  h ^= h >> 6  h += h << 3  h ^= h >> 11  // 哈希槽下标i  i := int(h % buckHashSize)  // 遍历哈希表冲突链表，找到节点；eqslice确保调用栈完全相同  for b := (*bucket)(bh[i].Load()); b != nil; b = b.next {    if b.typ == typ && b.hash == h && b.size == size && eqslice(b.stk(), stk) {      // 如果找到bucket指针就直接返回      return b     }  }  // 没有找到bucket节点，则创建新bucket节点  b := newBucket(typ, len(stk))  copy(b.stk(), stk) // 拷贝调用栈  b.hash = h // 设置hash  b.size = size // 设置分配内存大小  var allnext *atomic.UnsafePointer  if typ == memProfile {    allnext = &mbuckets // typ为内存分析，allnext指向mbuckets链表表头  }  ...  // 头插法，将bucket插入哈希桶buckhash[i]的冲突链表开头  b.next = (*bucket)(bh[i].Load())   // 头插法，将bucket插入mbuckets链表开头  b.allnext = (*bucket)(allnext.Load())  bh[i].StoreNoWB(unsafe.Pointer(b))  allnext.StoreNoWB(unsafe.Pointer(b))}

代码流程很清晰：根据节点调用栈 stk 和分配内存大小 size 计算哈希值 h，并计算出哈希槽下标 i；遍历哈希表 buckhash 的冲突链表 bh[i]，如果找到已存在该节点，则直接返回；否则创建一个新的 bucket 节点 b，保存内存大小、调用栈信息到 b 中，将 b 插入到 mbuckets 链表开头，将 b 加入冲突链表 bh[i] 开头。

• 内存分配过程：

runtime.mallocgc 函数是 Golang 堆内存管理的关键函数，所有的 new、make 和拷贝等操作都会走到 mallocgc 函数进行处理。在 mallocgc 函数中可以找到内存采样逻辑如下：

// runtime/malloc.gofunc mallocgc(size uintptr, typ *_type, needzero bool) unsafe.Pointer {  c := getMCache(mp) // 线程缓存cache  ...  // MemProfileRate默认为512 * 1024，内存分配采样默认开启  if rate := MemProfileRate; rate > 0 {    if rate != 1 && size < c.nextSample {      c.nextSample -= size     } else {      profilealloc(mp, x, size)    }  }  ...}func profilealloc(mp *m, x unsafe.Pointer, size uintptr) {  c := getMCache(mp) // 线程缓存cache  c.nextSample = nextSample() // 重置c.nextSample为512k  mProf_Malloc(x, size) // 进行内存分配采样}

c.nextSample 缓存了距离下次采样还需要分配多少内存，初始值为512k；每次分配内存时 c.nextSample 的值会减去当次分配内存的大小 size；当 size 小于 c.nextSample 时，说明累积分配了足够多的内存，此时会重置 c.nextSample 为初始值，并调用 mProf_Malloc 函数。

// runtime/mprof.gofunc callers(skip int, pcbuf []uintptr) int {  sp := getcallersp()  pc := getcallerpc()  gp := getg()  var n int  systemstack(func() {    // gentraceback获取调用栈信息    n = gentraceback(pc, sp, 0, gp, skip, &pcbuf[0], len(pcbuf), nil, nil, 0)  })  return n}func mProf_Malloc(p unsafe.Pointer, size uintptr) {  var stk [maxStack]uintptr // maxStack为32  // callers 调用gentraceback获取调用栈信息  nstk := callers(4, stk[:])  index := (mProfCycle.read() + 2) % uint32(len(memRecord{}.future))  // stkbucket 查找或创建bucket节点  b := stkbucket(memProfile, size, stk[:nstk], true)  // b.ntsk按偏移量定位到统计信息对象的地址，取出统计对象指针mp  mp := b.mp()  mpc := &mp.future[index]  lock(&profMemFutureLock[index])  mpc.allocs++ // 自增内存分配次数  mpc.alloc_bytes += size // 累加内存分配大小  unlock(&profMemFutureLock[index])  systemstack(func() {    // setprofilebucket，给对象打上_KindSpecialProfile标记，设置对象和bucket的关联关系    setprofilebucket(p, b)  })}

mProf_Malloc 函数逻辑也很清晰：

第一步，调用 callers 函数获得调用栈信息，在 callers 函数内部又调用了 gentraceback 函数，在 profile 采样原理分析小节中我们简单分析过这个函数是如何获取N层级的栈信息的，内存采样时采样了32层级的栈信息；

第二步，调用上文讨论过的 stkbucket 函数，得到 bucket 指针 b；

第三步，按偏移量从 b.nstk 中取到统计对象 mpc，调用 mpc.allocs++ 和 mpc.alloc_bytes += size，在 bucket 节点的统计对象中累加分配大小和自增分配次数；

第四步，调用 setprofilebucket 给对象 p 打上 _KindSpecialProfile 标记，并保存对象 p 和 bucket 指针 b 的映射关系，标记和映射关系都是保存在对象的 special 记录中，感兴趣的读者可以自行查看 setprofilebucket 源码，本文不进行展开。

• 内存回收过程：

对象销毁是在 GC 的清除阶段完成的，入口是 gcSweep。跟踪 gcSweep 流程可以在 freeSpecial 函数中看到，针对有被打上 _KindSpecialProfile 标记的对象有一个额外处理：查找到对象映射的 bucket 指针并调用了 mProf_Free。

// runtime/mheap.gofunc freeSpecial(s *special, p unsafe.Pointer, size uintptr) {  switch s.kind {  ...  case _KindSpecialProfile:    sp := (*specialprofile)(unsafe.Pointer(s))    // 调用mProf_Free，参数sp.b就是对象关联的bucket指针    mProf_Free(sp.b, size)     lock(&mheap_.speciallock)    mheap_.specialprofilealloc.free(unsafe.Pointer(sp))    unlock(&mheap_.speciallock)  ...  }}// runtime/mprof.gofunc mProf_Free(b *bucket, size uintptr) {  index := (mProfCycle.read() + 1) % uint32(len(memRecord{}.future))  // b.ntsk按偏移量定位到统计信息对象地址，取出统计对象指针  mp := b.mp()  mpc := &mp.future[index]  lock(&profMemFutureLock[index])  mpc.frees++ // 自增内存回收次数  mpc.free_bytes += size // 累加内存回收大小  unlock(&profMemFutureLock[index])}

mProf_Free 内部的处理就很简单了，按偏移量从 b.nstk 中取到统计对象 mpc，调用 mpc.frees++ 和 mpc.free_bytes += size，累加回收大小和自增回收次数。

• 分析过程：

遍历 mbuckets 中的所有 bucket 节点，就可以得到所有的内存分配和回收的采样情况，如果某个 bucket 节点统计信息中 alloc_bytes > free_bytes，就说明该 bucket 的调用栈对应有存活状态的对象，分配内存的大小=alloc_bytes-free_bytes，分配内存次数=allocs-frees；配合调用栈信息，就可以进一步分析程序的内存使用情况了。

• 性能影响：

内存采样默认一直都在进行中，所以采样 heap 数据对性能完全没有影响。

1.2.4 heap 实例分析

一般来讲，内存使用量并不是后台服务的主要瓶颈，本小节举个简单的优化。打开网关 heap 采样数据，进行 top 分析如下：

排在前列的调用中有一个自定义的方法 UpdateSysCookie，它的内存分配占比达到3.13%。使用 source 模式搜索分析 UpdateSysCookie 方法：

可以看到，m.SysCookie = &meshkit.MMSystemReqCookie{} 这一行语句采样到了 1.5MB 的内存分配。每次执行该方法都创建新对象，导致了较频繁的内存分配操作。我们可以通过引入 sync.Pool 对象池来优化，代码如下：

// poolMMSystemReqCookie syscookie对象池var poolMMSystemReqCookie = sync.Pool{  New: func() interface{} {    return &meshkit.MMSystemReqCookie{}  },}// getMMSystemReqCookie 从对象池中获取syscookie对象func getMMSystemReqCookie() *meshkit.MMSystemReqCookie {  return poolMMSystemReqCookie.Get().(*meshkit.MMSystemReqCookie)}// putMMSystemReqCookie 将syscookie对象清理后放回对象池func putMMSystemReqCookie(syscookie *meshkit.MMSystemReqCookie) {  if syscookie == nil {    return  }  cleanMMSystemReqCookie(syscookie)  poolMMSystemReqCookie.Put(syscookie)}// cleanMMSystemReqCookie 清理syscookie对象中的内容func cleanMMSystemReqCookie(syscookie *meshkit.MMSystemReqCookie) {  syscookie.Xxx = nil  ...}func (m *BaseInfo) UpdateSysCookie(fun func(*meshkit.MMSystemReqCookie)) {  m.lock.Lock()  defer m.lock.Unlock()  if m.SysCookie == nil {    // m.SysCookie = &meshkit.MMSystemReqCookie{} // 原始代码    m.SysCookie = getMMSystemReqCookie() // 使用对象池  }  fun(m.SysCookie)}// Clean 清理BaseInfo对象func (m *BaseInfo) Clean() {  ...  // 清理BaseInfo对象的同时也将其成员m.SysCookie放回对象池  putMMSystemReqCookie(m.SysCookie)}

通过 getMMSystemReqCookie 方法从对象池中获取对象，流程结束后再调用 putMMSystemReqCookie 将对象放回对象池。优化后再次分析heap，在top中已经看不到 UpdateSysCookie 了，source 模式也搜索不到 UpdateSysCookie 了，因为根本就没采样到该调用栈有内存分配了，优化目标达成。

1.3 goroutine 分析 Golang 协程

1.3.1 生成数据

1.3.1.1 代码直接生成

在 main 函数开头直接加入如下代码，就可以得到 goroutine 采样结果 goroutine.out。

func main() {  f, _ := os.Create("goroutine.out")  defer f.Close()  err := pprof.Lookup("goroutine").WriteTo(f, 1)  if err != nil {    log.Fatal(err)  }}

1.3.1.2 通过 http 接口生成

• 启动 http 服务：

与 profile 采样一样，在主路径上引入 net/http/pprof 包，启动 http 服务。

import (  "net/http"  _ "net/http/pprof")func process() {  go func() {    http.ListenAndServe("127.0.0.1:6060", nil) // 安全起见，使用本地地址进行监听  }()    ...}

• 获取指定时间段内的 goroutine 统计数据，按调用栈维度统计计数：

使用 go tool pprof 命令访问本地服务 /debug/pprof/goroutine?seconds={second}

$ go tool pprof http://127.0.0.1:6060/debug/pprof/goroutine?seconds=30Saved profile in /root/pprof/pprof.demo.goroutine.001.pb.gzFile: demoType: goroutineTime: Dec 31, 2023 at 12:59pm (CST)Duration: 10.01s, Total samples = 4 Entering interactive mode (type "help" for commands, "o" for options)(pprof)

• 获取当前时刻所有 goroutine 统计数据，按调用栈维度统计计数：

使用 go tool pprof 命令访问本地服务 /debug/pprof/goroutine?debug=1

$ go tool pprof http://127.0.0.1:6060/debug/pprof/goroutine?debug=1Saved profile in /root/pprof/pprof.demo.goroutine.001.pb.gzType: goroutineEntering interactive mode (type "help" for commands, "o" for options)(pprof)

• 获取当前所有 goroutine 的栈信息，展示每一个 goroutine 的信息：

直接通过 http 请求到本地服务 /debug/pprof/goroutine?debug=2

$ curl http://127.0.0.1:6060/debug/pprof/goroutine?debug=2goroutine 5879255 [select]:google.golang.org/grpc.newClientStreamWithParams.func4()        /home/xxx/go/pkg/mod/google.golang.org/grpc@v1.55.0/stream.go:375 +0x92created by google.golang.org/grpc.newClientStreamWithParams        /home/xxx/go/pkg/mod/google.golang.org/grpc@v1.55.0/stream.go:374 +0xf2agoroutine 5879362 [IO wait]:internal/poll.runtime_pollWait(0x7f3f84af3470, 0x72)        /usr/local/go/src/runtime/netpoll.go:306 +0x89internal/poll.(*pollDesc).wait(0xc0061fed80?, 0xc001353000?, 0x0)        /usr/local/go/src/internal/poll/fd_poll_runtime.go:84 +0x32...

1.3.2 分析数据

使用 go tool pprof 分析 goroutine 数据的方式与 profile 一致，差别是 goroutine 用于分析所有的协程数量和协程的调用栈情况，本小节不再赘述具体的分析模式和方法。

单独说明一下通过 http 请求直接请求 /debug/pprof/goroutine?debug=2 接口的数据分析，这个模式下不仅可以看到每一个协程的栈信息，还能看到当前协程的状态和持续的时间（如[running]、[select, 6 minutes]、[IO wait]、[chan receive]等），当需要针对某一个具体的协程进行分析时可以使用该模式。

1.3.3 goroutine 获取数据原理分析

1.3.3.1 太长不看版

• 如何采样：

Golang 的 newproc 函数用于创建新的协程，而新的协程对象 G 创建出来后，会通过 allgadd 函数将 G 指针添加到全局切片对象 allgs 中。通过遍历全局切片对象 allgs 即可获取每一个协程对象 G，并从 G 中获取调用栈信息。

• 性能影响：

goroutine 采样对性能的影响比 pprof 和 heap 更大。

Go1.18及之前版本在循环遍历获取 goroutine 数据的整个过程中，会 stopTheWorld 停止进程的执行，生产环境需谨慎使用。

Go1.19版本之后，在获取 goroutine 数据过程中，只会有两次短暂的 stopTheWorld 停止整个进程，实测对程序整体的影响不大，生产环境对性能要求不高的场景仍然可以使用。

1.3.3.2 源码分析

• 如何采样：

获取 goroutine 数据的入口是 writeGoroutine，代码如下：

// runtime/pprof/pprof.gofunc writeGoroutine(w io.Writer, debug int) error {  if debug >= 2 {    return writeGoroutineStacks(w)  }  return writeRuntimeProfile(w, debug, "goroutine", runtime_goroutineProfileWithLabels)}

当 debug 大于等于2时，调用 writeGoroutineStacks 函数，否则调用 writeRuntimeProfile 函数。两个函数流程类似，差别在于 debug 小于2时，会按调用栈合并统计总数。本小节分析 writeRuntimeProfile，writeGoroutineStacks 的情况读者可以自行查看源码。

writeRuntimeProfile 函数代码如下：

// runtime/pprof/pprof.gofunc writeRuntimeProfile(w io.Writer, debug int, name string, fetch func([]runtime.StackRecord, []unsafe.Pointer) (int, bool)) error {  var p []runtime.StackRecord  var labels []unsafe.Pointer  n, ok := fetch(nil, nil) // 调用fetch获取数量  for {    // 分配足够容量的StackRecord切片p，容量比n略微大一些，防止短时间内有更多的goroutine开启    p = make([]runtime.StackRecord, n+10)    labels = make([]unsafe.Pointer, n+10)    n, ok = fetch(p, labels) // 再次调用fetch填充切片p    if ok {      p = p[0:n]      break    }  }  return printCountProfile(w, debug, name, &runtimeProfile{p, labels})}

首先调用 fetch 获取协程总量 n；

然后分配足够容量的 StackRecord 切片 p，用于保存每一个协程的信息，容量为 n+10，防止在获取 n 之后又有新的 groutine 生成；

接下来是一个 for 循环，循环内部第二次调用 fetch 获取每个协程信息填充到传入的切片 p 中，fetch 失败会在 for 循环内重试；

最后调用 printCountProfile 将相同栈信息的协程合并，统计总数。

fetch 是一个函数指针，指向了
goroutineProfileWithLabelsConcurrent 函数，代码如下：

// runtime/mprof.gofunc goroutineProfileWithLabelsConcurrent(p []StackRecord, labels []unsafe.Pointer) (n int, ok bool) {  ...  stopTheWorld("profile") // 停止整个进程  ...  n = int(gcount())  ...  if n > len(p) {    // 传入p为nil时将走到这里，直接返回n    startTheWorld()    semrelease(&goroutineProfile.sema)    return n, false  }  // 保存当前协程的信息  sp := getcallersp()  pc := getcallerpc()  systemstack(func() {    saveg(pc, sp, ourg, &p[0])  })  ourg.goroutineProfiled.Store(goroutineProfileSatisfied)  goroutineProfile.offset.Store(1)  goroutineProfile.active = true  goroutineProfile.records = p  goroutineProfile.labels = labels  ...  startTheWorld()  // 遍历所有协程，记录栈信息  forEachGRace(func(gp1 *g) {    tryRecordGoroutineProfile(gp1, Gosched)  })  stopTheWorld("profile cleanup")  endOffset := goroutineProfile.offset.Swap(0)  goroutineProfile.active = false  goroutineProfile.records = nil  goroutineProfile.labels = nil  startTheWorld()  forEachGRace(func(gp1 *g) {    gp1.goroutineProfiled.Store(goroutineProfileAbsent)  })  ...}

goroutineProfileWithLabelsConcurrent 函数逻辑比较清晰：

首先调用 gcount 从全局变量 allglen 中获取协程的总数；

接下来如果参数传入的 p 是 nil，则直接返回，对应第一次调用 fetch 获取总数；

如果参数传入的 p 不是 nil，就继续调用 forEachGRace 遍历全局变量 allgs 获取每一个协程对象的地址，并调用 tryRecordGoroutineProfile 记录协程信息。

• 性能影响

我们可以看到
goroutineProfileWithLabelsConcurrent 函数调用了两次 stopTheWorld 停止整个进程，第一次是获取所有协程数量前，第二次是修改全局变量 goroutineProfile 之前；而中间循环获取协程信息的过程是和其他协程并发处理的。

上面这段代码是 Go1.19 之后的代码逻辑。但是在 Go1.18 版本及之前，goroutine 采样操作在整个过程中都会 stopTheWorld 停止整个进程，对应的函数是
goroutineProfileWithLabelsSync。

Go1.18 及之前的版本的 goroutine 采样笔者没有进行实际测试，生产环境影响不太确定，有需要请谨慎使用。

Go1.19 版本，因为需要两次 stopTheWorld，因此 goroutine 的性能影响要比 profile 和 heap 更大，不过实测影响也并不大，生产环境也可以使用。

1.3.4 goroutine 实例分析

goroutine 分析比较简单本文就不做展开了；如果想分析 goroutine 泄露问题、或者想查询当前有多少协程以及协程是在哪个调用栈开启的，那么直接用 svg 图、top 和 source 模式进行分析就能很快得出结论。

02

trace 工具详解

上一章中分析的 pprof 工具有着广泛的应用，可以用来很大一部分的性能问题，但是仍然有很多场景是其无法分析的。例如存在严重阻塞或者存在网络 IO 瓶颈的场景，这种因为等待而导致的性能不达标，CPU 占用和内存消耗可能都很小，pprof 分析无能为力，这时候就是 trace 工具大显身手的时候了。

trace 工具可以记录 Go 程序运行时的所有事件，例如协程的创建、结束、阻塞、解除阻塞，系统调用的进入和退出，GC 开始、结束和 stopTheWorld 等等；trace 会记录每个事件的纳秒级时间戳和调用栈信息。后续通过 trace 可视化工具打开记录的事件信息，就可以追踪事件的前驱后置，以及分析事件相关的协程的调度、阻塞等情况。

2.1 生成 trace 数据

2.1.1 代码直接生成

在 main 函数开头直接加入如下代码，就可以在程序结束后得到 trace.out 数据。

func main() {  f, _ := os.Create("trace.out")  defer f.Close()  trace.Start(f)  defer trace.Stop()  ...}

2.1.2 通过 http 接口生成

• 启动 http 服务：

与 profile 采样一样的处理方式，在主路径上引入 net/http/pprof 包，启动 http 服务

import (  "net/http"  _ "net/http/pprof")func process() {  go func() {    http.ListenAndServe("127.0.0.1:6060", nil) // 安全起见，使用本地地址进行监听  }()    ...}

• 请求 http 接口生成 trace 数据：

直接通过 http 请求到本地服务 /debug/pprof/trace 获得 trace 数据。

$ curl http://127.0.0.1:6060/debug/pprof/trace?seconds=10 > trace.data

2.2 分析 trace 数据

2.2.1 打开 trace 数据

trace 数据需要通过可视化界面进行分析，使用 go tool trace -http=ip:port 启动 http 服务，trace 解析耗时比较久，需要耐心等待。

$ go tool trace -http 127.0.0.1:9998 trace.out 2024/01/01 16:19:26 Parsing trace...2024/01/01 16:19:41 Splitting trace...2024/01/01 16:20:13 Opening browser. Trace viewer is listening on http://127.0.0.1:9998

浏览器访问 http://127.0.0.1:9998 可以打开可视化界面，如下图：

页面中包含四个主要部分，在下文将进行详细介绍：

• View trace。
• Profiles。
• Goroutine analysis。
• Minimum mutator utilization。

2.2.2 view trace

• view trace 总览：

View trace 的数据量一般较大，因此分析时只能对一小段时间片进行分析。任意进入一个时间片的 view trace 如下图。

第一次看到这个视图的读者大概率会觉得眼花缭乱，是因为时间粒度设置太大了，数据都杂在了一起；可以使用键盘 w/s 进行放大/缩小，键盘 a/d 进行时间轴的左移/右移，调整到合适的时间粒度才能进行下一步分析。

整个视图主要分为三部分，STAT 统计区域、PROCS 视图区域、选中项详情区域；其中位于最下方的选中项详情区域是上方两个区域的补充，鼠标选中或框选 STAT 或 PROCS 区域中带颜色的矩形块时，选中项详情区会展示额外的详细信息。

• STATS：

STATS 区域展示数据统计信息，从上到下依次是：

1. 协程统计，统计不同状态的协程数量（蓝色为 Runnable 数量，绿色为 Running 数量）。
2. 内存统计，统计当前分配内存大小（绿色为 NextGC 大小，红色为 Allocated 大小）。
3. 线程统计，统计不同状态的线程数量（绿色为 InSyscall 数量，紫红色为 Running 数量）。

在感兴趣的统计区域鼠标左键选中某个时刻或框选一段时间范围，选中项详情区域会展示更详细的信息。比如选中协程统计后，选中项详情区域将展示不同状态的协程具体的数量如下图。

• PROCS：

PROCS 是最复杂的部分，展示了采样周期内所有处理器上的所有事件。配合选中项详情区域可以得到很多信息。

按 s 键缩小视图可以对 GC 情况大致进行分析，上图是一个示例，可以看到该采样时间片内只执行了一次 GC，GC 持续时间 62ms，占用了3个协程来进行 GC。

按 w 键放大视图，可以对协程调度和阻塞情况进行分析，上图是单击选中运行在 Proc 8 上的 G889532 这个协程的结果。

查看下方的详情区域，左侧是基本信息，可以看到该协程执行了687微秒后被切换出了执行队列，而 End Stack Trace 显示，切换前协程调用栈位置在 runtime.chanrecv1，是一个 channel 的出队操作；

详情区域右侧是相关的 Events 事件，其中 Incoming flow 是导致该协程 unblock 解除阻塞的事件，两个 Outgoing flow 是指该协程的执行有导致两个后续unblock解除阻塞事件发生；接下来的 Preceding events、Following events 和 All connected events，分别代表所有的前驱事件链、后继事件链和所有相关的事件链。

鼠标悬停到 Link 列上，会出现箭头表明事件的前驱后置关系。点击Link列会展示更多事件流的信息。下图展示的是点击 Incoming flow 后的例子，图中的红色小箭头，代表导致 G889532 协程 unblock 事件发生在 G890930 协程。下方详情区域的红框标明了 From 和 To 也说明了这一点，另外可以看到 From 事件的调用栈在 net/http.(*persistConn).readLoop:2218 上，可知是 G890930 协程中 http 请求收到响应的后续处理导致了 G889532 协程的解除阻塞 unblock，分析源码可以看到实际上是一个 select 操作导致的。

2.2.3 Profiles

profiles 包含了四种数据类型

• network blocking：网络 IO 阻塞，协程阻塞在网络 IO 上的时间分析。
• Synchronization blocking：同步阻塞分析，协程阻塞在 waiting 状态的时间分析。
• Syscall blocking：系统调用阻塞，协程阻塞在系统调用上的时间分析。
• Scheduler latency：调度器延迟分析，协程从 runnable 状态到 running 状态花费的时间的分析。

打开后是四种数据类型的 svg 矢量图分析，分析方式与 profile 中的 svg 矢量图一致，不再赘述。

2.2.4 Goroutine analysis

打开 goroutine 分析如下，每一行是按协程调用栈汇总统计的协程数量。

点击左侧调用栈可以查看每一个的协程及其统计数据，包括协程汇总的执行时间、网络等待时间、同步阻塞时间、调度等待时间、GC 清扫时间和 GC 总时间。

继续点击 Goroutine 列可以进入 view trace 视图，进入指定协程的 view trace 视图。

goroutine 分析与 profile 里的 goroutine 分析都是对协程的分析，不过分析角度不尽不同；profile 的 goroutine 用于协程调用栈和状态的分析，而 trace 中的 goroutine 关注的是协程发生的事件和各种阻塞的时间。

2.2.5 minimum mutator utilization

minimum mutator utilization（mmu）是评价 GC 的重要指标，进入 minimum mutator utilization 分析界面如下图：

横坐标表示时间窗口，纵坐标 mmu 是指除了 GC 外程序占用 CPU 的最小的比例；在曲线上单击鼠标，可以在下方展示更多的信息。

用一个例子来说明，上图选中了横坐标 811.13μs 这个点，其对应的纵坐标是0；表明在 811.13μs 的时间窗口内，除了 GC 外，程序占用 CPU 最小值为0%，也就是说存在一个 811.13μs 的时间范围，该时间范围内整个程序除了 GC 外什么事情都没做。上图下方的列表列出了按 CPU 占用率从低到高的几个时间窗口信息，第一条0.000的这一个时间窗口发生在开始时间 244ms 左右；点击该条目进入 view trace 视图并放大如下图，可以看到原来是一次长达 811.13μs 的 stopTheWorld 停止了整个进程导致的。

我们还需要关注的是mmu曲线随横坐标变大而趋于稳定的 mmu 值，这个值越大越好，上上图 1s 刻度上 mmu 值为0.9725；这个值可以近似的代表整个程序运行过程中 GC 的 CPU 占用率=1-0.9725=2.75%。

在1.4.2小节中说明了通过调整 GOGC 配置进行 GC 优化，优化前后分别使用 minimum mutator utilization 进行分析，通过曲线的变化趋势，也可以分析出 GC 的 CPU 占用率的优化情况。

2.3 trace 获取数据原理

2.3.1 太长不看版

• 获取和分析数据

trace 包中定义了50种不同类型的事件 Event。Go 源码中针对所有的这些事件，都添加了 traceEvent 的埋点代码。

当用户请求 /debug/pprof/trace 接口时，埋点开关将变成 true；开关打开后所有的埋点代码都会被执行，而 traceEvent 就会将当前执行的协程 id、Proc id、埋点的额外参数、调用栈信息和事件类型一起，记录到缓冲区里；而另一个新建的协程会从缓冲区中循环读取数据，并写到 http 响应中。

解析所有的事件，就可以得到 view trace、Goroutine analysis、profile 和 mmu 信息。

• 性能影响

开启 trace 后会严重影响程序性能，至少在30%以上，记录的事件越多性能性能越严重，生产环境需谨慎使用。

2.3.2 源码分析

• 埋点代码：

首先分析一下埋点代码，以开启 gc 的入口函数 gcStart 为例子进行说明，代码如下：

// runtime/mgc.gofunc gcStart(trigger gcTrigger) {  ...  if trace.enabled {    traceGCStart()  }  ...  if trace.enabled {    traceGCSTWStart(1)  }  ...}// runtime/trace.gofunc traceGCStart() {  traceEvent(traceEvGCStart, 3, trace.seqGC)  trace.seqGC++}func traceGCSTWStart(kind int) {  traceEvent(traceEvGCSTWStart, -1, uint64(kind))}func traceEvent(ev byte, skip int, args ...uint64) {...}

代码中的 trace.enabled 就是开启 trace 的开关。开关开启后，埋点代码 traceGCStart和traceGCSTWStart，都会被执行。

所有的埋点代码都会调用 traceEvent 函数。traceEvent 的参数 ev 传递当前的事件类型，skip 是跳过栈的层级数，args 是可变的额外参数。

traceEvent 内部不进行详细分析，可以预期到其内部一定会调用到我们的老熟人 gentraceback 函数获取栈信息；在获得了协程 id、执行器 id、传入的额外参数、调用栈信息和事件类型等所需数据后，traceEvent 将数据以及当前的纳秒时间戳写入缓冲区 traceBuf 中；traceBuf 是一个无锁的并发安全的缓冲区，类似上文中提到过的 profBuf，可以用来进行高效的读写。

• 开启 trace

通过 http 接口请求 /debug/pprof/trace，打开开启 trace；入口在 Trace 函数，Trace 函数中调用 trace.Start 函数开启 trace，sleep 一段时间后，调用 trace.Stop 关闭了 trace，代码如下：

// net/http/pprof/pprof.gofunc init() {  ...  http.HandleFunc("/debug/pprof/trace", Trace)}func Trace(w http.ResponseWriter, r *http.Request) {  ...  if err := trace.Start(w); err != nil {    ...  }  sleep(r, time.Duration(sec*float64(time.Second)))  trace.Stop()}// runtime/trace/trace.gofunc Start(w io.Writer) error {  tracing.Lock()  defer tracing.Unlock()  // 调用runtime.StartTrace  if err := runtime.StartTrace(); err != nil {    return err  }  go func() {    // 开启一个协程循环读取缓冲区并写入http响应    for {      data := runtime.ReadTrace()      if data == nil {        break      }      w.Write(data)    }  }()  tracing.enabled.Store(true) // 打开埋点开关  return nil}func Stop() {  tracing.Lock()  defer tracing.Unlock()  tracing.enabled.Store(false) // 关闭埋点开关  runtime.StopTrace()}

trace.Stop 很简单，调用 tracing.enabled.Store(false) 来关闭埋点开关；

trace.Start 首先调用了 runtime.StartTrace 函数，接下来开启了一个协程循环读取缓冲区并写入 http 响应中，最后调用 tracing.enabled.Store(true) 打开了埋点开关。后两步很好理解，我们看一下 runtime.StartTrace 做了什么：

func StartTrace() error {  stopTheWorldGC("start tracing") // 停止整个协程  ...  forEachGRace(func(gp *g) {    status := readgstatus(gp)    if status != _Gdead {      ...      traceEvent(traceEvGoCreate, -1, gp.goid, uint64(id), stackID)    }    if status == _Gwaiting {      ...      traceEvent(traceEvGoWaiting, -1, gp.goid)    }    if status == _Gsyscall {      ...      traceEvent(traceEvGoInSyscall, -1, gp.goid)    } else if status == _Gdead && gp.m != nil && gp.m.isextra {      ...      traceEvent(traceEvGoCreate, -1, gp.goid, uint64(id), stackID)      gp.traceseq++      traceEvent(traceEvGoInSyscall, -1, gp.goid)    } else {      gp.sysblocktraced = false    }  })  ...  startTheWorldGC()  return nil}

可以看到函数内首先调用了 stopTheWorldGC 停止整个进程；然后调用 forEachGRace 来遍历所有的协程，对每个协程，根据协程当前不同的状态，调用 traceEvent 记录了不同的事件；最后再调用 startTheWorldGC 启动整个进程。这一大堆操作其实是在补充已经无法追踪的事件；已经发生过的协程事件，自然是没有记录的，为了让整个 trace 完整，需要做这个初始化处理。

• Incoming flow 和 Outcoming flow

有了这些数据，就能够绘制 view trace 了，例如通过协程的开始、结束、阻塞和解除阻塞事件，就能画出 view trace 里协程的一个个小矩形块了。

但是仍然有一个疑问就是：Incoming flow 和 Outcoming flow 是怎么关联上的呢？其实也很简单，就是上文中的额外参数传递的。

以 channel 的入队处理为例子进行说明；了解 channel 使用的读者肯定知道，当 channel 为空时，出队操作将一直阻塞到有入队操作发生后才会解除阻塞。查看入队操作源码如下：

// runtime/chan.gofunc chansend(c *hchan, ep unsafe.Pointer, block bool, callerpc uintptr) bool {  ...  if sg := c.recvq.dequeue(); sg != nil {    // Found a waiting receiver. We pass the value we want to send    // directly to the receiver, bypassing the channel buffer (if any).    send(c, sg, ep, func() { unlock(&c.lock) }, 3)    return true  }  ...}

在 chansend 函数中，尝试调用 c.recvq.dequeue 得到一个正在等待状态的接收者对象 sudog，并调用 send 函数将数据传递给接受者，同时会调用 ready 函数将接收者协程唤醒。在 trace.enabled 为 true 时，send 函数将一路调用到 traceGoUnpark 埋点函数如下：

// runtime/trace.gofunc traceGoUnpark(gp *g, skip int) {  pp := getg().m.p  gp.traceseq++  if gp.tracelastp == pp {    traceEvent(traceEvGoUnblockLocal, skip, gp.goid)  } else {    gp.tracelastp = pp    traceEvent(traceEvGoUnblock, skip, gp.goid, gp.traceseq)  }}

可以看到 traceEvent 第三个参数传递的是 gp.goid，而 gp.goid 正是 send 函数传递的接收者对象 sg 中保存的协程 id。通过额外参数传递解除阻塞的协程 id，再加上当前的栈信息，我们就能知道是当前协程中的 chansend 调用，导致了另一个协程的 unblock 解除阻塞事件发生了。

• 性能影响

因为每一个事件都要执行埋点代码，所以开启 trace 对性能影响非常大，事件越多影响越大，预期至少是30%以上的额外性能开销，trace 在生产环境中请谨慎使用。

2.4 trace 实例

本小节分析的例子来自 github 上一个很经典的例子 justforfunc-22，强烈建议读者也去看看原作者的博客原文；不过原博文的分析深度略显不足，本节借用这个优化实例进行更深入的分析。

2.4.1 原始代码及 trace 分析

原始代码用于生成一张曼德勃罗特图片，是一种复杂的几何图形，我们这里并不关心图片生成的具体算法，只需要知道图中每一个点的像素值和该点的坐标 x、y 及图片大小 w、h 有关。原始代码如下：

func main() {  // 开启trace输出到stdout上  trace.Start(os.Stdout)  defer trace.Stop()  // 创建待生成的图片文件  f, err := os.Create(output)  if err != nil {    log.Fatal(err)  }  // 生成曼德勃罗特图  img := createSeq(width, height)  // 保存图片到文件  if err = png.Encode(f, img); err != nil {    log.Fatal(err)  }}// CreateSeq 生成曼德勃罗特图的原始代码func createSeq(width, height int) image.Image {  // 创建image对象  m := image.NewGray(image.Rect(0, 0, width, height))  // for循环串行  for i := 0; i < width; i++ {    for j := 0; j < height; j++ {      // 调用pixel按照曼德勃罗特图的规则计算像素值大小      // m.Set将像素值设置到image对象m中，该操作是并发安全的      m.Set(i, j, pixel(i, j, width, height))     }  }  return m}

createSeq 函数是原始的生成算法，使用一个 for 循环，串行的调用 pixel 函数计算每一个像素点的像素值，并保存到 image 对象中。

原始代码的执行时间是 3.992s。打开 trace，查看 view trace 的情况：

可以看到，虽然一共有5个 Proc 在进行调度，但是从头到位只有一个协程 G1 在 Proc 0 上执行代码，这显然是效率低下的。

2.4.2 优化一 chan 并行化

针对原始代码的串行问题，可以很容易的想到并发来优化。justforfunc-22 中给出了一种经典的生产者+工作者的优化方案，代码如下：

// createWorkers 并行优化func createWorkers(width, height int) image.Image {  // 创建image对象  m := image.NewGray(image.Rect(0, 0, width, height))  type px struct{ x, y int }  c := make(chan px)  // 注意c没有甚至缓冲区  var w sync.WaitGroup  // numWorkers为8，创建8个工作者  for n := 0; n < numWorkers; n++ {    w.Add(1)    go func() {      // 从channel出队像素对象并处理      for px := range c {        m.Set(px.x, px.y, pixel(px.x, px.y, width, height))      }      w.Done()    }()  }  // 遍历每一个像素点  for i := 0; i < width; i++ {    for j := 0; j < height; j++ {      // 向channel中入队像素对象      c <- px{i, j}    }  }  close(c)  w.Wait()  return m}

createWorkersBuffered 函数中创建了一个缓冲区容量为0的 channel，主协程循环向 channel 中入队所有需要计算的像素点坐标对象 px；另外开启了8个工作者协程，循环从 channel 中出队坐标对象，并计算像素值。

优化一的执行时间是3.018秒，相比串行执行4秒左右的耗时并没有达到预期的提升，打开 view trace 分析一下：

图中可以看到，一共有8个处理器在运行我们的程序，但是肉眼可见每个 Proc 都没有跑满，有大量间隙存在。我们放大 trace 查看，鼠标选中主协程 G1，将鼠标悬停到 Following Events 上，如下图：

可以看到有时候主协程 G1 runtime.main 和其他协程在并行执行，如绿框内的时间段；但是有时候主协程却会和另一个协程串行调度，同时没有其他的协程在并行执行，如图中红框的时间段。为什么会这样呢？

我们知道没有缓冲容量的 channel 有一个特性，出队操作时如果没有发送者则出队协程会阻塞，同样入队操作时如果没有接收者则入队协程也会阻塞。这个特性导致了两个比较严重的问题。

第一个问题，当某个时刻有多个工作者协程都在执行 channel 出队操作时，最多只能有一个协程可以不被阻塞的拿到数据，其他协程将全部进入 waiting 阻塞状态。从上图中绿框部分可以看到，不同颜色每一个的 worker 协程都没有连续的执行，在短暂的执行之后变成了 waiting 阻塞状态。

而大部分协程被阻塞后，可能导致很多 Proc 上没有 runnable 的协程可供调度，此时 Proc 会触发 runtime.stealwork 从其他协程上“窃取”协程，而如果“窃取”也无法获得 runnable 的协程，Proc 会变成空闲状态（触发 proc stop 事件），并将把关联的线程变成自旋态（spnning），甚至会暂止线程（park）；等到后有续协程重新变为 runnable 状态后，空闲的 Proc 又需要重新变为忙碌状态，并将自旋态的线程恢复或者重新复始一个线程。大部分的协程频繁的阻塞和解除阻塞，会增加调度器的负担，导致调度延迟增加。

我们可以在 trace 中找到相关的证据。下图的 view trace 中，有很多 proc stop 的事件发生；同时查看上方的统计区域，可以看到蓝框中的 runnable 状态的协程越来越多但是都没有及时的得到调度；而绿框中的线程总数一直在变化，代表了一直有线程被开启和被暂停。

如果同时使用 pprof 进行 profile 分析，也可以在 svg 图中看到很多调度相关的节点，例如 runtime.stealwork和runtime.park_m 等等，感兴趣的读者可以自行实践一下。

第二个问题，当大量 worker 协程因为调度慢原因没有被执行时，主协程会因 channel 入队操作没有接收者而阻塞。此时主线程所在的 Proc 会“窃取”一个 runnable 的协程并执行。该协程处理完当前的像素点后，再次执行到 channel 出队，又变为阻塞，同时将主协程解除阻塞。主协程再一次执行到 channel 入队，又再一次变为阻塞，同时将 worker 协程再次解除阻塞。这就导致了上文中描述的主协程和某一个 worker 协程串行循环调度的情况发生。这个循环将一直持续到其它 Proc 上有 worker 协程执行为止。入队的阻塞也降低了程序效率。

总结一下，channel 没有缓冲区导致的调度延迟大大增加是程序执行慢的主要原因。打开 goroutine 分析，点开 worker 线程，可以看到每个工作协程的调度等待时间都是最长的（开启 trace 会放大调度延迟，但是即使关闭 trace，调度延迟仍然是一个最大的影响因素）。

2.4.3 优化二 buffer chan

优化的方向很明显，我们在 channel 在初始化时分配足够的缓冲区，优化代码如下：

func createWorkersBuffered(width, height int) image.Image {  m := image.NewGray(image.Rect(0, 0, width, height))   type px struct{ x, y int }  c := make(chan px, width*height) // 修改这里，缓冲区大小为width*height  var w sync.WaitGroup  for n := 0; n < numWorkers; n++ {    w.Add(1)    go func() {      for px := range c {        m.Set(px.x, px.y, pixel(px.x, px.y, width, height))      }      w.Done()    }()  }  for i := 0; i < width; i++ {    for j := 0; j < height; j++ {      c <- px{i, j}    }  }  close(c)  w.Wait()  return m}

优化后，程序执行时间为 1.899s，比上一步提升了很多。进入 view trace，相比上一步 view trace 要漂亮多了，9个处理器均匀的在调度执行我们的代码，goroutine、threads 统计区域里也是完美的绿色和紫色矩形，除了刚开始的350ms。

刚开始的 350ms 显然是有阻塞问题的，放大 trace 来看一看：

在上图中，我们看到所有的 worker 协程所在的 Proc 都发生了 proc stop 事件，再配合 worker 协程的调用栈是 runtime.chanrecv，我们可以得出结论：主协程处理入队太慢了。worker 协程出队操作时，channel 里一个数据都没有，所以全部阻塞了。等后续主协程慢慢入队后，worker 协程才能一个接一个的重新开始执行。

为什么这个现象只出现在 350ms 之前呢？猜测可能是因为 m.Set 设置的图片像素点多了之后，操作耗时增加，worker 协程操作速度比主协程慢了，所以不再出现了。

总结一下，入队速度慢于出队速度，导致 worker 协程出现阻塞。打开 Synchronization blocking 如下图，runtime.chanrecv2 阻塞了 90.12ms，这就是阻塞的带来的额外耗时。

2.4.4 优化三 buffer chan+减少入队/出队次数

为了解决上一步骤中前 350ms 的入队速度慢的问题，justforfunc-22 给出了一个巧妙的优化方案，将图片的一整列进行入队，而在出队任务中循环处理该列中的每一个像素点。优化后，入队次数等于图片的宽 w，大大减少了出入队次数。代码如下：

func createColWorkersBuffered(width, height int) image.Image {  m := image.NewGray(image.Rect(0, 0, width, height))  c := make(chan int, width) // 缓冲区容量为width，只需要入队width个任务  var w sync.WaitGroup  for n := 0; n < numWorkers; n++ {    w.Add(1)    go func() {      for i := range c {        // 循环处理每一个列的数据        for j := 0; j < height; j++ {          m.Set(i, j, pixel(i, j, width, height))        }      }      w.Done()    }()  }  // 只需要将每一列入队  for i := 0; i < width; i++ {    c <- i  }  close(c)  w.Wait()  return m}

优化后代码执行时间为 0.916s。打开 view trace，350ms 之前的阻塞问题不存在了，出现了完美的 trace。

至此我们完成了所有的优化操作。但是！眼尖的读者应该也注意到了，我们上一步分析中 chanrecv 导致的阻塞耗时是 90ms，但是优化后的实际耗时从 1.9s 降低到了 0.9s，性能为什么比上一步整整提升了一倍？

从阻塞方面来分析确实性能并不能提升1倍，但是别忘了 chanrecv 操作本身的 CPU 消耗，掏出 profile 再分析一下优化二中的 CPU 消耗情况如下图：

可以看到在优化二的代码中，chanrecv 函数内部调用的 runtime.procyield 函数，CPU 采样占比居然超过了 pixel，高达44%。procyield 用来实现 channel 内部的自旋锁，大量的 chanrecv 操作导致了大量的自旋锁等待；优化三中大大减少 chanrecv 的调用次数，这是程序性能能够翻倍的原因。至此我们完成了所有的优化分析。

03

总结

每一个 Golang 程序员，都应该学会 pprof 和 trace 工具的使用，掌握了这两个工具就足够应对绝大部分场景的 Golang 程序性能问题。

本文从使用方法、原理和实例三个方面对 pprof 和 trace 两个工具进行分析说明，其中有很多内容是笔者自己的理解总结，错误是难以避免的，如有错漏之处还请评论区留言指正~

作者:廖迪

来源-微信公众号:腾讯云开发者

出处
:https://mp.weixin.qq.com/s/8LdG26ZWxzoyAwymH2UmUg