萬字長文講透 Go 程序性能優化

性能分析和優化是所有軟件開發人員必備的技能，也是後臺大佬們口中津津樂道的話題。

Golang 作爲一門 “現代化” 的語言，原生就包含了強大的性能分析工具 pprof 和 trace。pprof 工具常用於分析資源的使用情況，可以採集程序運行時的多種不同類型的數據（例如 CPU 佔用、內存消耗和協程數量等），並對數據進行分析聚合生成的報告。trace 工具則關注程序運行時的事件（例如協程狀態切換，GC 的開始和結束、系統調用等等），常用於分析延遲、阻塞和調度等問題。掌握了這兩個工具就足以滿足大部分 Golang 程序的性能分析需求。

本文將從使用方法、原理和實踐三個方面分別介紹 pprof 和 trace 工具。讀完本文後，相信你也可以更全面地掌握 pprof 和 trace。廢話少說，讓我們開始！

01

pprof 工具詳解

pprof 是一個用於可視化和分析數據的工具。可以在 Go 程序運行時對多種不同類型的數據進行採樣，常用來分析的數據類型有：

獲取採樣數據後，pprof 提供了多種不同的分析模式用於數據分析，常用的分析模式有：

接下來按採樣數據類型逐一分析。

   1.1 profile CPU 分析

   1.1.1 生成採樣數據

   1.1.1.1 代碼直接生成

在 main 函數開頭直接加入如下代碼，程序結束後將得到完整的採樣數據文件 CPU.out；該方式常用在工具代碼分析場景。

func main() {
    f, _ := os.Create('CPU.out')
    defer f.Close()
    pprof.StartCPUProfile(f)
    defer   pprof.StopCPUProfile()
    ...
}

   1.1.1.2 go test 參數生成

執行 go test 時，加上參數 -CPUprofile CPU.out 生成採樣數據。

go test -CPUprofile CPU.out . -run=TestFunc

   1.1.1.3 通過 http 請求生成

在程序主路徑上引入 net/http/pprof 包，啓動 http 服務。

import (
  'net/http'
  _ 'net/http/pprof'
)
func pprofServerStart() {
  go func() {
    http.ListenAndServe('127.0.0.1:6060', nil) // 安全起見，使用本地地址進行監聽
  }()
}

引入 pprof 包後，會在默認處理器 DefaultServeMux 上註冊 /debug/pprof/profile 接口的路由；調用 ListenAndServe 啓動 http 服務，第二個參數傳 nil 使用默認處理器處理請求。考慮安全原因，http 服務的地址和端口建議使用本地地址。

使用 go tool pprof 命令訪問本地服務的 /debug/pprof/profile 接口，CPU 採樣數據會自動保存到 $HOME/pprof/ 目錄下，同時也會直接進入分析命令行。

$ go tool pprof http://127.0.0.1:6060/debug/pprof/profile?seconds=30
Saved profile in /root/pprof/pprof.demo.samples.CPU.001.pb.gz
File: demo
Type: CPU
Time: Dec 24, 2023 at 11:42am (CST)
Duration: 10s, Total samples = 70ms (  0.7%)
Entering interactive mode (type 'help' for commands, 'o' for options)
(pprof)

   1.1.2 分析數據

   1.1.2.1 打開採樣數據

需要將採樣數據下載到有源代碼的機器上進行分析，在沒有源代碼的機器上 source 和 peek 模式無效。

有兩種方法打開採樣數據，命令行和可視化界面。筆者個人更喜歡可視化界面的方式，鼠標點一點就能分析非常方便，本文後續章節都以可視化界面分析爲例子進行說明。

直接用 go tool pprof 打開採樣文件，輸入 top、list（等同於上文說的的 source）、peek 等命令進行分析。

$ go tool pprof CPU.out 
File: bench.test
Type: CPU
Time: Dec 24, 2023 at 10:43am (CST)
Duration: 1.96s, Total samples = 1.83s (93.33%)
Entering interactive mode (type 'help' for commands, 'o' for options)
(pprof)

使用 go tool pprof -http=ip:port 啓動服務。

$ go tool pprof -http=127.0.0.1:9888 CPU.out
Serving web UI on http://127.0.0.1:9888

瀏覽器訪問 http://127.0.0.1:9888 即可打開可視化界面，其中在 VIEW 菜單包含了常用的分析模式，如下圖所示。

   1.1.2.2 分析模式一 svg 矢量圖

點擊 VIEW 菜單下的 Graph 子項，可以生成 svg 矢量圖如下圖。svg 矢量圖很適合從整體上對資源使用情況進行把握，並且還可以輔助分析程序的調用鏈情況。

圖中每一個小的矩形框節點，代表一個函數（或方法），節點的入箭頭和出箭頭代表調用上游和下游。函數本身 + 函數下游彙總的 CPU 時間佔比越高，矩形框的顏色越深，進入該節點的箭頭也越粗。

節點說明如上圖，內部包含兩部分，上半部分是包名、類名、函數名和匿名函數名等基礎信息；下半部分是最多兩個統計數據，第一個是函數本身的彙總 CPU 時間，第二個是函數總體（本身 + 下游調用）的彙總 CPU 時間，統計信息如果沒有或很小會省略。

svg 矢量圖最上方的搜索框可以使用正則語法過濾特定的節點，搜索後只有調用鏈中有滿足搜索條件的節點纔會展示出來。

   1.1.2.3 分析模式二 top

點擊 VIEW 菜單的 top 子項，可以列出按本身 CPU 時間（即不包含下游）佔比從大到小排列的所有函數。

指標說明：

同樣的，top 模式中也可以在上方搜索框使用正則語法過濾特定的節點。top 的使用場景和 svg 矢量圖類似，都是整體上對資源使用情況進行分析。

   1.1.2.4 分析模式三 source

點擊 VIEW 菜單的 source 子項，進入源碼分析模式。svg 或 top 模式的分析顆粒度是函數，而 source 模式的顆粒度是源代碼的每一行；除了可以給出函數總體的 flat 和 cum 之外，還給出了每一行代碼的 flat 和 cum，這使得我們可以對函數內部逐行深入分析。source 一般都是配合搜索框使用，下圖展示了在 source 模式下搜索關鍵詞 chansend1，對 channel 入隊的源碼分析的結果。

   1.1.2.5 分析模式四 peek

點擊 VIEW 菜單的 peek 子項，可以在代碼行的顆粒度對函數調用上下游進行分析。

Peek 在強大之處在於，它可以量化的分析上下游調用的佔比情況。如圖中所示，chansend1 節點自身的統計信息是中間的紅框；上面的紅框列出了所有調用了 chansend1 的代碼行及其統計佔比，下面的紅框則是 chansend1 調用下游的代碼行及其統計佔比。當在 svg 矢量圖或 top 分析中看到一個很重的系統調用節點時，雖然我們無法對系統調用本身進行優化，但是使用 peek 排查調用上游情況，或許我們就會發現一個不合理的系統調用用法。

   1.1.3 profile 採樣原理分析

   1.1.3.1 太長不看版

Go 程序運行中，隨機選擇一個處於正在執行狀態的協程，記錄該協程當前的調用棧，這是一次 profile 採樣。

我們可以容易的得出這樣一個推論，如果某個函數佔用了較多的 CPU 時間，那麼一次採樣中記錄到的正在執行的函數就是該函數的概率也相對較大。這個推論反過來也成立，即如果在多次採樣中，某個函數出現次數佔比較高，那麼該函數大概率也佔用了較多的 CPU 時間。

因此可以用採樣的結果來逼近真實的結果，採樣頻次越高逼近效果越好。

在用戶指定的採樣週期內，profile 的會按照一定的頻率進行採樣，隨機得到一個協程的調用棧信息；採樣頻率固定爲 100，採樣間隔爲 1s/100=10ms；

在分析時，按採樣數據的調用棧進行聚合（調用棧計算 hash，hash 值相等就是相同的調用棧），某個調用棧的彙總 CPU 時間就等於該調用棧的採樣次數 * 採樣間隔。

調用棧及統計信息有了，按照函數或代碼行維度進行進一步聚合，再輔助調用棧的上下游關係，就可以生成 svg 圖、peek 和 source 等數據了。

分析採樣原理的最初的目的，是爲了弄清楚 pprof 本身對性能的影響情況，不瞭解 pprof 採樣原理的話，是不敢貿然用在生產環境上的。

這裏給直接結論，開啓 pprof 採樣後，對性能有影響但是非常小，生產環境可以放心使用。

   1.1.3.2 源碼分析

當在代碼中引入的 pprof 包後，包內的 init 函數會將 /debug/pprof/profile 路由註冊到默認處理器中，處理入口是 Profile 函數。

// net/http/pprof/pprof.go
func init() {
  ...
  http.HandleFunc('/debug/pprof/profile', Profile) // 路由註冊到Profile進行處理
  ...
}

在 Profile 函數中，會調用 pprof.StartCPUProfile 來開啓採樣，按傳參 seconds（默認 30s）進行 sleep 之後，再調用 pprof.StopCPUProfile 停止採樣。

// runtime/mprof.go
func Profile(w http.ResponseWriter, r *http.Request) {
   ...
   // 開啓採樣
  if err := pprof.StartCPUProfile(w); err != nil {
      ...
  }
  sleep(r, time.Duration(sec)*time.Second)
  // 停止採樣
  pprof.StopCPUProfile()}
}

追蹤 StartCPUProfile 函數，其中有兩個關鍵步驟：runtime.SetCPUProfileRate 和 profileWriter。

// runtime/pprof/pprof.go
func StartCPUProfile(w io.Writer) error {
   ...
  runtime.SetCPUProfileRate(hz) // hz固定爲100
  go profileWriter(w)
   ...
}

