go 程序性能調優 pprof 的使用（一）

本文轉載自查看原文 2020-10-13 10:28 2041 golang

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 一樣

免責聲明！

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

猜您在找 Go pprof性能調優 Go pprof性能調優 go pprof 性能調優 golang 使用pprof進行性能調優 Go 程序的性能優化及 pprof 的使用使用pprof及Go 程序的性能優化程序性能調優之怎樣使用gprof和oprofile來分析 linux程序的性能（每個函數的調用次數與耗時） Go性能調優使用pprof調試go程序 Go 程序的性能監控與分析 pprof