字节星球

Golang pprof 案例实战

2026/6/8 23:05:00Henry2 阅读0 点赞0 评论
#Golang

前段时间在 Golang 开发实习生面试时被问到你了解哪些 Debug 手段，回答的比较片面，只解释到了如何处理业务逻辑问题的一些方法，但其实性能问题也是会经常遇到的，不过这些也都是三板斧了，熟悉了就好。

在 Go 语言开发中，pprof 是官方提供的性能剖析工具。它能帮你动态地查看程序在运行时的 CPU 耗时、内存分配、协程状态等指标，是排查线上故障和性能优化的核心工具。

前置准备

小徐先生在去年发了一篇《Golang pprof 案例实战与原理解析》，里面基本涉及了 Golang pprof 的所有常见操作，基于以下项目进行实战：

https://github.com/wolfogre/go-pprof-practice

本文将使用 macOS 环境。

首先需要克隆该项目，然后安装 pprof 可视化工具 graphviz：

SH
brew install graphviz

项目实战

进入 go-pprof-practice 项目，可以发现 main.go 中对 pprof 包进行了匿名导入：

GO
import (
	"log"
	"net/http"

	// 启用 pprof 性能分析
	_ "net/http/pprof"
	"os"
	"runtime"
	"time"

	"github.com/wolfogre/go-pprof-practice/animal"
)

此外，使用 runtime 包启用 mutex 和 block 分析：

GO
// 启用 mutex 性能分析
runtime.SetMutexProfileFraction(1)
// 启用 block 性能分析
runtime.SetBlockProfileRate(1)

启动一个 http server，pprof handler 会自动挂载到该端口下：

GO
go func() {
	if err := http.ListenAndServe(":6060", nil); err != nil {
		log.Fatal(err)
	}
	os.Exit(0)
}()

注意到上述片段中 http.ListenAndServe 第二个参数为 nil，此时会默认使用 http.DefaultServeMux。

总结一下，要在项目中引入 pprof，需要完成：

  1. 匿名导入 pprof 包；
  2. 按需使用 runtime 包启用 mutex 或 block 性能分析（默认关闭）；
  3. 使用 goroutine 异步启用 http server，pprof 会向全局 http.DefaultServerMux 注册方法。