runtime.SetCPUProfileRate 最終調用到了 setThreadCPUProfiler 函數，該函數使用 time_create 開啓了一個定時器，並設置定時器間隔時間是 1s/100=10ms；該定時器會每 10ms 向所在線程定時發送 SIGPROF 信號，代碼如下：

// runtime/signal_unix.go
func setThreadCPUProfiler(hz int32) {
     mp := getg().m // 獲取當前協程綁定的的線程M
   ...
  spec := new(itimerspec)
  spec.it_value.setNsec(1 + int64(fastrandn(uint32(1e9/hz))))
  spec.it_interval.setNsec(1e9 / int64(hz)) // 設置間隔爲 100000000/100 納秒 = 10ms
  var timerid int32
  var sevp sigevent
  sevp.notify = _SIGEV_THREAD_ID
  sevp.signo = _SIGPROF // 設置signal類型爲SIGPROF
  sevp.sigev_notify_thread_id = int32(mp.procid) // 設置signal通知給線程procid
  ret := timer_create(_CLOCK_THREAD_CPUTIME_ID, &sevp, &timerid) // 創建定時器
   ...
  ret = timer_settime(timerid, 0, spec, nil) // 啓動定時器
   ...
}

線程收到 SIGPROF 信號中斷後，線程關聯的處理器 P 會使用特殊的協程 gsignal 來處理信號。在 Go 主線程啓動後到開始調度循環之前，會調用 mstartm0 函數，mstartm0 中則執行了 initsig 來設置所有信號的處理入口。一路追蹤 initsig 函數，最終可以在 sighandler 函數中找到處理 SIGPROF 信號的入口 sigprof。

// runtime/signal_unix.go
func sighandler(sig uint32, info *siginfo, ctxt unsafe.Pointer, gp *g) {
   ...
     // SIGPROF信號的處理入口
  if sig == _SIGPROF {
    if !delayedSignal && validSIGPROF(mp, c) {
      sigprof(c.sigpc(), c.sigsp(), c.siglr(), gp, mp)
    }
    return
  }
}

sigprof 首先會調用 gentraceback 得到當前協程正在執行的調用棧。gentraceback 比較複雜，好在大致流程是比較清晰的。簡化後的代碼如下圖，for 循環 max 次，從程序計數器 pc、棧指針 sp、鏈接寄存器 lr 取出當前協程的 max 層調用棧信息，保存在 pcbuf 中；profile 採樣下 max 取值爲 64，只取 64 層級的棧信息。

// runtime/traceback.go
func gentraceback(pc0, sp0, lr0 uintptr, gp *g, skip int, pcbuf *uintptr, max int, callback func(*stkframe, unsafe.Pointer) bool, v unsafe.Pointer, flags uint) int {
  ...
        // gp是當前協程對象G指針，保存了協程調度的各種信息
       if gp.syscallsp != 0 { // 如果當前是系統調用
      pc0 = gp.syscallpc // syscallpc程序計數器
      sp0 = gp.syscallsp // syscallsp得到棧指針
    } else { // 如果是用戶代碼調用
      pc0 = gp.sched.pc // sched.pc程序計數器
      sp0 = gp.sched.sp // sched.sp得到棧指針
    }
  ...
  var frame stkframe
     frame.pc = pc0 // 從pc0開始
  frame.sp = sp0
  frame.fp = 0
  ...
     for n < max { // profile採樣時max等於64，棧信息最多取64層級
      ...
      frame.fp = frame.sp + uintptr(funcspdelta(f, frame.pc, &cache))
      ...
        pc := frame.pc
      ...    
        (*[1 << 20]uintptr)(unsafe.Pointer(pcbuf))[n] = pc
      ...
      n++
      frame.pc = frame.lr // pc指向lr進入下一個循環
      frame.sp = frame.fp
      ...
   }
}

sigprof 接下來調用 traceCPUSample 將得到的採樣信息通過 log.write 寫入 profBuf 類型的緩衝區中，profBuf 是無鎖的併發安全的緩衝區，可供一個讀取者和一個寫入者高效安全的使用。

// runtime/trace.go
func traceCPUSample(gp *g, pp *p, stk []uintptr) {
  ...
  if log := (*profBuf)(atomic.Loadp(unsafe.Pointer(&trace.CPULogWrite))); log != nil {
    log.write(nil, now, hdr[:], stk)
  }
  ...
}

至此，程序完成了採樣信息的獲取和寫入了 profBuf 緩衝區。

回過頭來看看上文中提到 StartCPUProfile 的另一個關鍵步驟 go profileWriter，它做的事情比較簡單，就是循環從 profBuf 緩衝區中讀取數據，並按調用棧進行聚合，緩衝區讀到 eof 後，整理聚合的數據並壓縮寫入到 http 響應中。

// runtime/pprof/pprof.go
func profileWriter(w io.Writer) {
  b := newProfileBuilder(w)
  var err error
  for {
    time.Sleep(100 * time.Millisecond)
    // 從profBuf緩衝區讀取數據
    data, tags, eof := readProfile()
    // addCPUData按調用棧聚合數據
    if e := b.addCPUData(data, tags); e != nil && err == nil {
      ...
    }
    if eof {
      break // eof退出循環
    }
  }
  ...
  b.build() // 整理數據並壓縮寫入到http響應中
}

採樣時間到期後，StopCPUProfile 函數會調用 runtime.SetCPUProfileRate(0) 將採樣頻率設置爲 0，關閉定時器結束採樣。

profile 採樣的本質就是每隔 10ms 時間週期，佔用一個協程獲取一次當前的調用棧信息，因此對性能的影響非常小，生產環境可以放心使用。

   1.1.4 profile 實例分析

本小節中，將以一個 API 網關應用爲例介紹 profile 優化方法。

   1.1.4.1 優化前的指標情況

網關所有轉發的下游全部使用 mock 服務，響應爲固定時間和固定大小；使用 jmeter 壓測一組 3 個 API，併發數爲 1000，迭代次數 200，壓測網關轉發性能。

Starting standalone test @ 2024 Jan 4 22:38:17 CST (1704379097791)
summary = 600000 in 00:02:53 = 3459.8/s Avg:   281 Min:     9 Max:   1128 Err:     0 (0.00%)
Tidying up ...    @ 2024 Jan 4 22:41:11 CST (1704379271495)
$ dstat -lcmdnt 5
---load-avg--- ----total-CPU-usage---- ------memory-usage----- -dsk/total- -net/total- ----system----
 1m   5m  15m |usr sys idl wai hiq siq| used  buff  cach  free| read  writ| recv  send|     time     
18.5 27.0 26.8| 52  17  24   1   0   7|26.5G 2451M 31.4G 2232M|1895k 8395k|  96M  116M|04-01 22:38:26
20.7 27.3 26.9| 50  19  23   0   0   7|26.5G 2451M 31.4G 2134M|2105k   25M| 101M  116M|04-01 22:38:31
23.7 27.8 27.1| 48  19  24   1   0   7|25.9G 2451M 31.4G 2722M|2486k   20M| 102M  121M|04-01 22:38:36
...略...
62.5 42.9 32.9| 49  16  27   1   0   7|26.1G 2446M 31.7G 2303M|3691k 7273k| 105M  122M|04-01 22:40:56
66.1 44.0 33.3| 49  17  26   1   0   7|26.3G 2445M 31.7G 2051M|1539k   30M|  98M  115M|04-01 22:41:01
69.8 45.1 33.7| 51  19  23   1   0   6|26.7G 2440M 31.6G 1797M|1410k   66M|  90M  102M|04-01 22:41:06

   1.1.4.2 分析過程

從 svg 矢量圖或 top 分析入手是一個好的選擇，以 svg 矢量圖分析爲例。

我們可以從上圖中分析出程序運行的調用鏈關係，例如 gin(*Context).Next 的循環調用表明，這是一個使用 gin 框架實現的 http 服務；請求經過 7 個 middleware 中間件後，走到了 ProxyLogicsvr 函數並最終調到了 httputil.ServeHTTP；這個流程符合預期，因爲該應用就是基於 gin 框架和 httputil.ServerHttp 的代理能力搭建的網關服務。

httputil.ServerHttp 後續的節點都是 Go 原生代碼，暫時不好優化；我們需要關注 ServerHttp 之前的節點，進入 ServeHTTP 節點的總時間只有 26.58s，有大量 CPU 時間消耗在了代理轉發之前，需要進一步分析。

首先，重點關注顏色較深的自定義函數的節點，這些節點本身或下游佔用了較多 CPU 時間，同時又是我們自己寫的代碼，較容易進行分析和優化。比如 Check***Session 節點，高達 15% 的採樣佔比，我們要重點分析。

其次，關注其他顏色較深的節點，這些節點可能是系統調用、Golang 原生或第三方庫函數。對於這部分的熱點節點，我們需要了解它們的使用場景才能進一步分析。例如 runtime.growslice，這個是 Golang 切片擴容相關函數，我們無法對它本身進行優化，但是通過排查它的調用鏈，可以看到是否存在 slice 的誤用；再例如 runtime.gcBgMarkWorker 節點，是垃圾回收 GC 的標記階段相關的函數，我們需要針對 GC 情況進行分析。

最後，不妨通讀一遍 top 模式下的所有的節點，對找出有問題的節點很有幫助。

經過整體分析，我們可以找到很多有嫌疑的節點，我們以上一節中找出的三個節點爲例進行說明。

1）業務代碼實現效率低

在 source 模式搜索 Check***Session，顯示源碼分析如下圖：

可以看到一個簡單的 Debug 級日誌打印，居然消耗了 5.69s 的採樣時間；本例中的日誌級別是 Error，一個 debug 級的日誌預期是不會打印的。

