Go应用性能剖析
Go SDK自带了Profiling库,可以用来识别程序的缺陷、性能瓶颈。内置以下剖析能力:
- CPU剖析(profile):报告CPU的使用情况,定位到热点(消耗CPU周期最多的)代码。默认情况下Go以100HZ的频率进行CPU采样
- 内存剖析(heap):报告堆内存当前分配(存活对象)情况。默认情况下每分配512KB进行内存采样。你可以使用URL参数gc,提示报告前进行GC
- 内存剖析(allocs):报告所有内存分配历史
- 线程创建(threadcreate):报告导致新OS线程创建的代码片段,分析阻塞式系统调用
- 协程剖析(goroutine):报告所有Goroutine的调用栈
- 阻塞剖析(block):报告Goroutine在哪些同步原语(包括定时器通道)上阻塞,显示调用栈。必须显式调用 runtime.SetBlockProfileRate来启用此特性。默认每发生一次阻塞均采样
- 互斥量剖析(mutex):报告锁竞争情况,显示持有互斥量的代码的调用栈。当你认为CPU英文锁竞争而没有被完全使用时,显式调用 runtime.SetMutexProfileFraction 来启用此特性
- 执行追踪(trace):追踪当前应用程序的执行栈
此外,Go还允许定制自己的剖析,在代码中手工报告性能分析数据。
要采集一个Go应用的剖析数据,有两种方式:
- 利用runtime/pprof包,进行剖析数据采集,并且在应用退出时将剖析数据写入到文件
- 利用net/http/pprof包,进行剖析数据采集,支持连接到HTTP服务实时分析
不管使用那种方式,都需要增加一些代码。
进行CPU剖析,添加如下代码:
1 2 3 4 5 6 7 8 9 10 11 |
f, err := os.Create(*cpuprofile) if err != nil { log.Fatal("could not create CPU profile: ", err) } defer f.Close() if err := pprof.StartCPUProfile(f); err != nil { log.Fatal("could not start CPU profile: ", err) } // 停止采样,并将剖析概要信息记录到文件 // 此方法实际上会将采样率设置为0 defer pprof.StopCPUProfile() |
进行内存剖析,添加如下代码:
1 2 3 4 5 6 7 8 9 10 11 12 13 14 |
// 设置采样率,默认每分配512*1024字节采样一次。如果设置为0则禁止采样,只能设置一次 runtime.MemProfileRate = *memProfileRate f, err := os.Create(*memprofile) if err != nil { log.Fatal("could not create memory profile: ", err) } defer f.Close() runtime.GC() // 执行GC,避免垃圾对象干扰 // 将剖析概要信息记录到文件 if err := pprof.WriteHeapProfile(f); err != nil { log.Fatal("could not write memory profile: ", err) } |
调用下面的方法启用此功能:
1 |
runtime.SetBlockProfileRate(5) |
参数5表示,每发生5次Goroutine阻塞事件则采样一次。默认值1。
下面的代码演示了如何将阻塞剖析概要信息记录到文件:
1 2 3 4 5 6 7 8 9 |
func stopBlockProfile() { if *blockProfile != "" && *blockProfileRate >= 0 { f, err := os.Create(*blockProfile) if err = pprof.Lookup("block").WriteTo(f, 0); err != nil { fmt.Fprintf(os.Stderr, "Can not write %s: %s", *blockProfile, err) } f.Close() } } |
从Go 1.8开始,支持采集处于竞态条件的互斥锁,调用下面的方法启用此功能:
1 |
runtime.SetMutexProfileFraction(5) |
此调用允许你捕获处于竞态条件的Goroutine的调用栈的一部分。
在进行测试时,不需要上述显式的调用,使用命令行参数即可:
1 |
go test -mutexprofile=mutex.out |
包net/http/pprof能够将实时剖析数据通过HTTP暴露为pprof可视化工具能识别的格式。
要使用此包,需要导入:
1 |
import _ "net/http/pprof" |
你需要为pprof提供一个HTTP服务器:
1 2 3 |
go func() { log.Println(http.ListenAndServe("localhost:6060", nil)) }() |
如果你不使用 http.DefaultServeMux(如上代码),则需要手工注册路由规则:
1 2 3 4 5 |
r.HandleFunc("/debug/pprof/", pprof.Index) r.HandleFunc("/debug/pprof/cmdline", pprof.Cmdline) r.HandleFunc("/debug/pprof/profile", pprof.Profile) r.HandleFunc("/debug/pprof/symbol", pprof.Symbol) r.HandleFunc("/debug/pprof/trace", pprof.Trace) |
要连接到HTTP服务进行实时分析,使用如下命令:
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 |
# 设置剖析摘要信息存放目录 export PPROF_TMPDIR=/tmp/pprof # 获取堆快照 go tool pprof http://localhost:6060/debug/pprof/heap # 获取从启动依赖的内存分配历史 go tool pprof http://localhost:6060/debug/pprof/allocs # 30秒CPU分析,需要等待30秒才能看到命令提示符 go tool pprof http://localhost:6060/debug/pprof/profile?seconds=30 # Goroutine阻塞分析 go tool pprof http://localhost:6060/debug/pprof/block # 收集5秒的执行调用栈 wget http://localhost:6060/debug/pprof/trace?seconds=5 # 互斥锁分析 go tool pprof http://localhost:6060/debug/pprof/mutex |
要查看所有可用的剖析, 访问 http://localhost:6060/debug/pprof/ 。
1 2 3 |
# 可执行文件路径 # 保存的剖析摘要文件 go tool pprof bin/Temp mutex.mprof |
通过工具go tool pprof打开URL或文件后,会显示一个 (pprof)提示符,你可以使用以下命令:
命令 | 参数 | 说明 | ||
gv | [focus] |
将当前概要文件以图形化和层次化的形式显示出来。当没有任何参数时,在概要文件中的所有采样都会被显示 如果指定了focus参数,则只显示调用栈中有名称与此参数相匹配的函数或方法的采样。 focus参数应该是一个正则表达式 需要dot、gv命令,执行下面的命令安装:
|
||
web | [focus] | 与gv命令类似,web命令也会用图形化的方式来显示概要文件。但不同的是,web命令是在一个Web浏览器中显示它 | ||
list | [routine_regexp] | 列出名称与参数 routine_regexp代表的正则表达式相匹配的函数或方法的相关源代码 | ||
weblist | [routine_regexp] | 在Web浏览器中显示与list命令的输出相同的内容。它与list命令相比的优势是,在我们点击某行源码时还可以显示相应的汇编代码 | ||
top[N] | [--cum] |
top命令可以以本地采样计数为顺序列出函数或方法及相关信息 如果存在标记 --cum则以累积采样计数为顺序 默认情况下top命令会列出前10项内容。但是如果在top命令后面紧跟一个数字,那么其列出的项数就会与这个数字相同 |
||
traces | 打印所有采集的样本 | |||
disasm | [routine_regexp] | 显示名称与参数 routine_regexp相匹配的函数或方法的反汇编代码。并且,在显示的内容中还会标注有相应的采样计数 | ||
callgrind | [filename] | 利用callgrind工具生成统计文件。在这个文件中,说明了程序中函数的调用情况。如果未指定 filename参数,则直接调用kcachegrind工具。kcachegrind可以以可视化的方式查看callgrind工具生成的统计文件 | ||
help | 显示帮助 | |||
quit | 退出 |
调用pprof时,可以选择启动一个Web UI,指定-http选项即可:
1 |
go tool pprof -http=:8080 http://localhost:6060/debug/pprof/heap |
你可以访问Web UI来查看烈焰图等高级图表。
这里使用一段CPU密集型代码来学习CPU剖析:
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 |
package main import ( "net/http" _ "net/http/pprof" "sync" "time" ) var wg sync.WaitGroup func main() { go func() { http.ListenAndServe("localhost:6060", nil) }() wg.Add(1) go calculte(wg) wg.Wait() } func calculte(wg sync.WaitGroup) { for i := 0; i < 100000000; i++ { time.Sleep(time.Millisecond) cpuBound(i) } wg.Done() } func cpuBound(i int) { factorial(i) sieveOfEratosthenes(i) } func sieveOfEratosthenes(N int) (primes []int) { b := make([]bool, N) for i := 2; i < N; i++ { if b[i] == true { continue } primes = append(primes, i) for k := i * i; k < N; k += i { b[k] = true } } return } func factorial(x int) int { if x == 0 { return 1 } return x * factorial(x-1) } |
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 |
(pprof) top10 Showing nodes accounting for 24630ms, 83.75% of 29410ms total Dropped 107 nodes (cum <= 147.05ms) Showing top 10 nodes out of 31 flat flat% sum% cum cum% 4720ms 16.05% 16.05% 4990ms 16.97% main.sieveOfEratosthenes 4510ms 15.33% 31.38% 19440ms 66.10% runtime.gentraceback 3550ms 12.07% 43.45% 23490ms 79.87% main.factorial 2810ms 9.55% 53.01% 8460ms 28.77% runtime.getStackMap 2130ms 7.24% 60.25% 3220ms 10.95% runtime.funcdata 2070ms 7.04% 67.29% 2630ms 8.94% runtime.findfunc 1540ms 5.24% 72.53% 1740ms 5.92% runtime.pcvalue 1400ms 4.76% 77.29% 1400ms 4.76% runtime.add 1000ms 3.40% 80.69% 9610ms 32.68% runtime.adjustframe 900ms 3.06% 83.75% 1070ms 3.64% runtime.pcdatastart ... 0 0% 97.18% 5.01s 17.04% main.calculte 0 0% 97.18% 4.99s 16.97% main.cpuBound |
使用top命令可以直接看到消耗CPU最多的方法,各列含义如下:
- flat:在采样期间,此函数正在执行的次数 * 10ms。 可以用来粗略估计函数的运行耗时,不包含当前函数调用其它函数并等待返回的时间
- flat%:flat / 总采样时间。估算函数运行耗CPU占比
- sum%:当前行加上前面所有行的flat%总和
- cum:在采样期间,此函数出现在调用栈的次数*10ms。和flat相比,该指标包含子函数耗时
- cum%:cum/总采样时间
要以cum降序输出,执行 top10 -cum。
上面的例子中,factorial是自递归调用,其cum值不知道为何比父例程cpuBound还要大得多,不符合只觉。
通过top定位到耗时函数后,可以进一步使用该命令,分析函数每一行代码消耗多少时间。
函数cpuBound调用两个子例程factorial、sieveOfEratosthenes,它们都是非常耗时的:
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 |
(pprof) list cpuBound Total: 29.41s ROUTINE ======================== main.cpuBound in /home/alex/Go/workspaces/default/src/git.gmem.cc/alex/go-study/golang/profile.go 0 4.99s (flat, cum) 16.97% of Total . . 27: wg.Done() . . 28:} . . 29: . . 30:func cpuBound(i int) { . . 31: factorial(i) . 4.99s 32: sieveOfEratosthenes(i) . . 33:} . . 34:func sieveOfEratosthenes(N int) (primes []int) { . . 35: b := make([]bool, N) . . 36: for i := 2; i < N; i++ { . . 37: if b[i] == true { |
从上面的输出可以看到, cpuBound的全部时间均消耗在对sieveOfEratosthenes的调用上,而factorial这个自递归调用的耗时无法体现。
使用此命令可以生成一个SVG图片,清晰的显示调用关系图。图中越红的节点消耗CPU越多:
从图中可以看到factorial函数引发的调用链最耗时,calculte其次。由于factorial是自递归调用,calculte到factorial的调用关系没有识别出来。
这里使用一段内存消耗型代码来学习CPU剖析:
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 |
package main import ( "net/http" _ "net/http/pprof" "time" ) type pkg struct { blob } type blob struct { data [1024]int } func main() { go func() { http.ListenAndServe("localhost:6060", nil) }() consume() } func consume() { for i := 0; i < 100000000; i++ { time.Sleep(time.Millisecond * 1) b100 := createBlob(100) println(b100) p100 := createPkg(100) println(p100) } } func createPkg(i int) interface{} { ps := make([]pkg, 0) for x := 0; x < i; x++ { ps = append(ps, pkg{}) } return ps } func createBlob(i int) []blob { bs := make([]blob, 0) for x := 0; x < i; x++ { bs = append(bs, blob{}) } return bs } |
执行下面的命令,可以获取一个堆快照,快照中包含所有存活对象:
1 |
go tool pprof http://localhost:6060/debug/pprof/heap |
使用top命令可以看到哪些方法分配了最多的内存:
1 2 3 4 5 6 7 |
(pprof) top Showing nodes accounting for 1.95MB, 100% of 1.95MB total flat flat% sum% cum cum% 1.95MB 100% 100% 1.95MB 100% main.createPkg 0 0% 100% 1.95MB 100% main.consume 0 0% 100% 1.95MB 100% main.main 0 0% 100% 1.95MB 100% runtime.main |
可以看到,在本次快照中,createPkg分配的内存最多。
使用list命令,可以进一步定位到createPkg的哪一行代码分配了这些内存:
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 |
(pprof) list createPkg Total: 1.95MB ROUTINE ======================== main.createPkg in /home/alex/Go/workspaces/default/src/git.gmem.cc/alex/go-study/golang/heap.go 1.95MB 1.95MB (flat, cum) 100% of Total . . 31:} . . 32: . . 33:func createPkg(i int) interface{} { . . 34: ps := make([]pkg, 0) . . 35: for x := 0; x < i; x++ { 1.95MB 1.95MB 36: ps = append(ps, pkg{}) . . 37: } . . 38: return ps . . 39:} . . 40: . . 41:func createBlob(i int) []blob { |
可以看到,全部内存均由于代码 ps = append(ps, pkg{})分配。
类似的,使用web命令可以展示出内存分配的调用栈。
执行下面的命令,可以获取程序运行依赖,所有内存分配的历史:
1 |
go tool pprof http://localhost:6060/debug/pprof/allocs |
用top命令看,分配内存的量明显比heap剖析大的多:
1 2 3 4 5 6 7 8 9 |
(pprof) top Showing nodes accounting for 5.69TB, 100% of 5.69TB total Dropped 33 nodes (cum <= 0.03TB) flat flat% sum% cum cum% 2.85TB 50.00% 50.00% 2.85TB 50.00% main.createPkg 2.85TB 50.00% 100% 2.85TB 50.00% main.createBlob 0 0% 100% 5.69TB 100% main.consume 0 0% 100% 5.69TB 100% main.main 0 0% 100% 5.69TB 100% runtime.main |
使用web命令,可以展示出内存分配的调用栈:
所谓内存泄漏,意味着占用的内存一直无法释放。在pprof中,泄漏的内存一直存在于heap剖析的输出中,并且随着运行时间的增加,迟早会出现在top命令的输出中。
这里使用一段内存消耗型代码来学习阻塞剖析:
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 |
package main import ( "net/http" _ "net/http/pprof" "runtime" "sync" "time" ) var mutex sync.Mutex func main() { // rate = 1:统计所有的 block event, // rate <=0:关闭block profiling // rate > 1:阻塞时间t>rate那秒的event 一定会被统计,小于rate则有t/rate 的几率被统计 runtime.SetBlockProfileRate(1 * 1000 * 1000) go func() { http.ListenAndServe("localhost:6060", nil) }() var wg sync.WaitGroup for ; ; { wg.Add(1) mutex.Lock() go worker(&wg) time.Sleep(2 * time.Millisecond) mutex.Unlock() wg.Wait() } } func worker(wg *sync.WaitGroup) { defer wg.Done() mutex.Lock() time.Sleep(1 * time.Millisecond) mutex.Unlock() } |
执行下面的命令,可以获取所有录制的阻塞事件:
1 |
go tool pprof http://localhost:6060/debug/pprof/block |
top显示的是阻塞时间最长的方法:
1 2 3 4 5 6 7 8 9 10 |
(pprof) top Showing nodes accounting for 2.99mins, 100% of 2.99mins total Dropped 9 nodes (cum <= 0.01mins) flat flat% sum% cum cum% 1.95mins 65.37% 65.37% 1.95mins 65.37% sync.(*Mutex).Lock 1.03mins 34.63% 100% 1.03mins 34.63% sync.(*WaitGroup).Wait 0 0% 100% 1.03mins 34.63% main.main 0 0% 100% 1.95mins 65.37% main.worker 0 0% 100% 1.03mins 34.63% runtime.main (pprof) |
这里可以看到阻塞时间都消耗在互斥量的Lock和等待组的Wait方法上。
使用top无法感知什么代码导致了阻塞,你可以使用web,展示导致阻塞的调用栈。
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 |
package main import ( "math/rand" "net/http" _ "net/http/pprof" "runtime" "sync" "time" ) var mutex sync.Mutex func main() { // rate = 0:关闭 mutex prof // rate = 1:记录所有的 mutex event // rate > 1:随机记录 1/rate 的 mutex event runtime.SetMutexProfileFraction(1) go func() { http.ListenAndServe("localhost:6060", nil) }() go worker() go worker() var wg sync.WaitGroup wg.Add(1) wg.Wait() } func worker() { for ; ; { mutex.Lock() time.Sleep(time.Duration(rand.New(rand.NewSource(time.Now().Unix())).Intn(10)) * time.Second) mutex.Unlock() } } |
执行下面的命令,可以获取所有录制的互斥锁事件:
1 |
go tool pprof http://localhost:6060/debug/pprof/mutex |
使用top命令,可以看到锁竞争的位置。
可以执行:
1 |
curl -s http://localhost:6060/debug/pprof/goroutine?debug=2 |
来获取所有Goroutine的状态、调用栈。
如果Goroutine因为读写通道而阻塞,可以看到类似下面的输出:
1 2 3 |
goroutine 1 [chan receive, 7 minutes]: main.main() /home/alex/Go/workspaces/default/src/git.gmem.cc/alex/go-study/golang/goroutine.go:21 +0x71 |
在这个例子中,主协程已经等待达7分钟。这种在通道上的等待是无法通过阻塞分析看到的。
如果Goroutine正在等待(包括网络)IO完成,可以看到类似下面的输出:
1 2 |
goroutine 436 [IO wait]: internal/poll.runtime_pollWait(0x7ff9056e2dd8, 0x72, 0xb) |
Go允许开发人员扩展自己的Profile,来跟踪任何资源的创建/释放。
假设你负责编写某个Blob服务器的客户端库,用户的需求是随时了解某个客户端实例打开了多少Blob。 你可以使用定制剖析满足此需求:
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 |
package blobstore import "runtime/pprof" // 定制剖析 var openBlobProfile = pprof.NewProfile("blobstore.Open") // 打开一个Blob,所有Blob不再使用之后需要关闭 func Open(name string) (*Blob, error) { blob := &Blob{name: name} // ... 在这里加载并初始化Blob // 此方法将当前调用栈加入到剖析中,并且将此栈关联到对象blob // 信息存放在内部的一个map中,以blob为key,这意味着: // 1.blob必须适合用作key,而且它 // 2.在显示调用Remove之前不会被GC // 如果剖析已经包含blob的调用栈,则panic // 2 表示跳过的栈帧数量,对于调用栈 // Add // called from rpc.NewClient // called from mypkg.Run // called from main.main // skip=0 从rpc.NewClient中的Add调用处开始记录 // skip=1 从mypkg.Run的NewClient调用处开始记录 openBlobProfile.Add(blob, 2) return blob, nil } // 关闭Blob并释放底层资源 func (b *Blob) Close() error { // 从Profile中移除对象b关联的调用栈 openBlobProfile.Remove(b) return nil } |
如果此客户端库的使用者,想知道自己的程序当前打开了多少Blob,在什么地方(代码位置)打开的,可以这样编写:
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 |
package main import ( "fmt" "math/rand" "net/http" _ "net/http/pprof" "time" "myproject.org/blobstore" ) func main() { for i := 0; i < 1000; i++ { name := fmt.Sprintf("task-blob-%d", i) go func() { // 打开Blob,会导致剖析记录数据 b, err := blobstore.Open(name) if err != nil { } defer b.Close() }() } http.ListenAndServe("localhost:6060", nil) } |
程序运行期间,使用如下命令即可看到打开了哪些Blob:
1 2 3 4 5 6 |
go tool pprof http://localhost:6060/debug/pprof/blobstore.Open (pprof) top Showing nodes accounting for 800, 100% of 800 total flat flat% sum% cum cum% 800 100% 100% 800 100% main.main.func1 /Users/jbd/src/hello/main.go |
关注你的博客不久,但是浏览频率很高,每看一回,都感觉能学到不少东西,感觉博主很踏实、希望能跟着博主的步伐,越走越远!
共同进步:D
嗯嗯,加油