使用 pprof 和火焰圖調試 golang 應用

ZBFDes 7年前發布 | 40K 次閱讀 Go語言 Google Go/Golang開發 Kubernetes

什么是 Profiling?

Profiling 這個詞比較難翻譯，一般譯成 畫像 。比如在案件偵破的時候會對嫌疑人做畫像，從犯罪現場的種種證據，找到嫌疑人的各種特征，方便對嫌疑人進行排查；還有就是互聯網公司會對用戶信息做畫像，通過了解用戶各個屬性（年齡、性別、消費能力等），方便為用戶推薦內容或者廣告。

在計算機性能調試領域里，profiling 就是對應用的畫像，這里畫像就是應用使用 CPU 和內存的情況。也就是說應用使用了多少 CPU 資源？都是哪些部分在使用？每個函數使用的比例是多少？有哪些函數在等待 CPU 資源？知道了這些，我們就能對應用進行規劃，也能快速定位性能瓶頸。

golang 是一個對性能特別看重的語言，因此語言中自帶了 profiling 的庫，這篇文章就要講解怎么在 golang 中做 profiling。

在 go 語言中，主要關注的應用運行情況主要包括以下幾種：

  • CPU profile：報告程序的 CPU 使用情況，按照一定頻率去采集應用程序在 CPU 和寄存器上面的數據
  • Memory Profile（Heap Profile）：報告程序的內存使用情況
  • Block Profiling：報告 goroutines 不在運行狀態的情況，可以用來分析和查找死鎖等性能瓶頸
  • Goroutine Profiling：報告 goroutines 的使用情況，有哪些 goroutine，它們的調用關系是怎樣的

兩種收集方式

做 Profiling 第一步就是怎么獲取應用程序的運行情況數據。go 語言提供了 runtime/pprof 和 net/http/pprof 兩個庫，這部分我們講講它們的用法以及使用場景。

工具型應用

如果你的應用是一次性的，運行一段時間就結束。那么最好的辦法，就是在應用退出的時候把 profiling 的報告保存到文件中，進行分析。對于這種情況，可以使用 runtime/pprof 庫 。

pprof 封裝了很好的接口供我們使用，比如要想進行 CPU Profiling，可以調用 pprof.StartCPUProfile() 方法，它會對當前應用程序進行 CPU profiling，并寫入到提供的參數中（ w io.Writer ），要停止調用 StopCPUProfile() 即可。

去除錯誤處理只需要三行內容，一般把部分內容寫在 main.go 文件中，應用程序啟動之后就開始執行：

f, err := os.Create(*cpuprofile)
...
pprof.StartCPUProfile(f)
defer pprof.StopCPUProfile()

應用執行結束后，就會生成一個文件，保存了我們的 CPU profiling 數據。

想要獲得內存的數據，直接使用 WriteHeapProfile 就行，不用 start 和 stop 這兩個步驟了：

f, err := os.Create(*memprofile)
pprof.WriteHeapProfile(f)
f.Close()

服務型應用

如果你的應用是一直運行的，比如 web 應用，那么可以使用 net/http/pprof 庫，它能夠在提供 HTTP 服務進行分析。

如果使用了默認的 http.DefaultServeMux （通常是代碼直接使用 http.ListenAndServe("0.0.0.0:8000", nil) ），只需要添加一行：

import _ "net/http/pprof"

如果你使用自定義的 Mux ，則需要手動注冊一些路由規則：

r.HandleFunc("/debug/pprof/", pprof.Index)
r.HandleFunc("/debug/pprof/cmdline", pprof.Cmdline)
r.HandleFunc("/debug/pprof/profile", pprof.Profile)
r.HandleFunc("/debug/pprof/symbol", pprof.Symbol)
r.HandleFunc("/debug/pprof/trace", pprof.Trace)

不管哪種方式，你的 HTTP 服務都會多出 /debug/pprof endpoint，訪問它會得到類似下面的內容：

/debug/pprof/


profiles:
0   block
62  goroutine
444 heap
30  threadcreate


full goroutine stack dump</code></pre> 
  
這個路徑下還有幾個子頁面：
 
  
     
   
  • /debug/pprof/profile ：訪問這個鏈接會自動進行 CPU profiling，持續 30s，并生成一個文件供下載
    •  
   
  • /debug/pprof/heap ： Memory Profiling 的路徑，訪問這個鏈接會得到一個內存 Profiling 結果的文件
    •  
   
  • /debug/pprof/block ：block Profiling 的路徑
    •  
   
  • /debug/pprof/goroutines ：運行的 goroutines 列表，以及調用關系
    •  
  
 
  