分析這一行代碼，容易找出原因就是 req.String() 和 rsp.String()，進入 DebugGinCtxf 方法執行之前就會將 req 和 rsp 進行格式化化，導致了不必要的 CPU 開銷。

優化爲直接傳指針，優化完的 source 分析如下，該語句基本沒有額外的開銷。節點總體採樣 CPU 佔比也從 15% 下降到了 11.2%。

這是一個很低級的代碼效率問題，但是代碼 review 時可能會被忽略，而通過 profile 分析就可以進行精準定位。

2）庫函數調用不合理

runtime.growslice 節點消耗了 4.81s 採樣時間，總佔比爲 4.12%。對這個節點進行分析需要知道 slice 的基本原理，當使用 append 向 slice 填加元素時，如果 slice 的容量不足，則需要將 slice 容量擴大到原來的 2 倍或者 1.25 倍（取決於擴容前的 slice 容量大小）。假如 slice 初始化時沒有分配合適的容量，可能會導致 slice 進行多次擴容而產生不必要的性能開銷。

在 peek 模式搜索 runtime.growslice，會遇到一大堆的數據，耐心的查看列出的所有的調用棧，可以找到下圖中的一些有嫌疑的代碼位置。

圖中分析的 growslice 代碼位置位於 runtime/slice.go 的第 274 行，正是 growslice 內部調用 mallocgc 分配新內存的代碼行。可以看到其調用上游有很多的自定義的函數，逐一分析它們發現了多處 slice 初始化容量爲 0 的代碼；其中一個例子如下，很明顯一開始就可以給 vec 分配足夠的容量，從而避免多次的 slice 擴容。

  ...
  // 初始容量爲0
  // 應該改爲
  // vec := make([]interface{}, 2*len(m.data))
  vec := make([]interface{}, 0)
  for key, value := range m.data {
    vec = append(vec, key, value)
  }
}

將所有有問題的代碼優化掉，再重新分析 peek 如下圖，mallocgc 位置的採樣 CPU 佔比從 2.17% 下降到了 1.54%，幾個有問題的調用上游也都不見了。而 growslice 節點總體的 CPU 佔比也從 4.12% 下降到了 3.07%。

3）GC 相關優化

runtime.gcBgMarkWorker 節點消耗了 9.87% 的採樣時間。gcBgMarkWorker 是 GC 標記階段的關鍵函數，gcBgMarkWorker 佔比較高可能是因爲 GC 頻率較高導致，可以通過調整 GOGC 配置進行優化。

簡單展開一下 GOGC 配置，在 Go1.18 版本之後，自動 GC 的觸發條件爲：

target mem = Live heap + (Live heap + GC roots) * GOGC / 100

其中 Live heap 爲上一個週期活躍的堆內存大小，GC roots 我們暫時不管。可以這樣簡單理解，當 GOGC 爲默認值 100 時，新分配堆內存的數量是上一週期的活躍堆內存的一倍的時候，觸發 GC；GOGC 爲 200 時，該倍數關係變爲兩倍；以此類推。

我們的應用沒有使用大量內存，因此可以通過調大 GOGC 配置來降低 GC 的頻率，減少 GC 的 CPU 消耗。GOGC 值優化爲 800，優化後程序內存使用增加了 1 倍，而 gcBgMarkWorker 的 CPU 佔比則降到了 1%。

在 trace 工具中也可以對 GC 情況進行分析，將在本文的後半部分進行介紹。

   1.1.4.3 優化後的指標情況

上文說明的三個節點的優化預期能減少的 CPU 消耗在 10% 以上，使用 jmeter 進行壓測看一下實際結果。

Starting standalone test @ 2024 Jan 4 22:20:26 CST (1704378026473)
summary = 600000 in 00:02:46 = 3620.7/s Avg:   269 Min:    13 Max:  974 Err:     0 (0.00%)
Tidying up ...    @ 2024 Jan 4 22:23:12 CST (1704378192504)
$ dstat -lcmdnt 5
---load-avg--- ----total-CPU-usage---- ------memory-usage----- -dsk/total- -net/total- ----system----
 1m   5m  15m |usr sys idl wai hiq siq| used  buff  cach  free| read  writ| recv  send|     time  
17.9 23.2 22.2| 38  19  35   1   0   7|27.4G 2462M 31.4G 1313M|3609k   19M| 104M  119M|04-01 22:20:33
24.2 24.4 22.6| 37  16  38   1   0   8|27.6G 2462M 31.4G 1081M|1931k 5911k| 112M  128M|04-01 22:20:38
24.7 24.5 22.7| 37  17  37   1   0   8|27.6G 2462M 31.4G 1035M|2486k 4523k| 105M  121M|04-01 22:20:43
... 略...
55.2 36.0 27.1| 39  17  36   1   0   7|27.6G 2466M 31.4G 1030M|3897k 6099k| 108M  124M|04-01 22:22:58
54.5 36.2 27.2| 42  17  32   2   0   7|27.8G 2466M 31.3G  845M|2688k   18M| 110M  121M|04-01 22:23:03
56.3 36.9 27.5| 48  18  26   1   0   7|28.3G 2467M 31.2G  463M|1942k  109M| 101M  115M|04-01 22:23:08

優化後壓測 qps 提升 4%，CPU 從 72% 下降到 64%，性能提升也在 10% 以上，符合預期。

   1.1.4.4 總結

大部分的優化措施並不會像本文給出的例子這樣簡單，可能涉及更復雜的邏輯修改或架構重構；但是分析流程是類似的，先從整體上找出有問題的節點，再具體分析每個問題節點得到瓶頸點和可行的優化方案。

   1.2 allocs/heap 分析內存

allocs 和 heap 都可以用於內存分析，Golang 官方文檔給出的差別是：allocs 統計的是從程序開始以來所有內存分配的情況（即 alloc_space），而 heap 統計的是當前存活的對象的內存分配情況（即 inuse_space），但是實測獲取的數據都是 inuse_space。本節只討論使用 heap 進行內存分析。

   1.2.1 生成採樣數據

   1.2.1.1 代碼直接生成

在 main 函數開頭直接加入如下代碼，就可以得到 heap 採樣結果 mem.out。

func main() {
    f, _ := os.Create('mem.out')
    defer f.Close()
    runtime.GC() // 手動執行一次GC垃圾回收
    if err := pprof.WriteHeapProfile(f); err != nil {
        log.Fatal('could not write memory profile: ', err)
    }
    ...
}

   1.2.1.2 go test 參數生成

執行 go test 時，可以加上參數 -CPUprofile mem.out 生成 heap 採樣數據。

go test -memprofile mem.out . -run=TestFunc

   1.2.1.3 通過 http 接口生成

與 profile 採樣一樣，在主路徑上引入 net/http/pprof 包，啓動 http 服務。

import (
  'net/http'
  _ 'net/http/pprof'
)
func process() {
  go func() {
    http.ListenAndServe('127.0.0.1:6060', nil) // 安全起見，使用本地地址進行監聽
  }()
    ...
}

使用 go tool pprof 命令訪問本地服務的 /debug/pprof/heap 接口，獲得 heap 採樣數據保存到 $HOME/pprof/ 目錄下，同時也會直接進入分析命令行。

$ go tool pprof http://127.0.0.1:6060/debug/pprof/heap?seconds=30
Saved profile in /root/pprof/pprof.demo.alloc_objects.alloc_space.inuse_objects.inuse_space.001.pb.gz
File: demo
Type: inuse_space
Time: Dec 30, 2023 at 4:02pm (CST)
Duration: 30.09s, Total samples = 0 
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)

   1.2.2 通過 http 接口生成

分析 heap 採樣數據的方式與 profile 一致，差別是 heap 用於分析當前存活的對象是從哪個調用棧分配出來的以及累計的分配內存有多少，本小節不再贅述具體的分析模式和方法。

   1.2.3 heap 採樣原理分析

   1.2.3.1 太長不看版

bucket 節點用於保存內存採樣數據，bucket 中保存了程序調用棧信息，內存的分配大小、分配次數、回收大小、回收次數等統計信息；一個 bucket 代表程序執行到了某個調用棧並分配了某個大小的內存，不同調用棧或不同的內存大小會保存在不同的 bucket 中。

mbuckets 是一個鏈表結構，保存所有的內存採樣數據，新增 bucket 會添加到 mbuckets 開頭，通過 mbuckets 可以遍歷整個內存採樣 bucket。

buckhash 是一個哈希表結構，用於快速查找某個 bucket 節點，哈希 key 基於調用棧和分配內存大小兩個數據進行計算。

mbuckets 和 buckhash 一起，組成了一個可遍歷的哈希表存儲結構。

內存分配過程中，每次累積分配 512kb 大小的內存後，下一次內存分配將進行採樣，得到當前的調用棧信息和分配內存的大小。

按調用棧信息和分配內存的大小信息在 buckhash 中查找 bucket 節點，如果沒找到則創建新的 bucket 節點並添加到 mbuckets 鏈表開頭和添加到 buckhash 哈希表中；

找到 bucket 節點後，在節點中累加分配大小和自增分配次數；

最後還要將本次內存分配得到的對象添加特殊標記，並記錄下對象和 bucket 節點的映射關係。

GC 過程中，回收帶有特殊標記的對象時，通過對象映射關係找到 bucket 節點，在節點中累加回收大小和自增回收次數。

通過 mbuckets 遍歷所有 bucket 節點，就能得到所有的內存分配和回收的調用棧信息以及分配或回收的統計數據。基於這些統計數據，就可以進行後續的各種模式的分析了。

heap 採樣默認打開，對性能沒有影響，生產環境可以放心使用。

   1.2.3.2 源碼分析

bucket、mbuckets、buckhash 定義如下：

