golang pprof

一：背景

當正在執行的golang程式消耗預期之外的記憶體和時間，我們這個時候就需要去弄明白，到底是是我們的程式碼哪個地方消耗了這些記憶體及相應時間。但此時編譯好的golang程式對我們而言是黑盒，如果去分析具體的記憶體及時間使用情況？這個時候我們可以去了解和使用pprof來分析golang程式的記憶體使用。

 

二：實戰

2.1.環境搭建

下載安裝golang，需要進到pod容器中（或者也可以將這些打到基礎映象中）

$ wget https://go.dev/dl/go1.15.15.linux-amd64.tar.gz    
$ tar -C /usr/local -xzf go1.4.linux-amd64.tar.gz
# 新增到環境變數中
$ export PATH=$PATH:/usr/local/go/bin

安裝生成svg圖的依賴

$ yum install graphviz -y

2.2.修改和新增業務程式碼

在相關業務服務程式碼main中新增以下程式碼

// pprof 的init函式會將pprof裡的一些handler註冊到http.DefaultServeMux上
// 當不使用http.DefaultServeMux來提供http api時，可以查閱其init函式，自己註冊handler
import _ "net/http/pprof"

go func() {
    http.ListenAndServe("0.0.0.0:9090", nil)
}()

修改完成後編譯二進位制，並執行對應二進位制。 

2.3.通過 Web 介面檢視

檢視當前總覽：訪問 http://127.0.0.1:9090/debug/pprof/，可以檢視到如下圖相關資訊。

 

 

可以直接點選上面的連結，進入子頁面，檢視相關的彙總資訊。

 

 

2.4.go tool分析法

2.4.1.記憶體分析

我們可以採用go tool pprof -inuse_space http://127.0.0.1:9090/debug/pprof/heap命令連線到程式中 檢視正在使用的一些記憶體相關資訊，此時我們得到一個可以互動的命令列。

我們可以看資料top10來檢視正在使用的物件較多的10個函式入口。通常用來檢測有沒有不符合預期的記憶體 物件引用。

# go tool pprof -inuse_space http://127.0.0.1:9090/debug/pprof/heap
Fetching profile over HTTP from http://127.0.0.1:9090/debug/pprof/heap
Saved profile in /root/pprof/pprof.yaohong.alloc_objects.alloc_space.inuse_objects.inuse_space.003.pb.gz
File: test_exporter
Type: inuse_space
Time: Dec 15, 2021 at 1:05pm (CST)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top10
Showing nodes accounting for 512.69kB, 100% of 512.69kB total
Showing top 10 nodes out of 12
      flat  flat%   sum%        cum   cum%
  512.69kB   100%   100%   512.69kB   100%  crypto/x509.parseCertificate
         0     0%   100%   512.69kB   100%  crypto/x509.(*CertPool).AppendCertsFromPEM
         0     0%   100%   512.69kB   100%  crypto/x509.ParseCertificate
         0     0%   100%   512.69kB   100%  crypto/x509.SystemCertPool
         0     0%   100%   512.69kB   100%  crypto/x509.initSystemRoots
         0     0%   100%   512.69kB   100%  crypto/x509.loadSystemRoots
         0     0%   100%   512.69kB   100%  crypto/x509.systemRootsPool (inline)
         0     0%   100%   512.69kB   100%  harbor_exporter/collector.New
         0     0%   100%   512.69kB   100%  main.main
         0     0%   100%   512.69kB   100%  runtime.main
(pprof) 

然後我們在用go tool pprof -alloc_space http://127.0.0.1:9090/debug/pprof/heap命令連結程式來檢視 記憶體物件分配的相關情況。然後輸入top來檢視累積分配記憶體較多的一些函式呼叫:

# go tool pprof -alloc_space http://127.0.0.1:9090/debug/pprof/heap
Fetching profile over HTTP from http://127.0.0.1:9090/debug/pprof/heap
Saved profile in /root/pprof/pprof.yaohong.alloc_objects.alloc_space.inuse_objects.inuse_space.004.pb.gz
File: test_exporter
Type: alloc_space
Time: Dec 15, 2021 at 1:08pm (CST)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top
Showing nodes accounting for 29601.22kB, 86.52% of 34211.94kB total
Showing top 10 nodes out of 95
      flat  flat%   sum%        cum   cum%
 9272.51kB 27.10% 27.10%  9272.51kB 27.10%  os.(*File).readdirnames
 3610.34kB 10.55% 37.66%  3610.34kB 10.55%  compress/flate.NewWriter
 3587.75kB 10.49% 48.14%  3587.75kB 10.49%  bytes.makeSlice
 3584.50kB 10.48% 58.62%  5120.55kB 14.97%  os.Readlink
 2560.13kB  7.48% 66.10%  2560.13kB  7.48%  strings.(*Builder).grow (inline)
 2368.55kB  6.92% 73.03%  2368.55kB  6.92%  runtime/pprof.StartCPUProfile
 1542.01kB  4.51% 77.53%  1542.01kB  4.51%  bufio.NewReaderSize (inline)
 1536.05kB  4.49% 82.02%  1536.05kB  4.49%  syscall.ByteSliceFromString
 1024.38kB  2.99% 85.02%  5126.52kB 14.98%  github.com/shirou/gopsutil/internal/common.ReadLinesOffsetN
     515kB  1.51% 86.52%      515kB  1.51%  crypto/x509.(*CertPool).AddCert
(pprof) 

我們可以根據如上記憶體分配情況去review程式碼，如何減少這些相關的呼叫，或者優化相關程式碼邏輯。

當我們不明確這些呼叫時是被哪些函式引起的時，我們可以輸入top -cum來查詢，-cum的意思就是，將函式呼叫關係 中的資料進行累積，比如A函式呼叫的B函式，則B函式中的記憶體分配量也會累積到A上面，這樣就可以很容易的找出呼叫鏈。