go tool pprof 命令：獲取和分析 Profiling 數據
 
  
能通過對應的庫獲取想要的 Profiling 數據之后（不管是文件還是 http），下一步就是要對這些數據進行保存和分析，我們可以使用 go tool pprof 命令行工具。
 
  
在后面我們會生成調用關系圖和火焰圖，需要安裝 graphviz 軟件包，在 ubuntu 系統可以使用下面的命令：
 
  
$ sudo apt-get install -y graphviz
 
  
NOTE：獲取的 Profiling 數據是動態的，要想獲得有效的數據，請保證應用處于較大的負載（比如正在生成中運行的服務，或者通過其他工具模擬訪問壓力）。否則如果應用處于空閑狀態，得到的結果可能沒有任何意義。
 
  
CPU Profiling
 
  
go tool pprof 最簡單的使用方式為 go tool pprof [binary] [source] ， binary 是應用的二進制文件，用來解析各種符號； source 表示 profile 數據的來源，可以是本地的文件，也可以是 http 地址。比如：
 
  
?  go tool pprof ./hyperkube http://172.16.3.232:10251/debug/pprof/profile
Fetching profile from http://172.16.3.232:10251/debug/pprof/profile
Please wait... (30s)
Saved profile in /home/cizixs/pprof/pprof.hyperkube.172.16.3.232:10251.samples.cpu.002.pb.gz
Entering interactive mode (type "help" for commands)
(pprof)
 
  
這個命令會進行 CPU profiling 分析，等待一段時間（默認是 30s，如果在 url 最后加上 ?seconds=60 參數可以調整采集數據的時間為 60s）之后，我們就進入了一個交互式命令行，可以對解析的結果進行查看和導出。可以通過 help 來查看支持的自命令有哪些。
 
  
一個有用的命令是 topN ，它列出最耗時間的地方：
 
  
(pprof) top10
130ms of 360ms total (36.11%)
Showing top 10 nodes out of 180 (cum >= 10ms)
      flat  flat%   sum%        cum   cum%
      20ms  5.56%  5.56%      100ms 27.78%  encoding/json.(*decodeState).object
      20ms  5.56% 11.11%       20ms  5.56%  runtime.(*mspan).refillAllocCache
      20ms  5.56% 16.67%       20ms  5.56%  runtime.futex
      10ms  2.78% 19.44%       10ms  2.78%  encoding/json.(*decodeState).literalStore
      10ms  2.78% 22.22%       10ms  2.78%  encoding/json.(*decodeState).scanWhile
      10ms  2.78% 25.00%       40ms 11.11%  encoding/json.checkValid
      10ms  2.78% 27.78%       10ms  2.78%  encoding/json.simpleLetterEqualFold
      10ms  2.78% 30.56%       10ms  2.78%  encoding/json.stateBeginValue
      10ms  2.78% 33.33%       10ms  2.78%  encoding/json.stateEndValue
      10ms  2.78% 36.11%       10ms  2.78%  encoding/json.stateInString
 
  