// runtime/mprof.go
type bucket struct {
  _       sys.NotInHeap
  next    *bucket
  allnext *bucket
  typ     bucketType // memBucket or blockBucket (includes mutexProfile)
  hash    uintptr
  size    uintptr
  nstk    uintptr
}
const (
  buckHashSize = 179999 // 哈希表大小
)
type buckhashArray [buckHashSize]atomic.UnsafePointer // *bucket
var (
  mbuckets atomic.UnsafePointer // 鏈表頭部 *bucket
  buckhash atomic.UnsafePointer // 哈希表 [buckHashSize]*bucket buckHashSize爲179999
)

bucket 結構中，allnext 指針用於指向下一個 bucket 節點，從而可以形成一個鏈表結構；next 指針也指向一個 bucket 節點，用於哈希表解決衝突使用；size 是節點分配內存大小；nstk 是一大塊內存空間的首地址，用於保存節點調用棧信息和內存分配 / 回收的統計信息，使用時通過地址偏移來尋址，本文不做詳細展開。

mbuckets 是 *bucket 類型的指針。

buckhash 則是 [buckHashSize]*bucket 類型的 map，buckHashSize 大小爲 179999。

爲了更好的理解數據結構，我們將查找和創建 bucket 節點的代碼拿出來提前分析，代碼如下：

// runtime/mprof.go
func stkbucket(typ bucketType, size uintptr, stk []uintptr, alloc bool) *bucket {
  ...
  bh := (*buckhashArray)(buckhash.Load())
  // 哈希值h，通過節點調用棧stk和分配內存大小size計算得到
  var h uintptr
  for _, pc := range stk {
    h += pc
    h += h << 10
    h ^= h >> 6
  }
  h += size
  h += h << 10
  h ^= h >> 6
  h += h << 3
  h ^= h >> 11
  // 哈希槽下標i
  i := int(h % buckHashSize)
  // 遍歷哈希表衝突鏈表，找到節點；eqslice確保調用棧完全相同
  for b := (*bucket)(bh[i].Load()); b != nil; b = b.next {
    if b.typ == typ && b.hash == h && b.size == size && eqslice(b.stk(), stk) {
      // 如果找到bucket指針就直接返回
      return b 
    }
  }
  // 沒有找到bucket節點，則創建新bucket節點
  b := newBucket(typ, len(stk))
  copy(b.stk(), stk) // 拷貝調用棧
  b.hash = h // 設置hash
  b.size = size // 設置分配內存大小
  var allnext *atomic.UnsafePointer
  if typ == memProfile {
    allnext = &mbuckets // typ爲內存分析，allnext指向mbuckets鏈表表頭
  }
  ...
  // 頭插法，將bucket插入哈希桶buckhash[i]的衝突鏈表開頭
  b.next = (*bucket)(bh[i].Load()) 
  // 頭插法，將bucket插入mbuckets鏈表開頭
  b.allnext = (*bucket)(allnext.Load())
  bh[i].StoreNoWB(unsafe.Pointer(b))
  allnext.StoreNoWB(unsafe.Pointer(b))
}

代碼流程很清晰：根據節點調用棧 stk 和分配內存大小 size 計算哈希值 h，並計算出哈希槽下標 i；遍歷哈希表 buckhash 的衝突鏈表 bh[i]，如果找到已存在該節點，則直接返回；否則創建一個新的 bucket 節點 b，保存內存大小、調用棧信息到 b 中，將 b 插入到 mbuckets 鏈表開頭，將 b 加入衝突鏈表 bh[i] 開頭。

runtime.mallocgc 函數是 Golang 堆內存管理的關鍵函數，所有的 new、make 和拷貝等操作都會走到 mallocgc 函數進行處理。在 mallocgc 函數中可以找到內存採樣邏輯如下：

// runtime/malloc.go
func mallocgc(size uintptr, typ *_type, needzero bool) unsafe.Pointer {
  c := getMCache(mp) // 線程緩存cache
  ...
  // MemProfileRate默認爲512 * 1024，內存分配採樣默認開啓
  if rate := MemProfileRate; rate > 0 {
    if rate != 1 && size < c.nextSample {
      c.nextSample -= size 
    } else {
      profilealloc(mp, x, size)
    }
  }
  ...
}
func profilealloc(mp *m, x unsafe.Pointer, size uintptr) {
  c := getMCache(mp) // 線程緩存cache
  c.nextSample = nextSample() // 重置c.nextSample爲512k
  mProf_Malloc(x, size) // 進行內存分配採樣
}

c.nextSample 緩存了距離下次採樣還需要分配多少內存，初始值爲 512k；每次分配內存時 c.nextSample 的值會減去當次分配內存的大小 size；當 size 小於 c.nextSample 時，說明累積分配了足夠多的內存，此時會重置 c.nextSample 爲初始值，並調用 mProf_Malloc 函數。

// runtime/mprof.go
func callers(skip int, pcbuf []uintptr) int {
  sp := getcallersp()
  pc := getcallerpc()
  gp := getg()
  var n int
  systemstack(func() {
    // gentraceback獲取調用棧信息
    n = gentraceback(pc, sp, 0, gp, skip, &pcbuf[0], len(pcbuf), nil, nil, 0)
  })
  return n
}
func mProf_Malloc(p unsafe.Pointer, size uintptr) {
  var stk [maxStack]uintptr // maxStack爲32
  // callers 調用gentraceback獲取調用棧信息
  nstk := callers(4, stk[:])
  index := (mProfCycle.read() + 2) % uint32(len(memRecord{}.future))
  // stkbucket 查找或創建bucket節點
  b := stkbucket(memProfile, size, stk[:nstk], true)
  // b.ntsk按偏移量定位到統計信息對象的地址，取出統計對象指針mp
  mp := b.mp()
  mpc := &mp.future[index]
  lock(&profMemFutureLock[index])
  mpc.allocs++ // 自增內存分配次數
  mpc.alloc_bytes += size // 累加內存分配大小
  unlock(&profMemFutureLock[index])
  systemstack(func() {
    // setprofilebucket，給對象打上_KindSpecialProfile標記，設置對象和bucket的關聯關係
    setprofilebucket(p, b)
  })
}

mProf_Malloc 函數邏輯也很清晰：

第一步，調用 callers 函數獲得調用棧信息，在 callers 函數內部又調用了 gentraceback 函數，在 profile 採樣原理分析小節中我們簡單分析過這個函數是如何獲取 N 層級的棧信息的，內存採樣時採樣了 32 層級的棧信息；

第二步，調用上文討論過的 stkbucket 函數，得到 bucket 指針 b；

第三步，按偏移量從 b.nstk 中取到統計對象 mpc，調用 mpc.allocs++ 和 mpc.alloc_bytes += size，在 bucket 節點的統計對象中累加分配大小和自增分配次數；

第四步，調用 setprofilebucket 給對象 p 打上 _KindSpecialProfile 標記，並保存對象 p 和 bucket 指針 b 的映射關係，標記和映射關係都是保存在對象的 special 記錄中，感興趣的讀者可以自行查看 setprofilebucket 源碼，本文不進行展開。

對象銷燬是在 GC 的清除階段完成的，入口是 gcSweep。跟蹤 gcSweep 流程可以在 freeSpecial 函數中看到，針對有被打上 _KindSpecialProfile 標記的對象有一個額外處理：查找到對象映射的 bucket 指針並調用了 mProf_Free。

// runtime/mheap.go
func freeSpecial(s *special, p unsafe.Pointer, size uintptr) {
  switch s.kind {
  ...
  case _KindSpecialProfile:
    sp := (*specialprofile)(unsafe.Pointer(s))
    // 調用mProf_Free，參數sp.b就是對象關聯的bucket指針
    mProf_Free(sp.b, size) 
    lock(&mheap_.speciallock)
    mheap_.specialprofilealloc.free(unsafe.Pointer(sp))
    unlock(&mheap_.speciallock)
  ...
  }
}
// runtime/mprof.go
func mProf_Free(b *bucket, size uintptr) {
  index := (mProfCycle.read() + 1) % uint32(len(memRecord{}.future))
  // b.ntsk按偏移量定位到統計信息對象地址，取出統計對象指針
  mp := b.mp()
  mpc := &mp.future[index]
  lock(&profMemFutureLock[index])
  mpc.frees++ // 自增內存回收次數
  mpc.free_bytes += size // 累加內存回收大小
  unlock(&profMemFutureLock[index])
}

mProf_Free 內部的處理就很簡單了，按偏移量從 b.nstk 中取到統計對象 mpc，調用 mpc.frees++ 和 mpc.free_bytes += size，累加回收大小和自增回收次數。

遍歷 mbuckets 中的所有 bucket 節點，就可以得到所有的內存分配和回收的採樣情況，如果某個 bucket 節點統計信息中 alloc_bytes > free_bytes，就說明該 bucket 的調用棧對應有存活狀態的對象，分配內存的大小 = alloc_bytes-free_bytes，分配內存次數 = allocs-frees；配合調用棧信息，就可以進一步分析程序的內存使用情況了。

內存採樣默認一直都在進行中，所以採樣 heap 數據對性能完全沒有影響。

   1.2.4 heap 實例分析

一般來講，內存使用量並不是後臺服務的主要瓶頸，本小節舉個簡單的優化。打開網關 heap 採樣數據，進行 top 分析如下：

排在前列的調用中有一個自定義的方法 UpdateSysCookie，它的內存分配佔比達到 3.13%。使用 source 模式搜索分析 UpdateSysCookie 方法：

可以看到，m.SysCookie = &meshkit.MMSystemReqCookie{} 這一行語句採樣到了 1.5MB 的內存分配。每次執行該方法都創建新對象，導致了較頻繁的內存分配操作。我們可以通過引入 sync.Pool 對象池來優化，代碼如下：

