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 web

每一個方塊為pprof記錄的一個函數調用棧,連線上的標簽代表指定的方法調用的采樣值(例如時間、內存分配大小等),方框的大小與方法運行的采樣值的大小有關。

每個方框由兩個標簽組成:在 cpu profile 中,一個是方法運行的時間占比,一個是它在采樣的堆棧中出現的時間占比(前者是 flat 時間,后者則是 cumulate 時間占比);框越大,代表耗時越多或是內存分配越多。

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

通常情況下:

1.--inuse_space:用來分析程序常駐內存的占用情況;
2.--alloc_objects:用來分析內存的臨時分配情況,可以提高程序的運行速度。

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

 

參考


免責聲明!

本站轉載的文章為個人學習借鑒使用,本站對版權不負任何法律責任。如果侵犯了您的隱私權益,請聯系本站郵箱yoyou2525@163.com刪除。



 
粵ICP備18138465號   © 2018-2025 CODEPRJ.COM