go 程序性能调优 pprof 的使用 ，一
pprof是go语言内置 的分析性能，分析数据的工具，pprof开启后，每隔一段时间（10ms）就会收集下当前的堆栈信息，获取格格函数占用的CPU以及内存资源；最后通过对这些采样数据进行分析，形成一个性能分析报告。pprof用 profile.proto 读取分析样本的集合，并声称可视化报告，以帮助分析数据 （支持文本和图形报告）
profile.proto 是一个 Protobuf v3的描述文件，它描述了一组 callstack和 symbolization 信息，它的作用是统计分析一组采样的调用栈，配置文件格式是 stacktrace.
采样方式
- runtime/pprof 采集程序 （非server）指定区块的运行数据进行分析
- net/http/pprof 基于 http server 运行，并且可以采集运行时的数据进行分析 （其实net/http/pprof中只是使用runtime/pprof包来进行封装了一下，并在http端口上暴露出来）
- go test 通过运行测试用例，指定所需标识进行采集
使用模式
- Report Generation 报告生成
- InteractiveTerminal Use 交互式终端使用
- web interface web界面
可以做什么
- CPU profiling cpu分析，按照一定的频率采集所监听的应用程序cpu（含寄存器）的使用情况，确定应用程序在主动消耗cpu周期时花费时间的位置
- Memory Profiling 内存分析,在应用程序进行堆分配记录堆栈跟踪，用于监听当前和历史内存使用情况，以及检查内存泄漏。
- Block Profiling 阻塞分析，记录goroutine 阻塞等待同步（包含定时器通道）的位置，默认不开启，需要调用 runtime.SetBlockProfileRate 进行设置
- Mutex Profiling 互斥锁分析。报告互斥锁的竞争情况，默认不开启，需要调用 runtime.SetMutexProfileFraction 进行设置
简单例子
package main
import (
"log"
"net/http"
_ "net/http/pprof"
"time"
)
var datas []string
func main() {
go func() {
for {
log.Printf("len:%d",Add("gwyy"))
time.Sleep(time.Microsecond + 10)
}
}()
_ = http.ListenAndServe(":6060",nil)
}
func Add(str string) int {
data := []byte(str)
datas = append(datas,string(data))
return len(datas)
}
为什么要初始化 net/http/pprof
在前面例子中，在引用上对 net/http/pprof 包进行了默认的初始化，（也就是 _） ，如果没在对该包进行初始化，则无法调用pprof的相关接口，这是为什么呢，我们可以一起看看该包初始化方法：
func init() {
http.HandleFunc("/debug/pprof/", Index)
http.HandleFunc("/debug/pprof/cmdline", Cmdline)
http.HandleFunc("/debug/pprof/profile", Profile)
http.HandleFunc("/debug/pprof/symbol", Symbol)
http.HandleFunc("/debug/pprof/trace", Trace)
}
实际上，在初始化函数中， net/http/pprof 会对标准库中的 net/http 默认提供 DefaultServeMux 进行路由注册，源码如下
func HandleFunc(pattern string, handler func(ResponseWriter, *Request)) {
DefaultServeMux.HandleFunc(pattern, handler)
}
我们在例子中使用的 HTTP Server,也是标准库默认提供的，因此便可以注册进去。
在实际项目中 我们有独立的 ServeMux的，这时候只需要将PProf对应的路由注册进去即可
mux := http.NewServeMux()
mux.HandleFunc("/debug/pprof",pprof.Index)
mux.HandleFunc("/debug/pprof/cmdline"，pprof.cmdline)
mux.HandleFunc("/debug/pprof/profile", pprof.Profile)
mux.HandleFunc("/debug/pprof/symbol", pprof.Symbol)
mux.HandleFunc("/debug/pprof/trace", pprof.Trace)
好了 我们运行了上面的程序后，浏览器直接访问：
http://127.0.0.1:6060/debug/pprof/
如果在访问路径上加上 ?debug=1 则可以直接在浏览器中访问。
这个页面中有许多子页面，咱们继续深究下去，看看可以得到什么？
- profile（CPU Profiling）: $HOST/debug/pprof/profile，默认进行 30s 的 CPU Profiling，得到一个分析用的 profile 文件
- allocs 查看过去所有内存分配样本，访问路径为 /debug/pprof/allocs
- cmdline 当前程序命令行的完整调用路径
- block（Block Profiling）：$HOST/debug/pprof/block，查看导致阻塞同步的堆栈跟踪
- goroutine：$HOST/debug/pprof/goroutine，查看当前所有运行的 goroutines 堆栈跟踪
- heap（Memory Profiling）: $HOST/debug/pprof/heap，查看活动对象的内存分配情况
- mutex（Mutex Profiling）：$HOST/debug/pprof/mutex，查看导致互斥锁的竞争持有者的堆栈跟踪
- threadcreate：$HOST/debug/pprof/threadcreate，查看创建新OS线程的堆栈跟踪
一般在线上环境，为了网络安全，通常不会这么做。另外debug的访问方式是具有时效性的，在实际场景中，我们常常需要及时将当前状态下的 profile文件给存储下来，便于二次分析。
通过终端访问
第二种是通过命令行完整对正在运行的程序 pprof进行抓取和分析
//在执行命令后，需要等待 60s （可以调整seconds的值） PProf 会进行 cpu Profiling , 结束后将默认进入PProf 的命令行交互模式，查看或者导出分析结果。 // 如果是以TLS方式启动的HTTP Server 那么在调用需要改成 go tool pprof https+insecure://localhost:6060/debug/pprof/profile?seconds=60 go tool pprof http://localhost:6060/debug/pprof/profile?seconds=60 Fetching profile over HTTP from http://localhost:6060/debug/pprof/profile?seconds=60 Saved profile in C:\Users\admin\pprof\pprof.samples.cpu.001.pb.gz Type: cpu Time: Oct 12, 2020 at 11:40pm (CST) Duration: 1mins, Total samples = 13.53s (22.50%) Entering interactive mode (type "help" for commands, "o" for options) (pprof)
top命令
输入命令 top 10 查看对应资源开销 （例如 cpu就是执行耗时/开销 Memory 就是内存占用大小）排名前十的函数
(pprof) top 10
Showing nodes accounting for 10.82s, 79.97% of 13.53s total
Dropped 64 nodes (cum <= 0.07s)
Showing top 10 nodes out of 61
flat flat% sum% cum cum%
7.50s 55.43% 55.43% 7.56s 55.88% runtime.stdcall1
1.88s 13.90% 69.33% 1.90s 14.04% runtime.cgocall
0.31s 2.29% 71.62% 2.25s 16.63% runtime.timerproc
0.26s 1.92% 73.54% 0.26s 1.92% runtime.(*mcache).prepareForSweep
0.20s 1.48% 75.02% 0.53s 3.92% runtime.acquirep
0.18s 1.33% 76.35% 0.18s 1.33% runtime.casgstatus
0.15s 1.11% 77.46% 1.18s 8.72% runtime.exitsyscall
0.12s 0.89% 78.34% 0.52s 3.84% runtime.goroutineReady
0.11s 0.81% 79.16% 8.79s 64.97% runtime.systemstack
0.11s 0.81% 79.97% 0.11s 0.81% runtime.unlock
- flat：当前函数上运行耗时
- flat%：函数自身占用的 CPU 运行耗时总比例
- sum%：函数自身累积使用 CPU 总比例
- cum：当前函数及其调用函数的运行总耗时
- cum%：函数自身及其调用函数占 CPU 运行耗时总比例
- 最后一列为函数名称
大多数情况下，我们可以得出一个应用程序的运行情况，知道当前是什么函数，正在做什么事情，占用了多少资源等。
Heap Profiling
PS C:\Users\admin> go tool pprof http://localhost:6060/debug/pprof/heap Fetching profile over HTTP from http://localhost:6060/debug/pprof/heap Saved profile in C:\Users\admin\pprof\pprof.alloc_objects.alloc_space.inuse_objects.inuse_space.001.pb.gz Type: inuse_space Time: Oct 12, 2020 at 11:50pm (CST) 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)
这个命令能够很快的拉取到结果。不需要采样等待， 需要注意的是 Type 这个选项默认是 inuse_space，实际上，它可以对多种内存情况进行分析。常见的有：
inuse_space 分析应用常驻内存的占用情况
PS C:\Users\admin> go tool pprof -inuse_space http://localhost:6060/debug/pprof/heap
Fetching profile over HTTP from http://localhost:6060/debug/pprof/heap
Saved profile in C:\Users\admin\pprof\pprof.alloc_objects.alloc_space.inuse_objects.inuse_space.002.pb.gz
Type: inuse_space
Time: Oct 12, 2020 at 11:52pm (CST)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for 3.38MB, 100% of 3.38MB total
flat flat% sum% cum cum%
2.38MB 70.40% 70.40% 2.38MB 70.40% main.Add
1MB 29.60% 100% 3.38MB 100% main.main.func1
alloc_objects 分析应用程序的内存临时分配情况
PS C:\Users\admin> go tool pprof -alloc_objects http://localhost:6060/debug/pprof/heap
Fetching profile over HTTP from http://localhost:6060/debug/pprof/heap
Saved profile in C:\Users\admin\pprof\pprof.alloc_objects.alloc_space.inuse_objects.inuse_space.003.pb.gz
Type: alloc_objects
Time: Oct 12, 2020 at 11:53pm (CST)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for 98305, 100% of 98312 total
Dropped 14 nodes (cum <= 491)
flat flat% sum% cum cum%
98305 100% 100% 98311 100% main.main.func1
(pprof)
另外还有 inuse_objects 和 alloc_space 类别，分别对应查看每个函数的对象数量和分配的内存空间大小。
Goroutine Profiling
PS C:\Users\admin> go tool pprof http://localhost:6060/debug/pprof/goroutine Fetching profile over HTTP from http://localhost:6060/debug/pprof/goroutine Saved profile in C:\Users\admin\pprof\pprof.goroutine.001.pb.gz Type: goroutine Time: Oct 13, 2020 at 12:15am (CST) Entering interactive mode (type "help" for commands, "o" for options) (pprof)
在查看goroutine 时可以使用traces命令，这个命令会打印出对应的所有调用栈，以及指标信息，通过这个命令我们可以很方便的查看整改调用链路有什么，分别在哪里使用了多岁个goroutine,并且通过分析可以知道谁才是真正的调用方，输出结果如下：
(pprof) traces
Type: goroutine
Time: Oct 13, 2020 at 12:15am (CST)
-----------+-------------------------------------------------------
1 runtime.cgocall
syscall.Syscall9
syscall.WSARecv
internal/poll.(*FD).Read.func1
internal/poll.(*ioSrv).ExecIO
internal/poll.(*FD).Read
net.(*netFD).Read
net.(*conn).Read
net/http.(*connReader).backgroundRead
-----------+-------------------------------------------------------
1 runtime.gopark
runtime.netpollblock
internal/poll.runtime_pollWait
internal/poll.(*pollDesc).wait
internal/poll.(*ioSrv).ExecIO
internal/poll.(*FD).acceptOne
internal/poll.(*FD).Accept
net.(*netFD).accept
net.(*TCPListener).accept
net.(*TCPListener).Accept
net/http.(*Server).Serve
net/http.(*Server).ListenAndServe
net/http.ListenAndServe
main.main
runtime.main
-----------+-------------------------------------------------------
1 runtime.gopark
runtime.goparkunlock
time.Sleep
main.main.func1
-----------+-------------------------------------------------------
1 runtime/pprof.writeRuntimeProfile
runtime/pprof.writeGoroutine
runtime/pprof.(*Profile).WriteTo
net/http/pprof.handler.ServeHTTP
net/http/pprof.Index
net/http.HandlerFunc.ServeHTTP
net/http.(*ServeMux).ServeHTTP
net/http.serverHandler.ServeHTTP
net/http.(*conn).serve
-----------+-------------------------------------------------------
(pprof)
调用栈上的展示是自下而上的，也就是说 runtime.main方法调用了 main.main方法，而main.main方法又调用了 net/http.ListenAndServe 方法，排查起来比较方便。
每个调用栈信息都是用 ------- 分割，函数方法前面的是指标数据，例如，Gorutine Profiling 展示的是该方法占用的 goroutine的数量，而Heap Profiling 展示 的是占用内存大小。如图
PS C:\Users\admin> go tool pprof http://localhost:6060/debug/pprof/heap
Fetching profile over HTTP from http://localhost:6060/debug/pprof/heap
Saved profile in C:\Users\admin\pprof\pprof.alloc_objects.alloc_space.inuse_objects.inuse_space.005.pb.gz
Type: inuse_space
Time: Oct 13, 2020 at 12:24am (CST)
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) traces
Type: inuse_space
Time: Oct 13, 2020 at 12:24am (CST)
-----------+-------------------------------------------------------
bytes: 304kB
678.95kB main.Add
main.main.func1
-----------+-------------------------------------------------------
bytes: 192kB
0 main.Add
main.main.func1
-----------+-------------------------------------------------------
(pprof)
实际上，PProf中的所有功能都会根据 Profile的不同类型展示不同的对应结果
Mutex Profiling
一般来说，在调用 chan （通道）、sync.Mutex （同步锁）或者 time.Sleep() 时会造成阻塞，下面看个例子：
func init() {
runtime.SetMutexProfileFraction(1)
}
func main() {
var m sync.Mutex
var datas = make(map[int]struct{})
for i:=0;i<999;i++ {
go func(i int) {
m.Lock()
defer m.Unlock()
datas[i] = struct{}{}
}(i)
}
_ = http.ListenAndServe(":6060",nil)
}
需要特别注意的是 runtime.SetMutexProfileFraction(1) 语句，如果未来希望对互斥锁进行采集，则需要调用该方法设置采集频率，如果没有设置，或者设置数值小于0，则不进行采集
接下里调用 go tool pprof 进行分析：
PS C:\Users\admin> go tool pprof http://localhost:6060/debug/pprof/mutex Fetching profile over HTTP from http://localhost:6060/debug/pprof/mutex Saved profile in C:\Users\admin\pprof\pprof.contentions.delay.001.pb.gz Type: delay Time: Oct 13, 2020 at 12:31am (CST) Entering interactive mode (type "help" for commands, "o" for options) (pprof)
调用 top 命令，查看互斥锁排名
(pprof) top
Showing nodes accounting for 149.51us, 100% of 149.51us total
flat flat% sum% cum cum%
149.51us 100% 100% 149.51us 100% sync.(*Mutex).Unlock
0 0% 100% 149.51us 100% main.main.func1
(pprof)
调用 list命令 查看指定函数的代码情况 （包含特定的指标信息，如耗时）若函数名不明确，则默认对该函数名进行模糊匹配：
(pprof) list main
Total: 149.51us
ROUTINE ======================== main.main.func1 in D:\goroot\projects\_practice\go-learn\pprof\main.go
0 149.51us (flat, cum) 100% of Total
. . 16: for i:=0;i<999;i++ {
. . 17: go func(i int) {
. . 18: m.Lock()
. . 19: defer m.Unlock()
. . 20: datas[i] = struct{}{}
. 149.51us 21: }(i)
. . 22: }
. . 23: _ = http.ListenAndServe(":6060",nil)
. . 24:}
(pprof)
从输出分析中可以看到引起互斥锁函数，以及锁开销的位置。
Block Profiling
与 Mutex 的 runtime.SetMutexProfileFraction 语句类似，Block也需要调用 runtime.SetBlockProfileRate 语句进行设置，如果没有设置，或者设置数值小于0，则不进行采集
func init() {
runtime.SetMutexProfileFraction(1)
runtime.SetBlockProfileRate(1)
}
调用 top 命令，查看阻塞情况排名：
PS C:\Users\admin> go tool pprof http://localhost:6060/debug/pprof/block
Fetching profile over HTTP from http://localhost:6060/debug/pprof/block
Saved profile in C:\Users\admin\pprof\pprof.contentions.delay.004.pb.gz
Type: delay
Time: Oct 13, 2020 at 12:35am (CST)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for 83.75us, 100% of 83.75us total
flat flat% sum% cum cum%
83.75us 100% 100% 83.75us 100% sync.(*Cond).Wait
0 0% 100% 83.75us 100% net/http.(*conn).serve
0 0% 100% 83.75us 100% net/http.(*connReader).abortPendingRead
0 0% 100% 83.75us 100% net/http.(*response).finishRequest
(pprof)
也可以用 list 命令查看具体阻塞情况。调用方式和 Mutex Profiling 一样
- 上一篇 »Javascript性能调优【转】
- 下一篇 »php-fpm参数调优