最后我们启动项目即可，然后打开 pprof 页面 (http://localhost:6060/debug/pprof/)：

GO
go run main.go

CPU 分析

CPU 分析是在一段时间内进行打点采样，通过查看采样点在各个函数栈中的分布比例，以此来反映各函数对 CPU 的占用情况。

在 pprof 页面中点击 profile，因为需要进行采样，所以等待一段时间后才可以得到 profile 文件。

SH
go tool pprof {YOUR PROFILE PATH}

输入上述命令后可以交互分析 profile 文件，比如这里输入 top 可以得到执行时长最长的一系列方法：

注：go tool pprof -http=:8082 {YOUR PROFILE PATH} 可以在对应端口开启图形界面。

TEXT
Showing nodes accounting for 12.49s, 99.92% of 12.50s total
Dropped 11 nodes (cum <= 0.06s)
      flat  flat%   sum%        cum   cum%
    12.41s 99.28% 99.28%     12.49s 99.92%  github.com/wolfogre/go-pprof-practice/animal/felidae/tiger.(*Tiger).Eat
     0.08s  0.64% 99.92%      0.08s  0.64%  runtime.asyncPreempt
         0     0% 99.92%     12.49s 99.92%  github.com/wolfogre/go-pprof-practice/animal/felidae/tiger.(*Tiger).Live
         0     0% 99.92%     12.50s   100%  main.main
         0     0% 99.92%     12.50s   100%  runtime.main
参数名称 含义 解释
flat Flat Time 该函数自身代码执行所消耗的时间（不包含它调用的其他子函数的运行时间）。
flat% Flat Percentage 该函数自身消耗的时间，占本次采样总时间的百分比。
sum% Sum Percentage 从第一行到当前行，所有 flat% 的​累加和​。
cum Cumulative Time ​累计时间​。该函数自身代码时间 + 它调用的所有子函数执行时间的总和。
cum% Cumulative Percentage 该函数的 cum 时间占本次采样总时间的百分比。

可以看到，Tiger 结构体在指针类型上实现的 Eat 方法占用了 12.41s 的时间，在本次采样周期内，几乎所有的 CPU 时间都来自于此方法。下面我们进到该方法源码中查看：

GO
func (t *Tiger) Eat() {
	log.Println(t.Name(), "eat")
	loop := 10000000000
	for i := 0; i < loop; i++ {
		// do nothing
	}
}

很遗憾，这个方法啥也没做，仅仅是通过 for 循环无限空转打满了 CPU，刚才还注意到 CPU 分析中还有一个 runtime.asyncPreempt 方法，这个方法其实是来自于非协作式抢占（当前 g 中被插入 asyncPreempt 函数），因为 Eat() 方法仅仅是空转，没有 goroutine 的执行栈空间扩张，所以无法执行到协作抢占的检查桩点。

具体见 GMP 原理。

Heap 分析

同样的，在 pprof 页面中点击 heap，可以得到如下信息：

TEXT
heap profile: 3: 2583691424 [252: 10199507584] @ heap/1048576
0: 0 [1: 8388608] @ 0x102f8164c 0x102daffa4
#	0x102f8164b	github.com/wolfogre/go-pprof-practice/animal/muridae/mouse.(*Mouse).Pee.func1+0x9b	/Users/henry/工程/go-pprof-practice/animal/muridae/mouse/mouse.go:46

0: 0 [1: 67108864] @ 0x102f818e4 0x102f81198 0x102f81a58 0x102d711a8 0x102daffa4
#	0x102f818e3	github.com/wolfogre/go-pprof-practice/animal/muridae/mouse.(*Mouse).Steal+0xf3	/Users/henry/工程/go-pprof-practice/animal/muridae/mouse/mouse.go:60
#	0x102f81197	github.com/wolfogre/go-pprof-practice/animal/muridae/mouse.(*Mouse).Live+0x47	/Users/henry/工程/go-pprof-practice/animal/muridae/mouse/mouse.go:25
#	0x102f81a57	main.main+0xb7									/Users/henry/工程/go-pprof-practice/main.go:46
#	0x102d711a7	runtime.main+0x287								/usr/local/go/src/runtime/proc.go:272

0: 0 [1: 240] @ 0x102d40a48 0x102d40a91 0x102e04ee8 0x102f80ec8 0x102f80e59 0x102f80ae8 0x102f81a58 0x102d711a8 0x102daffa4
#	0x102e04ee7	log.(*Logger).output+0xb7							/usr/local/go/src/log/log.go:219
#	0x102f80ec7	log.Println+0x87								/usr/local/go/src/log/log.go:405
#	0x102f80e58	github.com/wolfogre/go-pprof-practice/animal/felidae/tiger.(*Tiger).Pee+0x18	/Users/henry/工程/go-pprof-practice/animal/felidae/tiger/tiger.go:38
#	0x102f80ae7	github.com/wolfogre/go-pprof-practice/animal/felidae/tiger.(*Tiger).Live+0x37	/Users/henry/工程/go-pprof-practice/animal/felidae/tiger/tiger.go:16
#	0x102f81a57	main.main+0xb7									/Users/henry/工程/go-pprof-practice/main.go:46
#	0x102d711a7	runtime.main+0x287								/usr/local/go/src/runtime/proc.go:272

第一行数据为全局视角 heap profile: 3: 2583691424 [252: 10199507584] @ heap/1048576：

参数 代表指标 含义
3 inuse_objects ​当前存活的对象数​：整个程序里现在还没被 GC（垃圾回收）释放的对象只有 3 个。
2583691424 inuse_bytes ​当前存活的内存字节数​：约​2.4 GB​。说明当前程序内存开销极大。
252 alloc_objects ​历史累计分配的对象数​：从程序启动到现在，一共创建过 252 个对象（很多已被释放）。
10199507584 alloc_bytes ​历史累计分配的内存字节数​：约​9.5 GB​。说明程序历史上有过密集的内存分配行为。
1048576 MemProfileRate ​内存采样率​：这里是 1048576 字节（即​1 MB​）。代表 Go 运行时每分配 1 MB 内存，就会记录一次数据。

第二行以后为调用栈信息，以第二行为例 0: 0 [1: 67108864] @ 0x102f818e4 0x102f81198 0x102f81a58 0x102d711a8 0x102daffa4：

参数 对应数据 含义
左起第 1 个数字 0 当前通过该调用链存活的对象数。这里是 0，说明现在没被它占着。
左起第 2 个数字 0 当前通过该调用链存活的内存大小。这里是 0，说明​已经被 GC 回收干净了​。
中括号内第 1 个数字 1 历史累计在这条调用链上分配的对象个数。
中括号内第 2 个数字 67108864 历史累计在这条调用链上分配的字节数（67108864 字节 = 刚好​64 MB​）。
@符号后面的十六进制 0x102f818e4... 内存分配时该调用栈每一层在代码里的​内存物理地址​（PC 寄存器值）。
#开始的后续行 mouse.go:60等 把上面的十六进制地址位于哪个文件名、第几行代码、哪个函数。

就以第二行数据为例吧，来到源码：

GO
func (m *Mouse) Steal() {
	log.Println(m.Name(), "steal")
	max := constant.Gi
	for len(m.buffer)*constant.Mi < max {
		m.buffer = append(m.buffer, [constant.Mi]byte{})
	}
}

可以看到该方法在不断对 buffer 追加内容，导致了内存占用。

Block 分析

即阻塞分析，查看某个 goroutine 陷入 waiting 状态（被动阻塞，通常因 gopark 操作触发，比如因加锁、读 chan 条件不满足而陷入阻塞）的触发次数和持续时长。

pprof 默认不启用 block 分析，若要开启则需要进行如下设置：

GO
runtime.SetBlockProfileRate(1)

同样的，点击 pprof 页面中的 block 即可。

TEXT
--- contention:
cycles/second=999999999
2130193082709 22 @ 0x102d3d824 0x102d50c8c 0x102daffa4
#	0x102d3d823	runtime.chanrecv1+0x13						/usr/local/go/src/runtime/chan.go:489
#	0x102d50c8b	runtime.unique_runtime_registerUniqueMapCleanup.func1+0x3b	/usr/local/go/src/runtime/mgc.go:1732

422399418761 422 @ 0x102f802b8 0x102f8025d 0x102f7fbd8 0x102f81a58 0x102d711a8 0x102daffa4
#	0x102f802b7	sync.(*Mutex).Lock+0x187							/usr/local/go/src/sync/mutex.go:92
#	0x102f8025c	github.com/wolfogre/go-pprof-practice/animal/canidae/wolf.(*Wolf).Howl+0x12c	/Users/henry/工程/go-pprof-practice/animal/canidae/wolf/wolf.go:76
#	0x102f7fbd7	github.com/wolfogre/go-pprof-practice/animal/canidae/wolf.(*Wolf).Live+0x47	/Users/henry/工程/go-pprof-practice/animal/canidae/wolf/wolf.go:33
#	0x102f81a57	main.main+0xb7									/Users/henry/工程/go-pprof-practice/main.go:46
#	0x102d711a7	runtime.main+0x287								/usr/local/go/src/runtime/proc.go:272

421391046552 421 @ 0x102d3d824 0x102f80820 0x102f80448 0x102f81a58 0x102d711a8 0x102daffa4
#	0x102d3d823	runtime.chanrecv1+0x13								/usr/local/go/src/runtime/chan.go:489
#	0x102f8081f	github.com/wolfogre/go-pprof-practice/animal/felidae/cat.(*Cat).Pee+0x9f	/Users/henry/工程/go-pprof-practice/animal/felidae/cat/cat.go:39
#	0x102f80447	github.com/wolfogre/go-pprof-practice/animal/felidae/cat.(*Cat).Live+0x37	/Users/henry/工程/go-pprof-practice/animal/felidae/cat/cat.go:19
#	0x102f81a57	main.main+0xb7									/Users/henry/工程/go-pprof-practice/main.go:46
#	0x102d711a7	runtime.main+0x287								/usr/local/go/src/runtime/proc.go:272
参数/指标 含义
contention 代表当前是竞争/阻塞分析报告，专门记录因抢锁、读写通道（Channel）导致的挂起时间。
cycles/second ​每秒时钟周期数​。这里约等于 10 亿（1 GHz）。Go 运行时内部使用 CPU 时钟周期来记录阻塞时长，这个参数是换算成“秒”的比例尺（时钟周期数 ÷ cycles/second = 阻塞秒数）。

以数据 422399418761 422 @ 0x102f802b8 0x102f8025d 0x102f7fbd8 0x102f81a58 0x102d711a8 0x102daffa4 为例：

参数 对应数据 含义
左起第 1 个数字 422399418761 ​累计阻塞总时间​（单位：CPU 周期）。换算成人类时间：422399418761 ÷ 999999999 ≈ 422.4秒。也就是说，所有协程在这行代码上足足干等了 422 秒！
左起第 2 个数字 422 ​累计阻塞总次数​。说明在这个地方，一共有 422 次“准备往前冲，结果被拦下来挂起”的经历。
@符号后面的十六进制 0x102f802b8... 发生阻塞时，当前调用栈每一层代码在内存中的物理地址。
#开始的后续行 mutex.go:92/wolf.go:76 ​指出是哪一行代码在阻塞。这里显示是Wolf.Howl函数里在执行sync.(*Mutex).Lock时被卡住了。

同样来到源码：

GO
func (w *Wolf) Howl() {
	log.Println(w.Name(), "howl")

	m := &sync.Mutex{}
	m.Lock()

	// 子 goroutine 会解锁，所以主 goroutine 二次 Lock 不会导致死锁
	go func() {
		time.Sleep(time.Second)
		m.Unlock()
	}()

	// mutex 不可重入
	// 同一个 goroutine 对同一把锁重复加锁
	// 会阻塞等待锁被释放，如果这把锁一直没被 Unlock 那么会导致死锁
	m.Lock()
}

可以看到每次调用该方法都会被阻塞 1s，因为主 goroutine 会阻塞等待锁被 Unlock 后才能加锁。

Goroutine 分析

在 pprof 页面点击 goroutine 即可进行分析：

TEXT
goroutine profile: total 60
50 @ 0x102da7c18 0x102dabda0 0x102f803e8 0x102daffa4
#	0x102dabd9f	time.Sleep+0xdf										/usr/local/go/src/runtime/time.go:300
#	0x102f803e7	github.com/wolfogre/go-pprof-practice/animal/canidae/wolf.(*Wolf).Drink.func1+0x27	/Users/henry/工程/go-pprof-practice/animal/canidae/wolf/wolf.go:44

5 @ 0x102da7c18 0x102dabda0 0x102f815e0 0x102daffa4
#	0x102dabd9f	time.Sleep+0xdf										/usr/local/go/src/runtime/time.go:300
#	0x102f815df	github.com/wolfogre/go-pprof-practice/animal/muridae/mouse.(*Mouse).Pee.func1+0x2f	/Users/henry/工程/go-pprof-practice/animal/muridae/mouse/mouse.go:43

1 @ 0x102d66e0c 0x102da6a84 0x102f6bdb4 0x102f6bbd0 0x102f69168 0x102f7e054 0x102f7e968 0x102f47338 0x102f48f34 0x102f4ff5c 0x102f461bc 0x102daffa4
#	0x102f6bdb3	runtime/pprof.writeRuntimeProfile+0xb3	/usr/local/go/src/runtime/pprof/pprof.go:793
#	0x102f6bbcf	runtime/pprof.writeGoroutine+0x4f	/usr/local/go/src/runtime/pprof/pprof.go:752
#	0x102f69167	runtime/pprof.(*Profile).WriteTo+0x147	/usr/local/go/src/runtime/pprof/pprof.go:374
#	0x102f7e053	net/http/pprof.handler.ServeHTTP+0x443	/usr/local/go/src/net/http/pprof/pprof.go:272
#	0x102f7e967	net/http/pprof.Index+0xc7		/usr/local/go/src/net/http/pprof/pprof.go:388
#	0x102f47337	net/http.HandlerFunc.ServeHTTP+0x37	/usr/local/go/src/net/http/server.go:2220
#	0x102f48f33	net/http.(*ServeMux).ServeHTTP+0x1b3	/usr/local/go/src/net/http/server.go:2747
#	0x102f4ff5b	net/http.serverHandler.ServeHTTP+0xbb	/usr/local/go/src/net/http/server.go:3210
#	0x102f461bb	net/http.(*conn).serve+0x4fb		/usr/local/go/src/net/http/server.go:2092

1 @ 0x102d6fd4c 0x102db0b4c 0x102f80bb1 0x102f80ad0 0x102f81a58 0x102d711a8 0x102daffa4
#	0x102f80bb0	github.com/wolfogre/go-pprof-practice/animal/felidae/tiger.(*Tiger).Eat+0x90	/Users/henry/工程/go-pprof-practice/animal/felidae/tiger/tiger.go:24
#	0x102f80acf	github.com/wolfogre/go-pprof-practice/animal/felidae/tiger.(*Tiger).Live+0x1f	/Users/henry/工程/go-pprof-practice/animal/felidae/tiger/tiger.go:13
#	0x102f81a57	main.main+0xb7									/Users/henry/工程/go-pprof-practice/main.go:46
#	0x102d711a7	runtime.main+0x287								/usr/local/go/src/runtime/proc.go:272

第一行顾名思义就不解释了，从第二行开始 50 @ 0x102da7c18 0x102dabda0 0x102f803e8 0x102daffa4：

参数 含义
左起第一个数字50 ​相同状态的协程数量​。代表当前整个程序里，有50 个独立的 Goroutine 正卡在下面完全一模一样的调用栈里。
@符号后面的十六进制 这些协程当前执行到的代码在内存中的物理地址。
#开始的后续行 ​指出这 50 个协程目前停留在wolf.go:44行的time.Sleep内部（处于休眠阻塞状态）。

来到源码部分：

GO
func (w *Wolf) Drink() {
	log.Println(w.Name(), "drink")
	for i := 0; i < 10; i++ {
		go func() {
			time.Sleep(30 * time.Second)
		}()
	}
}
GO
func (m *Mouse) Pee() {
	log.Println(m.Name(), "pee")
	go func() {
		time.Sleep(time.Second * 30)
		max := constant.Gi
		for len(m.slowBuffer)*constant.Mi < max {
			m.slowBuffer = append(m.slowBuffer, [constant.Mi]byte{})
			time.Sleep(time.Millisecond * 500)
		}
	}()
}

很明显，上述两个方法均在创建一个/多个 goroutine，然后在每个 goroutine 中注入各种耗时任务，导致 goroutine 长时间阻塞。

至此，我们把 pprof 中常用的性能分析流程串联了一遍，实战 demo 到此为止。

字节星球 2026-06-08

评论区