// poolMMSystemReqCookie syscookie對象池
var poolMMSystemReqCookie = sync.Pool{
  New: func() interface{} {
    return &meshkit.MMSystemReqCookie{}
  },
}
// getMMSystemReqCookie 從對象池中獲取syscookie對象
func getMMSystemReqCookie() *meshkit.MMSystemReqCookie {
  return poolMMSystemReqCookie.Get().(*meshkit.MMSystemReqCookie)
}
// putMMSystemReqCookie 將syscookie對象清理後放回對象池
func putMMSystemReqCookie(syscookie *meshkit.MMSystemReqCookie) {
  if syscookie == nil {
    return
  }
  cleanMMSystemReqCookie(syscookie)
  poolMMSystemReqCookie.Put(syscookie)
}
// cleanMMSystemReqCookie 清理syscookie對象中的內容
func cleanMMSystemReqCookie(syscookie *meshkit.MMSystemReqCookie) {
  syscookie.Xxx = nil
  ...
}
func (m *BaseInfo) UpdateSysCookie(fun func(*meshkit.MMSystemReqCookie)) {
  m.lock.Lock()
  defer m.lock.Unlock()
  if m.SysCookie == nil {
    // m.SysCookie = &meshkit.MMSystemReqCookie{} // 原始代碼
    m.SysCookie = getMMSystemReqCookie() // 使用對象池
  }
  fun(m.SysCookie)
}
// Clean 清理BaseInfo對象
func (m *BaseInfo) Clean() {
  ...
  // 清理BaseInfo對象的同時也將其成員m.SysCookie放回對象池
  putMMSystemReqCookie(m.SysCookie)
}

通過 getMMSystemReqCookie 方法從對象池中獲取對象，流程結束後再調用 putMMSystemReqCookie 將對象放回對象池。優化後再次分析 heap，在 top 中已經看不到 UpdateSysCookie 了，source 模式也搜索不到 UpdateSysCookie 了，因爲根本就沒采樣到該調用棧有內存分配了，優化目標達成。

   1.3 goroutine 分析 Golang 協程

   1.3.1 生成數據

   1.3.1.1 代碼直接生成

在 main 函數開頭直接加入如下代碼，就可以得到 goroutine 採樣結果 goroutine.out。

func main() {
  f, _ := os.Create('goroutine.out')
  defer f.Close()
  err := pprof.Lookup('goroutine').WriteTo(f, 1)
  if err != nil {
    log.Fatal(err)
  }
}

   1.3.1.2 通過 http 接口生成

與 profile 採樣一樣，在主路徑上引入 net/http/pprof 包，啓動 http 服務。

import (
  'net/http'
  _ 'net/http/pprof'
)
func process() {
  go func() {
    http.ListenAndServe('127.0.0.1:6060', nil) // 安全起見，使用本地地址進行監聽
  }()
    ...
}

使用 go tool pprof 命令訪問本地服務 /debug/pprof/goroutine?seconds={second}

$ go tool pprof http://127.0.0.1:6060/debug/pprof/goroutine?seconds=30
Saved profile in /root/pprof/pprof.demo.goroutine.001.pb.gz
File: demo
Type: goroutine
Time: Dec 31, 2023 at 12:59pm (CST)
Duration: 10.01s, Total samples = 4 
Entering interactive mode (type 'help' for commands, 'o' for options)
(pprof)

使用 go tool pprof 命令訪問本地服務 /debug/pprof/goroutine?debug=1

$ go tool pprof http://127.0.0.1:6060/debug/pprof/goroutine?debug=1
Saved profile in /root/pprof/pprof.demo.goroutine.001.pb.gz
Type: goroutine
Entering interactive mode (type 'help' for commands, 'o' for options)(pprof)

直接通過 http 請求到本地服務 /debug/pprof/goroutine?debug=2

$ curl http://127.0.0.1:6060/debug/pprof/goroutine?debug=2
goroutine 5879255 [select]:
google.golang.org/grpc.newClientStreamWithParams.func4()
        /home/xxx/go/pkg/mod/google.golang.org/grpc@v1.55.0/stream.go:375 +0x92
created by google.golang.org/grpc.newClientStreamWithParams
        /home/xxx/go/pkg/mod/google.golang.org/grpc@v1.55.0/stream.go:374 +0xf2a
goroutine 5879362 [IO wait]:
internal/poll.runtime_pollWait(0x7f3f84af3470, 0x72)
        /usr/local/go/src/runtime/netpoll.go:306 +0x89
internal/poll.(*pollDesc).wait(0xc0061fed80?, 0xc001353000?, 0x0)
        /usr/local/go/src/internal/poll/fd_poll_runtime.go:84 +0x32
...

   1.3.2 分析數據

使用 go tool pprof 分析 goroutine 數據的方式與 profile 一致，差別是 goroutine 用於分析所有的協程數量和協程的調用棧情況，本小節不再贅述具體的分析模式和方法。

單獨說明一下通過 http 請求直接請求 /debug/pprof/goroutine?debug=2 接口的數據分析，這個模式下不僅可以看到每一個協程的棧信息，還能看到當前協程的狀態和持續的時間（如 [running]、[select, 6 minutes]、[IO wait]、[chan receive] 等），當需要針對某一個具體的協程進行分析時可以使用該模式。

   1.3.3 goroutine 獲取數據原理分析

   1.3.3.1 太長不看版

Golang 的 newproc 函數用於創建新的協程，而新的協程對象 G 創建出來後，會通過 allgadd 函數將 G 指針添加到全局切片對象 allgs 中。通過遍歷全局切片對象 allgs 即可獲取每一個協程對象 G，並從 G 中獲取調用棧信息。

goroutine 採樣對性能的影響比 pprof 和 heap 更大。

Go1.18 及之前版本在循環遍歷獲取 goroutine 數據的整個過程中，會 stopTheWorld 停止進程的執行，生產環境需謹慎使用。

Go1.19 版本之後，在獲取 goroutine 數據過程中，只會有兩次短暫的 stopTheWorld 停止整個進程，實測對程序整體的影響不大，生產環境對性能要求不高的場景仍然可以使用。

   1.3.3.2 源碼分析

獲取 goroutine 數據的入口是 writeGoroutine，代碼如下：

// runtime/pprof/pprof.go
func writeGoroutine(w io.Writer, debug int) error {
  if debug >= 2 {
    return writeGoroutineStacks(w)
  }
  return writeRuntimeProfile(w, debug, 'goroutine', runtime_goroutineProfileWithLabels)
}

當 debug 大於等於 2 時，調用 writeGoroutineStacks 函數，否則調用 writeRuntimeProfile 函數。兩個函數流程類似，差別在於 debug 小於 2 時，會按調用棧合併統計總數。本小節分析 writeRuntimeProfile，writeGoroutineStacks 的情況讀者可以自行查看源碼。

writeRuntimeProfile 函數代碼如下：

// runtime/pprof/pprof.go
func writeRuntimeProfile(w io.Writer, debug int, name string, fetch func([]runtime.StackRecord, []unsafe.Pointer) (int, bool)) error {
  var p []runtime.StackRecord
  var labels []unsafe.Pointer
  n, ok := fetch(nil, nil) // 調用fetch獲取數量
  for {
    // 分配足夠容量的StackRecord切片p，容量比n略微大一些，防止短時間內有更多的goroutine開啓
    p = make([]runtime.StackRecord, n+10)
    labels = make([]unsafe.Pointer, n+10)
    n, ok = fetch(p, labels) // 再次調用fetch填充切片p
    if ok {
      p = p[0:n]
      break
    }
  }
  return printCountProfile(w, debug, name, &runtimeProfile{p, labels})
}

首先調用 fetch 獲取協程總量 n；

然後分配足夠容量的 StackRecord 切片 p，用於保存每一個協程的信息，容量爲 n+10，防止在獲取 n 之後又有新的 groutine 生成；

接下來是一個 for 循環，循環內部第二次調用 fetch 獲取每個協程信息填充到傳入的切片 p 中，fetch 失敗會在 for 循環內重試；

最後調用 printCountProfile 將相同棧信息的協程合併，統計總數。

fetch 是一個函數指針，指向了 goroutineProfileWithLabelsConcurrent 函數，代碼如下：

// runtime/mprof.go
func goroutineProfileWithLabelsConcurrent(p []StackRecord, labels []unsafe.Pointer) (n int, ok bool) {
  ...
  stopTheWorld('profile') // 停止整個進程
  ...
  n = int(gcount())
  ...
  if n > len(p) {
    // 傳入p爲nil時將走到這裏，直接返回n
    startTheWorld()
    semrelease(&goroutineProfile.sema)
    return n, false
  }
  // 保存當前協程的信息
  sp := getcallersp()
  pc := getcallerpc()
  systemstack(func() {
    saveg(pc, sp, ourg, &p[0])
  })
  ourg.goroutineProfiled.Store(goroutineProfileSatisfied)
  goroutineProfile.offset.Store(1)
  goroutineProfile.active = true
  goroutineProfile.records = p
  goroutineProfile.labels = labels
  ...
  startTheWorld()
  // 遍歷所有協程，記錄棧信息
  forEachGRace(func(gp1 *g) {
    tryRecordGoroutineProfile(gp1, Gosched)
  })
  stopTheWorld('profile cleanup')
  endOffset := goroutineProfile.offset.Swap(0)
  goroutineProfile.active = false
  goroutineProfile.records = nil
  goroutineProfile.labels = nil
  startTheWorld()
  forEachGRace(func(gp1 *g) {
    gp1.goroutineProfiled.Store(goroutineProfileAbsent)
  })
  ...
}

