go语言中的大杀器,对应用程序进行分析。

pprof

简介

采样方式

  • runtime/pprof 采集程序(非server) 指定区块对运行数据进行分析
  • net/http/pprof 基于http server运行,并且采集运行时对数据进行分析

使用模式:

  • web ui
  • 报告生成
  • 交互式终端

可以用来做什么?

  • cpu profiling cpu分析
  • memory profiling 内存分析。内存泄漏,内存使用情况。
  • block profiling goroutine 阻塞分析。 默认不开启 runtime.SetBlockProfileRate 进行开启
  • mutex profiling 互斥锁分析。报告互斥锁对竞争情况。默认不开启,需要调用 runtime.SetMutexProfileFraction 进行开启

demo

 1package main
 2
 3import (
 4	"log"
 5	"net/http"
 6	_ "net/http/pprof"
 7	"time"
 8)
 9
10var datas []string
11
12func main() {
13	go func() {
14		for {
15			log.Printf("len:%d", Add("crmoaodssdsd"))
16			time.Sleep(time.Millisecond * 10)
17		}
18	}()
19	_ = http.ListenAndServe("0.0.0.0:6060", nil)
20}
21
22func Add(str string) int {
23	datas = append(datas, str)
24	return len(datas)
25}

浏览器访问 http://localhost:6060/debug/pprof

cpu profiling

1go tool pprof http://localhost:6060/debug/pprof/profile\?seconds\=60
2go tool pprof https+insecure://localhost:6060/debug/pprof/profile\?seconds\=60
3
4# 输入top10, top20

Entering interactive mode (type “help” for commands, “o” for options) (pprof) top Showing nodes accounting for 1.06s, 96.36% of 1.10s total Showing top 10 nodes out of 52 flat flat% sum% cum cum% 0.30s 27.27% 27.27% 0.51s 46.36% runtime.kevent 0.28s 25.45% 52.73% 0.28s 25.45% runtime.libcCall 0.17s 15.45% 68.18% 0.17s 15.45% runtime.pthread_cond_signal 0.11s 10.00% 78.18% 0.18s 16.36% runtime.pthread_cond_wait 0.09s 8.18% 86.36% 0.10s 9.09% syscall.syscall 0.04s 3.64% 90.00% 0.18s 16.36% log.(*Logger).Output 0.03s 2.73% 92.73% 0.03s 2.73% runtime.write1 0.02s 1.82% 94.55% 0.02s 1.82% log.itoa (inline) 0.01s 0.91% 95.45% 0.11s 10.00% internal/poll.(*FD).Write 0.01s 0.91% 96.36% 0.03s 2.73% log.(*Logger).formatHeader

  • flat:当前函数占用CPU的耗时
  • flat::当前函数占用CPU的耗时百分比
  • sum%:函数占用CPU的耗时累计百分比
  • cum:当前函数加上调用当前函数的函数占用CPU的总耗时
  • cum%:当前函数加上调用当前函数的函数占用CPU的总耗时百分比
  • 最后一列:函数名称

heap profiling

1go tool pprof http://localhost:6060/debug/pprof/heap
2
3go tool pprof -inuse_space http://localhost:6060/debug/pprof/heap

常用类型

  • inuse_space 分析应用程序常住内存对占用情况
  • alloc_objects 分析应用程序对内存临时分配情况
  • inuse_objects 查看每个函数对对象数量
  • alloc_space 分配的内存空间大小

goroutine profiling

go tool pprof http://localhost:6060/debug/pprof/goroutine

输入traces 命令 ,打印出对应的所有调用栈,以及指标信息。

 1➜  fashnv git:(main) ✗ go tool pprof http://localhost:6060/debug/pprof/goroutine
 2Fetching profile over HTTP from http://localhost:6060/debug/pprof/goroutine
 3Saved profile in /Users/maozhongyu/pprof/pprof.goroutine.001.pb.gz
 4Type: goroutine
 5Time: May 26, 2023 at 2:48pm (CST)
 6Entering interactive mode (type "help" for commands, "o" for options)
 7(pprof) traces
 8Type: goroutine
 9Time: May 26, 2023 at 2:48pm (CST)
10-----------+-------------------------------------------------------
111   runtime.gopark
12runtime.netpollblock
13internal/poll.runtime_pollWait
14internal/poll.(*pollDesc).wait
15internal/poll.(*pollDesc).waitRead (inline)
16internal/poll.(*FD).Accept
17net.(*netFD).accept
18net.(*TCPListener).accept
19net.(*TCPListener).Accept
20net/http.(*Server).Serve
21net/http.(*Server).ListenAndServe
22net/http.ListenAndServe (inline)
23main.main
24runtime.main
25-----------+-------------------------------------------------------
261   runtime.gopark
27time.Sleep
28main.main.func1
29-----------+-------------------------------------------------------
301   runtime/pprof.runtime_goroutineProfileWithLabels
31runtime/pprof.writeRuntimeProfile
32runtime/pprof.writeGoroutine
33runtime/pprof.(*Profile).WriteTo
34net/http/pprof.handler.ServeHTTP
35net/http/pprof.Index
36net/http.HandlerFunc.ServeHTTP
37net/http.(*ServeMux).ServeHTTP
38net/http.serverHandler.ServeHTTP
39net/http.(*conn).serve
40-----------+-------------------------------------------------------

mutex profiling

查看引起互斥锁的函数,以及锁开销的位置

go tool pprof http://localhost:6060/debug/pprof/mutex

输入 top 输入 list main

runtime.SetMutexProfileFraction(1) 采集频率。 0表示不采集

 1package main
 2
 3import (
 4	"net/http"
 5	_ "net/http/pprof"
 6	"runtime"
 7	"sync"
 8)
 9
10func init() {
11	runtime.SetMutexProfileFraction(1)
12}
13
14func main() {
15	var m sync.Mutex
16	var datas = make(map[int]struct{})
17	for i := 0; i < 999; i++ {
18		go func(i int) {
19			m.Lock()
20			defer m.Unlock()
21			datas[i] = struct{}{}
22		}(i)
23	}
24	_ = http.ListenAndServe("0.0.0.0:6060", nil)
25}
 1  fashnv git:(main) ✗ go tool pprof http://localhost:6060/debug/pprof/mutex    
 2Fetching profile over HTTP from http://localhost:6060/debug/pprof/mutex
 3Saved profile in /Users/maozhongyu/pprof/pprof.contentions.delay.001.pb.gz
 4Type: delay
 5Time: May 26, 2023 at 3:09pm (CST)
 6Entering interactive mode (type "help" for commands, "o" for options)
 7(pprof) top
 8Showing nodes accounting for 1.30ms, 100% of 1.30ms total
 9      flat  flat%   sum%        cum   cum%
10    1.30ms   100%   100%     1.30ms   100%  sync.(*Mutex).Unlock
11         0     0%   100%     1.30ms   100%  main.main.func1
12(pprof) list
13command list requires an argument
14(pprof) list main
15Total: 1.30ms
16ROUTINE ======================== main.main.func1 in /Users/maozhongyu/code/fashnv/tmp.go
17         0     1.30ms (flat, cum)   100% of Total
18         .          .     17:   for i := 0; i < 999; i++ {
19         .          .     18:           go func(i int) {
20         .          .     19:                   m.Lock()
21         .          .     20:                   defer m.Unlock()
22         .          .     21:                   datas[i] = struct{}{}
23         .     1.30ms     22:           }(i)
24         .          .     23:   }
25         .          .     24:   _ = http.ListenAndServe("0.0.0.0:6060", nil)
26         .          .     25:}
27(pprof) %                                 
  • go语言编程之旅 (第6章)