(pprof) top20 -cum
Showing nodes accounting for 14393.43kB, 42.07% of 34211.94kB total
Showing top 20 nodes out of 95
      flat  flat%   sum%        cum   cum%
         0     0%     0% 25669.06kB 75.03%  harbor_exporter/collector.(*Exporter).scrape.func1
         0     0%     0% 25669.06kB 75.03%  harbor_exporter/collector.ScrapeSystemSocketInfo.Scrape
         0     0%     0% 14905.07kB 43.57%  github.com/shirou/gopsutil/process.(*Process).OpenFiles (inline)
         0     0%     0% 14905.07kB 43.57%  github.com/shirou/gopsutil/process.(*Process).OpenFilesWithContext
         0     0%     0% 14905.07kB 43.57%  github.com/shirou/gopsutil/process.(*Process).fillFromfdWithContext
         0     0%     0%  9272.51kB 27.10%  github.com/shirou/gopsutil/process.(*Process).fillFromfdListWithContext
         0     0%     0%  9272.51kB 27.10%  os.(*File).Readdirnames (inline)
 9272.51kB 27.10% 27.10%  9272.51kB 27.10%  os.(*File).readdirnames
         0     0% 27.10%  8713.24kB 25.47%  github.com/shirou/gopsutil/process.(*Process).CreateTimeWithContext
         0     0% 27.10%  8713.24kB 25.47%  github.com/shirou/gopsutil/process.(*Process).createTimeWithContext
         0     0% 27.10%  8713.24kB 25.47%  github.com/shirou/gopsutil/process.(*Process).fillFromStatWithContext
  512.05kB  1.50% 28.60%  8713.24kB 25.47%  github.com/shirou/gopsutil/process.(*Process).fillFromTIDStatWithContext
         0     0% 28.60%  8713.24kB 25.47%  github.com/shirou/gopsutil/process.NewProcessWithContext
         0     0% 28.60%  8713.24kB 25.47%  github.com/shirou/gopsutil/process.Processes (inline)
         0     0% 28.60%  8713.24kB 25.47%  github.com/shirou/gopsutil/process.ProcessesWithContext
         0     0% 28.60%  5126.52kB 14.98%  github.com/shirou/gopsutil/internal/common.BootTimeWithContext
         0     0% 28.60%  5126.52kB 14.98%  github.com/shirou/gopsutil/internal/common.ReadLines (inline)
 1024.38kB  2.99% 31.59%  5126.52kB 14.98%  github.com/shirou/gopsutil/internal/common.ReadLinesOffsetN
 3584.50kB 10.48% 42.07%  5120.55kB 14.97%  os.Readlink
         0     0% 42.07%  4685.97kB 13.70%  net/http.(*ServeMux).ServeHTTP

 

2.4.2.CPU耗時分析

我們可以採用go tool pprof http://127.0.0.1:9090/debug/pprof/profile命令連線到程式中 檢視正在使用的一些CPU相關資訊。

Type: cpu
Time: Dec 15, 2021 at 2:17pm (CST)
Duration: 30s, Total samples = 10ms (0.033%)
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top 10
Showing nodes accounting for 10ms, 100% of 10ms total
      flat  flat%   sum%        cum   cum%
      10ms   100%   100%       10ms   100%  runtime.runqgrab
         0     0%   100%       10ms   100%  runtime.findrunnable
         0     0%   100%       10ms   100%  runtime.mcall
         0     0%   100%       10ms   100%  runtime.park_m
         0     0%   100%       10ms   100%  runtime.runqsteal
         0     0%   100%       10ms   100%  runtime.schedule
(pprof) 
(pprof) top20 -cum
Showing nodes accounting for 10ms, 100% of 10ms total
      flat  flat%   sum%        cum   cum%
         0     0%     0%       10ms   100%  runtime.findrunnable
         0     0%     0%       10ms   100%  runtime.mcall
         0     0%     0%       10ms   100%  runtime.park_m
      10ms   100%   100%       10ms   100%  runtime.runqgrab
         0     0%   100%       10ms   100%  runtime.runqsteal
         0     0%   100%       10ms   100%  runtime.schedule

2.3.3.獲取svg圖

在我們執行go tool pprof -inuse_space http://127.0.0.1:9090/debug/pprof/heap命令和go tool pprof http://127.0.0.1:9090/debug/pprof/profile命令都可以在回顯中注入svg，這樣將會產生一個.svg圖片，其會把這些累積關係畫成一個拓撲圖，提供給 我們。

下面我們取一個圖片中的一個片段進行分析:

每一個方塊為pprof記錄的一個函式呼叫棧，連線上的標籤代表指定的方法呼叫的取樣值（例如時間、記憶體分配大小等），方框的大小與方法執行的取樣值的大小有關。

每個方框由兩個標籤組成：在 cpu profile 中，一個是方法執行的時間佔比，一個是它在取樣的堆疊中出現的時間佔比（前者是 flat 時間，後者則是 cumulate 時間佔比)；框越大，代表耗時越多或是記憶體分配越多。

--inuse/alloc_space --inuse/alloc_objects區別

通常情況下：

1.--inuse_space:用來分析程式常駐記憶體的佔用情況;
2.--alloc_objects：用來分析記憶體的臨時分配情況，可以提高程式的執行速度。

 原文：https://www.cnblogs.com/yaohong/

 

參考

• profiling-go-programs
• Optimising Go allocations using pprof
• Debugging performance issues in Go programs
• Golang Slices And The Case Of The Missing Memory
• https://www.cnblogs.com/qcrao-2018/p/11832732.html