goroutineProfileWithLabelsConcurrent 函數邏輯比較清晰：

首先調用 gcount 從全局變量 allglen 中獲取協程的總數；

接下來如果參數傳入的 p 是 nil，則直接返回，對應第一次調用 fetch 獲取總數；

如果參數傳入的 p 不是 nil，就繼續調用 forEachGRace 遍歷全局變量 allgs 獲取每一個協程對象的地址，並調用 tryRecordGoroutineProfile 記錄協程信息。

我們可以看到 goroutineProfileWithLabelsConcurrent 函數調用了兩次 stopTheWorld 停止整個進程，第一次是獲取所有協程數量前，第二次是修改全局變量 goroutineProfile 之前；而中間循環獲取協程信息的過程是和其他協程併發處理的。

上面這段代碼是 Go1.19 之後的代碼邏輯。但是在 Go1.18 版本及之前，goroutine 採樣操作在整個過程中都會 stopTheWorld 停止整個進程，對應的函數是 goroutineProfileWithLabelsSync。

Go1.18 及之前的版本的 goroutine 採樣筆者沒有進行實際測試，生產環境影響不太確定，有需要請謹慎使用。

Go1.19 版本，因爲需要兩次 stopTheWorld，因此 goroutine 的性能影響要比 profile 和 heap 更大，不過實測影響也並不大，生產環境也可以使用。

   1.3.4 goroutine 實例分析

goroutine 分析比較簡單本文就不做展開了；如果想分析 goroutine 泄露問題、或者想查詢當前有多少協程以及協程是在哪個調用棧開啓的，那麼直接用 svg 圖、top 和 source 模式進行分析就能很快得出結論。

02

trace 工具詳解

上一章中分析的 pprof 工具有着廣泛的應用，可以用來很大一部分的性能問題，但是仍然有很多場景是其無法分析的。例如存在嚴重阻塞或者存在網絡 IO 瓶頸的場景，這種因爲等待而導致的性能不達標，CPU 佔用和內存消耗可能都很小，pprof 分析無能爲力，這時候就是 trace 工具大顯身手的時候了。

trace 工具可以記錄 Go 程序運行時的所有事件，例如協程的創建、結束、阻塞、解除阻塞，系統調用的進入和退出，GC 開始、結束和 stopTheWorld 等等；trace 會記錄每個事件的納秒級時間戳和調用棧信息。後續通過 trace 可視化工具打開記錄的事件信息，就可以追蹤事件的前驅後置，以及分析事件相關的協程的調度、阻塞等情況。

   2.1 生成 trace 數據

   2.1.1 代碼直接生成

在 main 函數開頭直接加入如下代碼，就可以在程序結束後得到 trace.out 數據。

func main() {
  f, _ := os.Create('trace.out')
  defer f.Close()
  trace.Start(f)
  defer trace.Stop()
  ...
}

   2.1.2 通過 http 接口生成

與 profile 採樣一樣的處理方式，在主路徑上引入 net/http/pprof 包，啓動 http 服務

import (
  'net/http'
  _ 'net/http/pprof'
)
func process() {
  go func() {
    http.ListenAndServe('127.0.0.1:6060', nil) // 安全起見，使用本地地址進行監聽
  }()
    ...
}

直接通過 http 請求到本地服務 /debug/pprof/trace 獲得 trace 數據。

$ curl http://127.0.0.1:6060/debug/pprof/trace?seconds=10 > trace.data

   2.2 分析 trace 數據

   2.2.1 打開 trace 數據

trace 數據需要通過可視化界面進行分析，使用 go tool trace -http=ip:port 啓動 http 服務，trace 解析耗時比較久，需要耐心等待。

$ go tool trace -http 127.0.0.1:9998 trace.out 
2024/01/01 16:19:26 Parsing trace...
2024/01/01 16:19:41 Splitting trace...
2024/01/01 16:20:13 Opening browser. Trace viewer is listening on http://127.0.0.1:9998

瀏覽器訪問 http://127.0.0.1:9998 可以打開可視化界面，如下圖：

頁面中包含四個主要部分，在下文將進行詳細介紹：

   2.2.2 view trace

View trace 的數據量一般較大，因此分析時只能對一小段時間片進行分析。任意進入一個時間片的 view trace 如下圖。

第一次看到這個視圖的讀者大概率會覺得眼花繚亂，是因爲時間粒度設置太大了，數據都雜在了一起；可以使用鍵盤 w/s 進行放大 / 縮小，鍵盤 a/d 進行時間軸的左移 / 右移，調整到合適的時間粒度才能進行下一步分析。

整個視圖主要分爲三部分，STAT 統計區域、PROCS 視圖區域、選中項詳情區域；其中位於最下方的選中項詳情區域是上方兩個區域的補充，鼠標選中或框選 STAT 或 PROCS 區域中帶顏色的矩形塊時，選中項詳情區會展示額外的詳細信息。

STATS 區域展示數據統計信息，從上到下依次是：

  1. 協程統計，統計不同狀態的協程數量（藍色爲 Runnable 數量，綠色爲 Running 數量）。

  2. 內存統計，統計當前分配內存大小（綠色爲 NextGC 大小，紅色爲 Allocated 大小）。

  3. 線程統計，統計不同狀態的線程數量（綠色爲 InSyscall 數量，紫紅色爲 Running 數量）。

在感興趣的統計區域鼠標左鍵選中某個時刻或框選一段時間範圍，選中項詳情區域會展示更詳細的信息。比如選中協程統計後，選中項詳情區域將展示不同狀態的協程具體的數量如下圖。

PROCS 是最複雜的部分，展示了採樣週期內所有處理器上的所有事件。配合選中項詳情區域可以得到很多信息。

按 s 鍵縮小視圖可以對 GC 情況大致進行分析，上圖是一個示例，可以看到該採樣時間片內只執行了一次 GC，GC 持續時間 62ms，佔用了 3 個協程來進行 GC。

按 w 鍵放大視圖，可以對協程調度和阻塞情況進行分析，上圖是單擊選中運行在 Proc 8 上的 G889532 這個協程的結果。

查看下方的詳情區域，左側是基本信息，可以看到該協程執行了 687 微秒後被切換出了執行隊列，而 End Stack Trace 顯示，切換前協程調用棧位置在 runtime.chanrecv1，是一個 channel 的出隊操作；

詳情區域右側是相關的 Events 事件，其中 Incoming flow 是導致該協程 unblock 解除阻塞的事件，兩個 Outgoing flow 是指該協程的執行有導致兩個後續 unblock 解除阻塞事件發生；接下來的 Preceding events、Following events 和 All connected events，分別代表所有的前驅事件鏈、後繼事件鏈和所有相關的事件鏈。

鼠標懸停到 Link 列上，會出現箭頭表明事件的前驅後置關係。點擊 Link 列會展示更多事件流的信息。下圖展示的是點擊 Incoming flow 後的例子，圖中的紅色小箭頭，代表導致 G889532 協程 unblock 事件發生在 G890930 協程。下方詳情區域的紅框標明瞭 From 和 To 也說明了這一點，另外可以看到 From 事件的調用棧在 net/http.(*persistConn).readLoop:2218 上，可知是 G890930 協程中 http 請求收到響應的後續處理導致了 G889532 協程的解除阻塞 unblock，分析源碼可以看到實際上是一個 select 操作導致的。

   2.2.3 Profiles

profiles 包含了四種數據類型

打開後是四種數據類型的 svg 矢量圖分析，分析方式與 profile 中的 svg 矢量圖一致，不再贅述。

   2.2.4 Goroutine analysis

打開 goroutine 分析如下，每一行是按協程調用棧彙總統計的協程數量。

點擊左側調用棧可以查看每一個的協程及其統計數據，包括協程彙總的執行時間、網絡等待時間、同步阻塞時間、調度等待時間、GC 清掃時間和 GC 總時間。

繼續點擊 Goroutine 列可以進入 view trace 視圖，進入指定協程的 view trace 視圖。

goroutine 分析與 profile 裏的 goroutine 分析都是對協程的分析，不過分析角度不盡不同；profile 的 goroutine 用於協程調用棧和狀態的分析，而 trace 中的 goroutine 關注的是協程發生的事件和各種阻塞的時間。

   2.2.5 minimum mutator utilization

minimum mutator utilization（mmu）是評價 GC 的重要指標，進入 minimum mutator utilization 分析界面如下圖：

橫座標表示時間窗口，縱座標 mmu 是指除了 GC 外程序佔用 CPU 的最小的比例；在曲線上單擊鼠標，可以在下方展示更多的信息。

用一個例子來說明，上圖選中了橫座標 811.13μs 這個點，其對應的縱座標是 0；表明在 811.13μs 的時間窗口內，除了 GC  外，程序佔用 CPU 最小值爲 0%，也就是說存在一個 811.13μs 的時間範圍，該時間範圍內整個程序除了 GC 外什麼事情都沒做。上圖下方的列表列出了按 CPU 佔用率從低到高的幾個時間窗口信息，第一條 0.000 的這一個時間窗口發生在開始時間 244ms 左右；點擊該條目進入 view trace 視圖並放大如下圖，可以看到原來是一次長達 811.13μs 的 stopTheWorld 停止了整個進程導致的。

我們還需要關注的是 mmu 曲線隨橫座標變大而趨於穩定的 mmu 值，這個值越大越好，上上圖 1s 刻度上 mmu 值爲 0.9725；這個值可以近似的代表整個程序運行過程中 GC 的 CPU 佔用率 = 1-0.9725=2.75%。

在 1.4.2 小節中說明了通過調整 GOGC 配置進行 GC 優化，優化前後分別使用 minimum mutator utilization 進行分析，通過曲線的變化趨勢，也可以分析出 GC 的 CPU 佔用率的優化情況。

   2.3 trace 獲取數據原理

   2.3.1 太長不看版