每一行表示一個函數的信息。前兩列表示函數在 CPU 上運行的時間以及百分比；第三列是當前所有函數累加使用 CPU 的比例；第四列和第五列代表這個函數以及子函數運行所占用的時間和比例（也被稱為 累加值 cumulative ），應該大于等于前兩列的值；最后一列就是函數的名字。如果應用程序有性能問題，上面這些信息應該能告訴我們時間都花費在哪些函數的執行上了。
 
  
pprof 不僅能打印出最耗時的地方( top )，還能列出函數代碼以及對應的取樣數據( list )、匯編代碼以及對應的取樣數據( disasm )，而且能以各種樣式進行輸出，比如 svg、gv、callgrind、png、gif等等。
 
  
其中一個非常便利的是 web 命令，在交互模式下輸入 web ，就能自動生成一個 svg 文件，并跳轉到瀏覽器打開，生成了一個函數調用圖：
 
  
 
  
這個調用圖包含了更多的信息，而且可視化的圖像能讓我們更清楚地理解整個應用程序的全貌。圖中每個方框對應一個函數，方框越大代表執行的時間越久（包括它調用的子函數執行時間，但并不是正比的關系）；方框之間的箭頭代表著調用關系，箭頭上的數字代表被調用函數的執行時間。
 
  
因為原圖比較大，這里只截取了其中一部分，但是能明顯看到 encoding/json.(*decodeState).object 是這里耗時比較多的地方，而且能看到它調用了哪些函數，分別函數多少。這些更詳細的信息對于定位和調優性能是非常有幫助的！
 
  
要想更細致分析，就要精確到代碼級別了，看看每行代碼的耗時，直接定位到出現性能問題的那行代碼。 pprof 也能做到， list 命令后面跟著一個正則表達式，就能查看匹配函數的代碼以及每行代碼的耗時：
 
  
(pprof) list podFitsOnNode
Total: 120ms
ROUTINE ======================== k8s.io/kubernetes/plugin/pkg/scheduler.podFitsOnNode in /home/cizixs/go/src/k8s.io/kubernetes/_output/local/go/src/k8s.io/kubernetes/plugin/pkg/scheduler/generic_scheduler.go
         0       20ms (flat, cum) 16.67% of Total
         .          .    230:
         .          .    231:// Checks whether node with a given name and NodeInfo satisfies all predicateFuncs.
         .          .    232:func podFitsOnNode(pod *api.Pod, meta interface{}, info *schedulercache.NodeInfo, predicateFuncs map[string]algorithm.FitPredicate) (bool, []algorithm.PredicateFailureReason, error) {
         .          .    233:   var failedPredicates []algorithm.PredicateFailureReason
         .          .    234:   for _, predicate := range predicateFuncs {
         .       20ms    235:       fit, reasons, err := predicate(pod, meta, info)
         .          .    236:       if err != nil {
         .          .    237:           err := fmt.Errorf("SchedulerPredicates failed due to %v, which is unexpected.", err)
         .          .    238:           return false, []algorithm.PredicateFailureReason{}, err
         .          .    239:       }
         .          .    240:       if !fit {
 
  
如果想要了解對應的匯編代碼，可以使用 disadm <regex> 命令。這兩個命令雖然強大，但是在命令行中查看代碼并不是很方面，所以你可以使用 weblist 命令，用法和兩者一樣，但它會在瀏覽器打開一個頁面，能夠同時顯示源代碼和匯編代碼。
 
  
NOTE：更詳細的 pprof 使用方法可以參考 pprof --help 或者 pprof 文檔 。
 
  
Memory Profiling
 
  
要想獲得內存使用 Profiling 信息，只需要把數據源修改一下就行（對于 http 方式來說就是修改 url 的地址，從 /debug/pprof/profile 改成 /debug/pprof/heap ）：
 
  
?  go tool pprof ./hyperkube http://172.16.3.232:10251/debug/pprof/heap        
Fetching profile from http://172.16.3.232:10251/debug/pprof/heap
Saved profile in /home/cizixs/pprof/pprof.hyperkube.172.16.3.232:10251.inuse_objects.inuse_space.002.pb.gz
Entering interactive mode (type "help" for commands)
(pprof)
 
  
和 CPU Profiling 使用一樣，使用 top N 可以打印出使用內存最多的函數列表：
 
  
(pprof) top
11712.11kB of 14785.10kB total (79.22%)
Dropped 580 nodes (cum <= 73.92kB)
Showing top 10 nodes out of 146 (cum >= 512.31kB)
      flat  flat%   sum%        cum   cum%
 2072.09kB 14.01% 14.01%  2072.09kB 14.01%  k8s.io/kubernetes/vendor/github.com/beorn7/perks/quantile.NewTargeted
 2049.25kB 13.86% 27.87%  2049.25kB 13.86%  k8s.io/kubernetes/pkg/api/v1.(*ResourceRequirements).Unmarshal
 1572.28kB 10.63% 38.51%  1572.28kB 10.63%  k8s.io/kubernetes/vendor/github.com/beorn7/perks/quantile.(*stream).merge
 1571.34kB 10.63% 49.14%  1571.34kB 10.63%  regexp.(*bitState).reset
 1184.27kB  8.01% 57.15%  1184.27kB  8.01%  bytes.makeSlice
 1024.16kB  6.93% 64.07%  1024.16kB  6.93%  k8s.io/kubernetes/pkg/api/v1.(*ObjectMeta).Unmarshal
  613.99kB  4.15% 68.23%  2150.63kB 14.55%  k8s.io/kubernetes/pkg/api/v1.(*PersistentVolumeClaimList).Unmarshal
  591.75kB  4.00% 72.23%  1103.79kB  7.47%  reflect.Value.call
  520.67kB  3.52% 75.75%   520.67kB  3.52%  k8s.io/kubernetes/vendor/github.com/gogo/protobuf/proto.RegisterType
  512.31kB  3.47% 79.22%   512.31kB  3.47%  k8s.io/kubernetes/pkg/api/v1.(*PersistentVolumeClaimStatus).Unmarshal
 
  
每一列的含義也是類似的，只不過從 CPU 使用時間變成了內存使用大小，就不多解釋了。
 
  
類似的， web 命令也能生成 svg 圖片在瀏覽器中打開，從中可以看到函數調用關系，以及每個函數的內存使用多少。
 
  
需要注意的是，默認情況下，統計的是內存使用大小，如果執行命令的時候加上 --inuse_objects 可以查看每個函數分配的對象數； --alloc-space 查看分配的內存空間大小。
 
  
這里還要提兩個比較有用的方法，如果應用比較復雜，生成的調用圖特別大，看起來很亂，有兩個辦法可以優化：
 
  
     
   
  • 使用 web funcName 的方式，只打印和某個函數相關的內容
    •  
   
  • 運行 go tool pprof 命令時加上 --nodefration=0.05 參數，表示如果調用的子函數使用的 CPU、memory 不超過 5%，就忽略它，不要顯示在圖片中
    •  
  
 
  
pprof 已經支持動態的 web 瀏覽方式：https://github.com/google/pprof/commit/f83a3d89c18c445178f794d525bf3013ef7b3330
 
  
go-torch 和火焰圖
 
  
火焰圖（Flame Graph）是 Bredan Gregg 創建的一種性能分析圖表，因為它的樣子近似 :fire:而得名。上面的 profiling 結果也轉換成火焰圖，如果對火焰圖比較了解可以手動來操作，不過這里我們要介紹一個工具： go-torch 。這是 uber 開源的一個工具，可以直接讀取 golang profiling 數據，并生成一個火焰圖的 svg 文件。
 
  
 
  
火焰圖 svg 文件可以通過瀏覽器打開，它對于調用圖的最優點是它是動態的：可以通過點擊每個方塊來 zoom in 分析它上面的內容。
 
  
火焰圖的調用順序從下到上，每個方塊代表一個函數，它上面一層表示這個函數會調用哪些函數，方塊的大小代表了占用 CPU 使用的長短。火焰圖的配色并沒有特殊的意義，默認的紅、黃配色是為了更像火焰而已。
 
  
go-torch 工具的使用非常簡單，沒有任何參數的話，它會嘗試從 http://localhost:8080/debug/pprof/profile 獲取 profiling 數據。它有三個常用的參數可以調整：
 
  
     
   
  • -u --url ：要訪問的 URL，這里只是主機和端口部分
    •  
   
  • -s --suffix ：pprof profile 的路徑，默認為 /debug/pprof/profile
    •  
   
  • --seconds ：要執行 profiling 的時間長度，默認為 30s
    •  
  
 
  
要生成火焰圖，需要事先安裝 FlameGraph 工具，這個工具的安裝很簡單，只要把對應的可執行文件放到 $PATH 目錄下就行。
 
  
和測試工具的集成
 
  
go test 命令有兩個參數和 pprof 相關，它們分別指定生成的 CPU 和 Memory profiling 保存的文件：
 
  
     
   
  • -cpuprofile ：cpu profiling 數據要保存的文件地址
    •  
   
  • -memprofile ：memory profiling 數據要報文的文件地址
    •  
  
 
  
比如下面執行測試的同時，也會執行 CPU profiling，并把結果保存在 cpu.prof 文件中：
 
  
$ go test -bench . -cpuprofile=cpu.prof
 
  
執行結束之后，就會生成 main.test 和 cpu.prof 文件。要想使用 go tool pprof ，需要指定的二進制文件就是 main.test 。
 
  
需要注意的是，Profiling 一般和性能測試一起使用，這個原因在前文也提到過，只有應用在負載高的情況下 Profiling 才有意義。
 
  
參考資料
 
   
  
 
 
  
來自：http://cizixs.com/2017/09/11/profiling-golang-program
 
  
 
 本文由用戶 ZBFDes 自行上傳分享，僅供網友學習交流。所有權歸原作者，若您的權利被侵害，請聯系管理員。
 轉載本站原創文章，請注明出處，并保留原始鏈接、圖片水印。
 本站是一個以用戶分享為主的開源技術平臺，歡迎各類分享！