概述
在一个庞大的程序中,有时候出现一些诡异的卡顿或者内存飙升,这时候光靠经验和认知去定位性能不佳的代码往往都不靠谱。这时候就需要用到pprof工具了。
在golang官方提供的性能测试工具中,分别提供了net/http/pprof和runtime/pprof两个包,两个包的使用场景分别如下:
runtime/pprof: 作用于一次性运行的代码块,如脚本程序等。
net/http/pprof: 是runtime/pprof的二次封装,主要作用于不可结束的代码块,如web应用。
pprof作用原理:
pprof是以profile.proto读取分析样本的集合,并生成文本和图形化报告输出。
profile.proto是一个 Protocol Buffer v3 的描述文件,描述了一组callstack和symbolization信息,作用是表示统计分析的一组采样的调用栈,是很常见的stacktrace配置文件格式。
支持输出格式:
- 生成报告
- 交互式终端输出
- web界面输出
Profiling类型:
CPU Profiling: CPU分析,按照一定的频率采集所监听的应用程序CPU(含寄存器)的使用情况,可确定应用程序在主动消耗CPU周期时花费时间的位置
Memory Profiling:内存分析,在应用程序进行堆分配时记录堆栈跟踪,用于监视当前和历史内存使用情况,以及检查内存泄漏
Block Profiling: 阻塞分析,记录goroutine阻塞等待同步(包括定时器通道)的位置
Mutex Profiling: 互斥锁分析,报告互斥锁的竞争情况
runtime/pprof
package main
import (
"os"
"runtime/pprof"
"sync"
)
func addData() {
data := make([]int, 0)
c := 0
for i := 0; i < 100000; i++ {
c = i + c
data = append(data, c)
}
}
func workOnce(wg *sync.WaitGroup) {
addData()
wg.Done()
}
func main() {
cpuf, err := os.OpenFile("cpu.pprof", os.O_WRONLY|os.O_TRUNC|os.O_CREATE, 0664)
if err != nil {
panic(err)
}
pprof.StartCPUProfile(cpuf)
defer cpuf.Close()
defer pprof.StopCPUProfile()
var wg sync.WaitGroup
wg.Add(100)
for i := 0; i < 100; i++ {
go workOnce(&wg)
}
wg.Wait()
memf, err := os.OpenFile("mem.pprof", os.O_WRONLY|os.O_TRUNC|os.O_CREATE, 0664)
if err != nil {
panic(err)
}
pprof.WriteHeapProfile(memf)
memf.Close()
}
编译通过后执行下面命令获得cpu使用情况
go tool pprof cpu.pprof
/***
得到结果
Type: cpu
Time: Mar 22, 2021 at 4:58pm (CST)
Duration: 201.01ms, Total samples = 230ms (114.42%)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof)
***/
使用top指令
(pprof) top
Showing nodes accounting for 230ms, 100% of 230ms total
Showing top 10 nodes out of 44
flat flat% sum% cum cum%
100ms 43.48% 43.48% 100ms 43.48% runtime.memmove
40ms 17.39% 60.87% 40ms 17.39% runtime.memclrNoHeapPointers
30ms 13.04% 73.91% 30ms 13.04% runtime.osyield
30ms 13.04% 86.96% 30ms 13.04% runtime.stdcall2
20ms 8.70% 95.65% 170ms 73.91% main.addData
10ms 4.35% 100% 10ms 4.35% runtime.(*pallocBits).summarize
0 0% 100% 170ms 73.91% main.workOnce
0 0% 100% 10ms 4.35% runtime.(*mcache).prepareForSweep
0 0% 100% 10ms 4.35% runtime.(*mcache).releaseAll
0 0% 100% 10ms 4.35% runtime.(*mcentral).uncacheSpan
Duration:程序执行时间。在本例中golang自动分配任务给多个核执行程序,总计耗时201.01ms,采样时间为230ms;也就是说假设有10核执行程序,平均每个核的采样23ms的数据。
(pprof) :命令行提示。表示当前在go tool的pprof工具命令行中,go tool还包括cgo、doc、pprof、test2json、trace等多种命令。
top:pprof的指令之一,显示pprof文件中的前10项数据,可以通过top 20等方式显示20行数据;当然pprof下有很多指令,例如list、pdf、eog等等。
flat/flat% :分别表示在当前层级cpu的占用时间和百分比。例如runtime.memmove在当前层级占用cpu时间100ms,占比本次采集时间的43.48%。
cum/cum% :分别表示截止到当前层级累计的cpu时间和占比。例如main.addData累计占用时间170ms,占本次采集时间的73.91%。
sum% :所有层级的cpu时间积累占用,从小到大一直积累到100%,即230ms。
(pprof) list main.addData
Total: 230ms
ROUTINE ======================== main.addData in D:\zone\project\iot\test\main.go
. . 9:func addData() {
. . 10: data := make([]int, 0)
. . 11: c := 0
. . 12: for i := 0; i < 100000; i++ {
. . 13: c = i + c
20ms 170ms 14: data = append(data, c)
. . 15: }
. . 16:}
. . 17:
. . 18:func workOnce(wg *sync.WaitGroup) {
. . 19: addData()
使用pprof的list指令,可以看到程序的14行占用了170ms,由此可以确定优化的方向。分析该行代码,可知slice的初始容量为0,导致循环中append时将发生多次扩容(slice的扩容方式说明:当容量不超过1024时,扩容为原来的2倍,超出则扩容为1.25倍)。
(pprof) web
failed to execute dot. Is Graphviz installed? Error: exec: "dot": executable file not found in %PATH%
如果想使用web输出,在未安装相关插件的情况下,会得到上面的提示。
下载对应版本安装后加入环境变量path即可
net/http/pprof
package main
import (
"net/http"
"time"
_ "net/http/pprof"
)
func addData() {
data := make([]int, 100000)
c := 1
for i := 0; i < 100000; i++ {
c = i + c
data[i] = c
}
}
func work() {
for ; ; time.Sleep(1 * time.Second) {
go addData()
}
}
func httpWork(w http.ResponseWriter, r *http.Request) {
addData()
}
func main() {
go work()
http.HandleFunc("/work", httpWork)
http.ListenAndServe(":8080", nil)
}
运行后打开http://localhost:8080/debug/pprof/
可以看到当前服务的运行情况
也可以使用下面的命令查看内存情况
go tool pprof main.exe http://localhost:8080/debug/pprof/heap
火焰图
安装
go get -v github.com/uber/go-torch
git clone http://github.com/brendangregg/FlameGraph.git
git clone http://github.com/adjust/go-wrk.git
FlameGraph是画图需要的工具,而wrk是模拟并发访问的工具。
将FlameGraph所在路径添加到环境变量中。
注意:windows下需要运行FlameGraph需要安装:perl
网址:
https://www.activestate.com/products/perl/ (慢)
https://strawberryperl.com/ (快)
windows下未必能成功使用,可使用(注1)方法查看
使用go-wrk命令模拟并发操作
4个线程|每个线程100个请求|共100000次请求
go-wrk -t=4 -c=100 -n=100000 http://localhost:8080/work
同时开启go-torch工具对http://localhost:8080采集30s信息,采集完毕后会生成svg文件,用浏览器打开就是火焰图。
go-torch -u http://localhost:8080 -t 30
亦可以直接使用生成的信息 (注1)
go tool pprof main -http=:6666 http://localhost:8080/debug/pprof/profile //生成信息打开网页查看
go tool pprof main http://localhost:8080/debug/pprof/heap //采集内存信息
go tool pprof main http://localhost:8080/debug/pprof/profile //采集cpu信息
trace
trace和pprof一样,也是go tool下的工具。
package main
import (
"os"
"runtime/trace"
"sync"
)
func addData() {
data := make([]int, 0)
c := 0
for i := 0; i < 100000; i++ {
c = i + c
data = append(data, c)
}
}
func workOnce(wg *sync.WaitGroup) {
addData()
wg.Done()
}
func main() {
tracef, err := os.OpenFile("trace.pprof", os.O_WRONLY|os.O_TRUNC|os.O_CREATE, 0664)
if err != nil {
panic(err)
}
trace.Start(tracef)
defer tracef.Close()
defer trace.Stop()
var wg sync.WaitGroup
wg.Add(100)
for i := 0; i < 100; i++ {
go workOnce(&wg)
}
wg.Wait()
}
编译执行
调用命令查看程序的执行情况
go tool trace -http=127.0.0.1:8080 trace.pprof