trace 包中定義了 50 種不同類型的事件 Event。Go 源碼中針對所有的這些事件，都添加了 traceEvent 的埋點代碼。

當用戶請求 /debug/pprof/trace 接口時，埋點開關將變成 true；開關打開後所有的埋點代碼都會被執行，而 traceEvent 就會將當前執行的協程 id、Proc id、埋點的額外參數、調用棧信息和事件類型一起，記錄到緩衝區裏；而另一個新建的協程會從緩衝區中循環讀取數據，並寫到 http 響應中。

解析所有的事件，就可以得到 view trace、Goroutine analysis、profile 和 mmu 信息。

開啓 trace 後會嚴重影響程序性能，至少在 30% 以上，記錄的事件越多性能性能越嚴重，生產環境需謹慎使用。

   2.3.2 源碼分析

首先分析一下埋點代碼，以開啓 gc 的入口函數 gcStart 爲例子進行說明，代碼如下：

// runtime/mgc.go
func gcStart(trigger gcTrigger) {
  ...
  if trace.enabled {
    traceGCStart()
  }
  ...
  if trace.enabled {
    traceGCSTWStart(1)
  }
  ...
}
// runtime/trace.go
func traceGCStart() {
  traceEvent(traceEvGCStart, 3, trace.seqGC)
  trace.seqGC++
}
func traceGCSTWStart(kind int) {
  traceEvent(traceEvGCSTWStart, -1, uint64(kind))
}
func traceEvent(ev byte, skip int, args ...uint64) {...}

代碼中的 trace.enabled 就是開啓 trace 的開關。開關開啓後，埋點代碼 traceGCStart 和 traceGCSTWStart，都會被執行。

所有的埋點代碼都會調用 traceEvent 函數。traceEvent 的參數 ev 傳遞當前的事件類型，skip 是跳過棧的層級數，args 是可變的額外參數。

traceEvent 內部不進行詳細分析，可以預期到其內部一定會調用到我們的老熟人 gentraceback 函數獲取棧信息；在獲得了協程 id、執行器 id、傳入的額外參數、調用棧信息和事件類型等所需數據後，traceEvent 將數據以及當前的納秒時間戳寫入緩衝區 traceBuf 中；traceBuf 是一個無鎖的併發安全的緩衝區，類似上文中提到過的 profBuf，可以用來進行高效的讀寫。

通過 http 接口請求 /debug/pprof/trace，打開開啓 trace；入口在 Trace 函數，Trace 函數中調用 trace.Start 函數開啓 trace，sleep 一段時間後，調用 trace.Stop 關閉了 trace，代碼如下：

// net/http/pprof/pprof.go
func init() {
  ...
  http.HandleFunc('/debug/pprof/trace', Trace)
}
func Trace(w http.ResponseWriter, r *http.Request) {
  ...
  if err := trace.Start(w); err != nil {
    ...
  }
  sleep(r, time.Duration(sec*float64(time.Second)))
  trace.Stop()
}
// runtime/trace/trace.go
func Start(w io.Writer) error {
  tracing.Lock()
  defer tracing.Unlock()
  // 調用runtime.StartTrace
  if err := runtime.StartTrace(); err != nil {
    return err
  }
  go func() {
    // 開啓一個協程循環讀取緩衝區並寫入http響應
    for {
      data := runtime.ReadTrace()
      if data == nil {
        break
      }
      w.Write(data)
    }
  }()
  tracing.enabled.Store(true) // 打開埋點開關
  return nil
}
func Stop() {
  tracing.Lock()
  defer tracing.Unlock()
  tracing.enabled.Store(false) // 關閉埋點開關
  runtime.StopTrace()
}

trace.Stop 很簡單，調用 tracing.enabled.Store(false) 來關閉埋點開關；

trace.Start 首先調用了 runtime.StartTrace 函數，接下來開啓了一個協程循環讀取緩衝區並寫入 http 響應中，最後調用 tracing.enabled.Store(true) 打開了埋點開關。後兩步很好理解，我們看一下 runtime.StartTrace 做了什麼：

func StartTrace() error {
  stopTheWorldGC('start tracing') // 停止整個協程
  ...
  forEachGRace(func(gp *g) {
    status := readgstatus(gp)
    if status != _Gdead {
      ...
      traceEvent(traceEvGoCreate, -1, gp.goid, uint64(id), stackID)
    }
    if status == _Gwaiting {
      ...
      traceEvent(traceEvGoWaiting, -1, gp.goid)
    }
    if status == _Gsyscall {
      ...
      traceEvent(traceEvGoInSyscall, -1, gp.goid)
    } else if status == _Gdead && gp.m != nil && gp.m.isextra {
      ...
      traceEvent(traceEvGoCreate, -1, gp.goid, uint64(id), stackID)
      gp.traceseq++
      traceEvent(traceEvGoInSyscall, -1, gp.goid)
    } else {
      gp.sysblocktraced = false
    }
  })
  ...
  startTheWorldGC()
  return nil
}

可以看到函數內首先調用了 stopTheWorldGC 停止整個進程；然後調用 forEachGRace 來遍歷所有的協程，對每個協程，根據協程當前不同的狀態，調用 traceEvent 記錄了不同的事件；最後再調用 startTheWorldGC 啓動整個進程。這一大堆操作其實是在補充已經無法追蹤的事件；已經發生過的協程事件，自然是沒有記錄的，爲了讓整個 trace 完整，需要做這個初始化處理。

有了這些數據，就能夠繪製 view trace 了，例如通過協程的開始、結束、阻塞和解除阻塞事件，就能畫出 view trace 裏協程的一個個小矩形塊了。

但是仍然有一個疑問就是：Incoming flow 和 Outcoming flow 是怎麼關聯上的呢？其實也很簡單，就是上文中的額外參數傳遞的。

以 channel 的入隊處理爲例子進行說明；瞭解 channel 使用的讀者肯定知道，當 channel 爲空時，出隊操作將一直阻塞到有入隊操作發生後纔會解除阻塞。查看入隊操作源碼如下：

// runtime/chan.go
func chansend(c *hchan, ep unsafe.Pointer, block bool, callerpc uintptr) bool {
  ...
  if sg := c.recvq.dequeue(); sg != nil {
    // Found a waiting receiver. We pass the value we want to send
    // directly to the receiver, bypassing the channel buffer (if any).
    send(c, sg, ep, func() { unlock(&c.lock) }, 3)
    return true
  }
  ...
}

在 chansend 函數中，嘗試調用 c.recvq.dequeue 得到一個正在等待狀態的接收者對象 sudog，並調用 send 函數將數據傳遞給接受者，同時會調用 ready 函數將接收者協程喚醒。在 trace.enabled 爲 true 時，send 函數將一路調用到 traceGoUnpark 埋點函數如下：

// runtime/trace.go
func traceGoUnpark(gp *g, skip int) {
  pp := getg().m.p
  gp.traceseq++
  if gp.tracelastp == pp {
    traceEvent(traceEvGoUnblockLocal, skip, gp.goid)
  } else {
    gp.tracelastp = pp
    traceEvent(traceEvGoUnblock, skip, gp.goid, gp.traceseq)
  }
}

可以看到 traceEvent 第三個參數傳遞的是 gp.goid，而 gp.goid 正是 send 函數傳遞的接收者對象 sg 中保存的協程 id。通過額外參數傳遞解除阻塞的協程 id，再加上當前的棧信息，我們就能知道是當前協程中的 chansend 調用，導致了另一個協程的 unblock 解除阻塞事件發生了。

因爲每一個事件都要執行埋點代碼，所以開啓 trace 對性能影響非常大，事件越多影響越大，預期至少是 30% 以上的額外性能開銷，trace 在生產環境中請謹慎使用。

   2.4 trace 實例

本小節分析的例子來自 github 上一個很經典的例子 justforfunc-22，強烈建議讀者也去看看原作者的博客原文；不過原博文的分析深度略顯不足，本節借用這個優化實例進行更深入的分析。

   2.4.1 原始代碼及 trace 分析

原始代碼用於生成一張曼德勃羅特圖片，是一種複雜的幾何圖形，我們這裏並不關心圖片生成的具體算法，只需要知道圖中每一個點的像素值和該點的座標 x、y 及圖片大小 w、h 有關。原始代碼如下：

func main() {
  // 開啓trace輸出到stdout上
  trace.Start(os.Stdout)
  defer trace.Stop()
  // 創建待生成的圖片文件
  f, err := os.Create(output)
  if err != nil {
    log.Fatal(err)
  }
  // 生成曼德勃羅特圖
  img := createSeq(width, height)
  // 保存圖片到文件
  if err = png.Encode(f, img); err != nil {
    log.Fatal(err)
  }
}
// CreateSeq 生成曼德勃羅特圖的原始代碼
func createSeq(width, height int) image.Image {
  // 創建image對象
  m := image.NewGray(image.Rect(0, 0, width, height))
  // for循環串行
  for i := 0; i < width; i++ {
    for j := 0; j < height; j++ {
      // 調用pixel按照曼德勃羅特圖的規則計算像素值大小
      // m.Set將像素值設置到image對象m中，該操作是併發安全的
      m.Set(i, j, pixel(i, j, width, height)) 
    }
  }
  return m
}

createSeq 函數是原始的生成算法，使用一個 for 循環，串行的調用 pixel 函數計算每一個像素點的像素值，並保存到 image 對象中。

原始代碼的執行時間是 3.992s。打開 trace，查看 view trace 的情況：

可以看到，雖然一共有 5 個 Proc 在進行調度，但是從頭到位只有一個協程 G1 在 Proc 0 上執行代碼，這顯然是效率低下的。

   2.4.2 優化一 chan 並行化

針對原始代碼的串行問題，可以很容易的想到併發來優化。justforfunc-22 中給出了一種經典的生產者 + 工作者的優化方案，代碼如下：

// createWorkers 並行優化
func createWorkers(width, height int) image.Image {
  // 創建image對象
  m := image.NewGray(image.Rect(0, 0, width, height))
  type px struct{ x, y int }
  c := make(chan px)  // 注意c沒有甚至緩衝區
  var w sync.WaitGroup
  // numWorkers爲8，創建8個工作者
  for n := 0; n < numWorkers; n++ {
    w.Add(1)
    go func() {
      // 從channel出隊像素對象並處理
      for px := range c {
        m.Set(px.x, px.y, pixel(px.x, px.y, width, height))
      }
      w.Done()
    }()
  }
  // 遍歷每一個像素點
  for i := 0; i < width; i++ {
    for j := 0; j < height; j++ {
      // 向channel中入隊像素對象
      c <- px{i, j}
    }
  }
  close(c)
  w.Wait()
  return m
}

createWorkersBuffered 函數中創建了一個緩衝區容量爲 0 的 channel，主協程循環向 channel 中入隊所有需要計算的像素點座標對象 px；另外開啓了 8 個工作者協程，循環從 channel 中出隊座標對象，並計算像素值。

優化一的執行時間是 3.018 秒，相比串行執行 4 秒左右的耗時並沒有達到預期的提升，打開 view trace 分析一下：

圖中可以看到，一共有 8 個處理器在運行我們的程序，但是肉眼可見每個 Proc 都沒有跑滿，有大量間隙存在。我們放大 trace 查看，鼠標選中主協程 G1，將鼠標懸停到 Following Events 上，如下圖：

可以看到有時候主協程 G1 runtime.main 和其他協程在並行執行，如綠框內的時間段；但是有時候主協程卻會和另一個協程串行調度，同時沒有其他的協程在並行執行，如圖中紅框的時間段。爲什麼會這樣呢？

我們知道沒有緩衝容量的 channel 有一個特性，出隊操作時如果沒有發送者則出隊協程會阻塞，同樣入隊操作時如果沒有接收者則入隊協程也會阻塞。這個特性導致了兩個比較嚴重的問題。

第一個問題，當某個時刻有多個工作者協程都在執行 channel 出隊操作時，最多隻能有一個協程可以不被阻塞的拿到數據，其他協程將全部進入 waiting 阻塞狀態。從上圖中綠框部分可以看到，不同顏色每一個的 worker 協程都沒有連續的執行，在短暫的執行之後變成了 waiting 阻塞狀態。而大部分協程被阻塞後，可能導致很多 Proc 上沒有 runnable 的協程可供調度，此時 Proc 會觸發 runtime.stealwork 從其他協程上 “竊取” 協程，而如果 “竊取” 也無法獲得 runnable 的協程，Proc 會變成空閒狀態（觸發 proc stop 事件），並將把關聯的線程變成自旋態（spnning），甚至會暫止線程（park）；等到後有續協程重新變爲 runnable 狀態後，空閒的 Proc 又需要重新變爲忙碌狀態，並將自旋態的線程恢復或者重新復始一個線程。大部分的協程頻繁的阻塞和解除阻塞，會增加調度器的負擔，導致調度延遲增加。

我們可以在 trace 中找到相關的證據。下圖的 view trace 中，有很多 proc stop 的事件發生；同時查看上方的統計區域，可以看到藍框中的 runnable 狀態的協程越來越多但是都沒有及時的得到調度；而綠框中的線程總數一直在變化，代表了一直有線程被開啓和被暫停。

如果同時使用 pprof 進行 profile 分析，也可以在 svg 圖中看到很多調度相關的節點，例如 runtime.stealwork 和 runtime.park_m 等等，感興趣的讀者可以自行實踐一下。

第二個問題，當大量 worker 協程因爲調度慢原因沒有被執行時，主協程會因 channel 入隊操作沒有接收者而阻塞。此時主線程所在的 Proc 會 “竊取” 一個 runnable 的協程並執行。該協程處理完當前的像素點後，再次執行到 channel 出隊，又變爲阻塞，同時將主協程解除阻塞。主協程再一次執行到 channel 入隊，又再一次變爲阻塞，同時將 worker 協程再次解除阻塞。這就導致了上文中描述的主協程和某一個 worker 協程串行循環調度的情況發生。這個循環將一直持續到其它 Proc 上有 worker 協程執行爲止。入隊的阻塞也降低了程序效率。

總結一下，channel 沒有緩衝區導致的調度延遲大大增加是程序執行慢的主要原因。打開 goroutine 分析，點開 worker 線程，可以看到每個工作協程的調度等待時間都是最長的（開啓 trace 會放大調度延遲，但是即使關閉 trace，調度延遲仍然是一個最大的影響因素）。

   2.4.3 優化二 buffer chan

優化的方向很明顯，我們在 channel 在初始化時分配足夠的緩衝區，優化代碼如下：

func createWorkersBuffered(width, height int) image.Image {
  m := image.NewGray(image.Rect(0, 0, width, height)) 
  type px struct{ x, y int }
  c := make(chan px, width*height) // 修改這裏，緩衝區大小爲width*height
  var w sync.WaitGroup
  for n := 0; n < numWorkers; n++ {
    w.Add(1)
    go func() {
      for px := range c {
        m.Set(px.x, px.y, pixel(px.x, px.y, width, height))
      }
      w.Done()
    }()
  }
  for i := 0; i < width; i++ {
    for j := 0; j < height; j++ {
      c <- px{i, j}
    }
  }
  close(c)
  w.Wait()
  return m
}

優化後，程序執行時間爲 1.899s，比上一步提升了很多。進入 view trace，相比上一步 view trace 要漂亮多了，9 個處理器均勻的在調度執行我們的代碼，goroutine、threads 統計區域裏也是完美的綠色和紫色矩形，除了剛開始的 350ms。

剛開始的 350ms 顯然是有阻塞問題的，放大 trace 來看一看：

在上圖中，我們看到所有的 worker 協程所在的 Proc 都發生了 proc stop 事件，再配合 worker 協程的調用棧是 runtime.chanrecv，我們可以得出結論：主協程處理入隊太慢了。worker 協程出隊操作時，channel 裏一個數據都沒有，所以全部阻塞了。等後續主協程慢慢入隊後，worker 協程才能一個接一個的重新開始執行。

爲什麼這個現象只出現在 350ms 之前呢？猜測可能是因爲 m.Set 設置的圖片像素點多了之後，操作耗時增加，worker 協程操作速度比主協程慢了，所以不再出現了。

總結一下，入隊速度慢於出隊速度，導致 worker 協程出現阻塞。打開 Synchronization blocking 如下圖，runtime.chanrecv2 阻塞了 90.12ms，這就是阻塞的帶來的額外耗時。

   2.4.4 優化三 buffer chan + 減少入隊 / 出隊次數

爲了解決上一步驟中前 350ms 的入隊速度慢的問題，justforfunc-22 給出了一個巧妙的優化方案，將圖片的一整列進行入隊，而在出隊任務中循環處理該列中的每一個像素點。優化後，入隊次數等於圖片的寬 w，大大減少了出入隊次數。代碼如下：

func createColWorkersBuffered(width, height int) image.Image {
  m := image.NewGray(image.Rect(0, 0, width, height))
  c := make(chan int, width) // 緩衝區容量爲width，只需要入隊width個任務
  var w sync.WaitGroup
  for n := 0; n < numWorkers; n++ {
    w.Add(1)
    go func() {
      for i := range c {
        // 循環處理每一個列的數據
        for j := 0; j < height; j++ {
          m.Set(i, j, pixel(i, j, width, height))
        }
      }
      w.Done()
    }()
  }
  // 只需要將每一列入隊
  for i := 0; i < width; i++ {
    c <- i
  }
  close(c)
  w.Wait()
  return m
}

優化後代碼執行時間爲 0.916s。打開 view trace，350ms 之前的阻塞問題不存在了，出現了完美的 trace。

至此我們完成了所有的優化操作。但是！眼尖的讀者應該也注意到了，我們上一步分析中 chanrecv 導致的阻塞耗時是 90ms，但是優化後的實際耗時從 1.9s 降低到了 0.9s，性能爲什麼比上一步整整提升了一倍？

從阻塞方面來分析確實性能並不能提升 1 倍，但是別忘了 chanrecv 操作本身的 CPU 消耗，掏出 profile 再分析一下優化二中的 CPU 消耗情況如下圖：

可以看到在優化二的代碼中，chanrecv 函數內部調用的 runtime.procyield 函數，CPU 採樣佔比居然超過了 pixel，高達 44%。procyield 用來實現 channel 內部的自旋鎖，大量的 chanrecv 操作導致了大量的自旋鎖等待；優化三中大大減少 chanrecv 的調用次數，這是程序性能能夠翻倍的原因。至此我們完成了所有的優化分析。

03

總結

每一個 Golang 程序員，都應該學會 pprof 和 trace 工具的使用，掌握了這兩個工具就足夠應對絕大部分場景的 Golang 程序性能問題。

本文從使用方法、原理和實例三個方面對 pprof 和 trace 兩個工具進行分析說明，其中有很多內容是筆者自己的理解總結，錯誤是難以避免的，如有錯漏之處還請評論區留言指正~

原創作者 | 廖迪

本文由 Readfog 進行 AMP 轉碼，版權歸原作者所有。
來源：https://mp.weixin.qq.com/s/wLPfiJ0wKH3DrBJS4yxeHw

猜你喜歡