Go 中的阻塞分析

Go 中的阻塞分析

---

• 原文地址：https://github.com/DataDog/go-profiler-notes/blob/main/block.md
• 原文作者：felixge
• 本文永久連結：https://github.com/gocn/translator/blob/master/2021/w43_Block_Profiling_in_Go.md
• 譯者：lsj1342
• 校對：laxiaohong

---

描述

Go 中的阻塞分析有助於您分析程式在等待下列阻塞操作上的花費時間：

• select
• chan send
• chan receive
• semacquire ( Mutex.Lock, RWMutex.RLock , RWMutex.Lock, WaitGroup.Wait)
• notifyListWait ( Cond.Wait)

只有當 Go 通過將 goroutine 置於等待狀態來暫停執行時，時間才會被跟蹤。例如 Mutex.Lock()，如果鎖可以立即或通過少量自旋被獲得，那麼這樣的操作將不會出現在您的分析結果中。

上面的操作是 Go 執行時使用的等待狀態的子集，下面的操作將不會出現在分析檔案中：

• time.Sleep（但是 time.After, time.Tick 和其他封裝了 channel 的操作會顯示出來）
• 垃圾回收
• 系統呼叫（例如網路 I/O，檔案 I/O 等）
• 執行時內部鎖（例如 stopTheWorld）
• cgo 阻塞呼叫
• 永遠阻塞的事件（例如在 nil 通道上傳送/接收）
• 阻止尚未完成的事件

在某些場景下， Goroutine Profiling (debug=2) 可能是阻塞分析的一個很好的文件，因為它涵蓋了所有等待狀態，並且可以顯示尚未完成且正在進行的阻塞事件。

用法

阻塞分析器預設是被禁用的。您可以通過按下面方式通過傳遞 rate > 0 來啟用它。

runtime.SetBlockProfileRate(rate)

引數 rate 會影響分析器的精度和開銷。在文件中，rate 是這樣描述的：

SetBlockProfileRate 控制 goroutine 阻塞事件在阻塞分析中的比例。分析器旨在對每個阻塞事件耗時以納秒級進行平均取樣。

如果想要囊括全部的阻塞事件，可將 rate 置為 1。完全關閉則置為 0。

就個人而言，我很難理解第二句。我更喜歡這樣描述 rate （又名 blockprofilerate）：

• rate <= 0 完全禁用分析器（預設設定）
• rate == 1 跟蹤每個阻塞事件，不論事件的 duration 是多少。
• rate => 2 設定納秒取樣率。每一個 duration >= rate 的事件都能被追蹤到。對於 duration < rate 的事件，分析器將會隨機取樣 duration / rate 的事件。例如，假設您的事件耗時 100ns ，rate 值設為 1000ns ，那麼事件就有 10% 的概率被分析器追蹤。

阻塞持續時間在程式的整個生命週期內聚合（啟用分析時）。要獲取導致阻塞事件及其累積持續時間的當前堆疊資訊的 pprof 格式的快照，您可以呼叫：

pprof.Lookup("block").WriteTo(myFile, 0)

為了方便，你可以使用 github.com/pkg/profile 或 net/http/pprof 通過 http 檢視分析，再或者使用持續分析器 在生產環境中自動收集資料。

此外，您可以使用runtime.BlockProfile API 以結構化格式獲取相同的資訊。

開銷

當 blockprofilerate >= 10000 (10µs) 時，對生產環境應用的影響可以忽略不計，也包括那些爭搶非常嚴重的應用。

實現細節

阻塞分析基本是在 Go 執行時內部實現的（有關程式碼，可以點選描述中的連結）。

func chansend(...) {
  var t0 int64
  if blockprofilerate > 0 {
    t0 = cputicks()
  }
  // ... park goroutine in waiting state while blocked ...
  if blockprofilerate > 0 {
    cycles := cputicks() - t0
    if blocksampled(cycles) {
      saveblockevent(cycles)
    }
  }
}

這意味著如果您未啟用阻塞分析，由於 CPU 分支預測，開銷實際上是 0。

當開啟阻塞分析時，每一個阻塞操作都會有兩個 cputicks() 呼叫的開銷。在 amd64 上，這是通過使用了 RDTSC 指令 優化後的彙編來完成的，並且在我的機器上花費了可忽略不計的 ~10ns/op 。

根據設定的 blockprofilerate（在精度一節有更多相關內容），阻塞事件最終可能會被儲存。這意味著堆疊跟蹤資訊被收集，此動作在我的機器 上耗時~1µs（堆疊深度=16）。通過增加相關 blockRecord 計數和週期的方式，堆疊會作為鍵更新一個內部雜湊表。

type blockRecord struct {
    count  int64
    cycles int64
}

更新雜湊表的開銷大概和收集堆疊跟蹤資訊差不多，不過我還沒測過。

基準

不管怎樣，就您的應用程式開銷而言，所有這些意味著什麼？這通常意味著阻塞分析是低開銷的。除非您的應用程式由於爭用而花費幾乎所有時間暫停和取消暫停 goroutine，這樣的話即使對每個阻塞事件進行了取樣，您也可能無法看到可衡量的影響。

話雖如此，下面的基準測試結果（詳情見Methodology ）會讓您瞭解到阻塞分析在理論最壞情況下的開銷。圖 chan(cap=0) 展示了通過無緩衝通道傳送訊息時blockprofilerate 從 1 到 1000 的工作負載 ，可看到吞吐量顯著的下降。圖 chan(cap=128) 使用的是緩衝通道，開銷大大減少，所以對於不會將所有時間耗費在通道通訊開銷上的應用程式可能是無關緊要的。

值得注意的是，我無法基於負載看到互斥鎖的開銷。我認為是互斥鎖在爭搶時在暫停 goroutine 之前使用的是自旋鎖。如果有人對在 Go 中能表現出非自旋鎖爭搶的工作負載方面有好的想法，請告訴我！

無論如何，請記住，下圖顯示了專門設計用於觸發您可以想象的最壞阻塞分析開銷的工作負載。實際應用程式通常不會看到顯著的開銷，尤其是在使用 blockprofilerate>= 10000(10µs) 時。

記憶體使用情況

阻塞分析利用共享雜湊表進行對映，即使表為空時也會使用 1.4 MiB 記憶體。除非您在程式中明確禁用堆分析，否則無論您是否使用了阻塞分析器，雜湊表都會被分配記憶體。

此外，每個唯一的堆疊跟蹤都會佔用一些額外的記憶體。runtime.MemStats 的 BuckHashSys 欄位允許您在執行時檢查使用情況。未來，我可能會嘗試提供有關這方面的其他資訊以及真實資料。

時間初始化

第一次呼叫 runtime.SetBlockProfileRate() 會耗費 100ms是因為它試圖測量掛鐘和TSC時鐘之間的速度比率。然而，最近關於非同步搶佔的更改破壞了此程式碼，因此現在該呼叫耗時僅在 ~10ms。

精度

取樣偏差

在 Go 1.17 之前，阻塞分析器偏向於不頻繁的長事件而不是頻繁的短事件。一個詳細的分析說明此問題。

時間戳計數器

amd64 和其他平臺使用 TSC 實現了cputicks() 功能。這種技術歷來受到頻率縮放和其他型別 CPU 功率轉換問題的挑戰。現代 CPU 提供不變的 TSCs ，但是仍有一些 Go 語言使用者在提出該問題。我不知道這些是否是由於硬體損壞還是多路系統問題所引入的，但希望將來對此進行更多研究。

另請注意時間初始化部分中的錯誤描述，可能會影響將 cputicks 轉換為掛鐘時間的精度。

堆疊深度

阻塞分析的最大堆疊深度為32。在更深的堆疊深度發生的阻塞事件仍將包含在阻塞分析中，但是結果資料可能就很難被處理了。

自旋鎖

如前所述，存在爭搶的 Go 互斥鎖將先自旋一段時間，然後才服從排程器程式。如果自旋成功，阻塞事件就會跟蹤不到。所以阻塞分析器更偏向於持續時間較長的事件。

? 本節需要更多的研究，我將在互斥分析器筆記中做這些研究。

與掛鐘時間的關係

阻塞時間不受掛鐘時間的限制。多個 goroutine 可以同時花費時間阻塞，這意味著分析中可以看到累積的阻塞持續時間超過程式執行時間。

與互斥分析的關係

Go 中的互斥分析功能與阻塞分析功能重疊，似乎兩者都可以用來理解互斥量爭用。使用互斥分析器時，它會報告 Unlock() 的呼叫點，而阻塞分析中會報告 Lock() 的呼叫點。互斥量分析器還使用了更簡單且可能是無偏的取樣機制，這應該使其更準確。但是，互斥分析器不包括通道爭用，因此阻塞分析器更靈活一些。當互斥和阻塞分析器都啟用時，跟蹤重複的爭用事件可能會浪費一些開銷。

? 本節需要更多的研究，我將在互斥分析器筆記中做這些研究。

分析器標籤

阻塞分析器目前不支援分析器標籤，但這在未來很有可能被實現。

pprof 輸出

下面是一個以 pprof 的 protobuf 格式編碼的阻塞分析示例。有兩種值型別：

• contentions/count
• delay/nanoseconds

用於建立分析檔案的blockprofilerate 沒有包括在這裡，也不屬於分析器標籤。

$ go tool pprof -raw block.pb.gz 
PeriodType: contentions count
Period: 1
Time: 2021-02-08 14:53:53.243777 +0100 CET
Samples:
contentions/count delay/nanoseconds
      22820  867549417: 1 2 3 4 
      22748  453510869: 1 2 5 4 
Locations
     1: 0x10453af M=1 runtime.selectgo /usr/local/Cellar/go/1.15.6/libexec/src/runtime/select.go:511 s=0
     2: 0x10d082b M=1 main.simulateBlockEvents /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/block-sample/main.go:71 s=0
     3: 0x10d0b72 M=1 main.eventB /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/block-sample/main.go:57 s=0
             main.run.func2 /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/block-sample/main.go:33 s=0
     4: 0x10d01b8 M=1 golang.org/x/sync/errgroup.(*Group).Go.func1 /Users/felix.geisendoerfer/go/pkg/mod/golang.org/x/sync@v0.0.0-20201207232520-09787c993a3a/errgroup/errgroup.go:57 s=0
     5: 0x10d0b12 M=1 main.eventA /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/block-sample/main.go:53 s=0
             main.run.func1 /Users/felix.geisendoerfer/go/src/github.com/felixge/go-profiler-notes/examples/block-sample/main.go:30 s=0
Mappings
1: 0x0/0x0/0x0   [FN]

歷史

阻塞分析由 Dmitry Vyukov 實現，並首次出現在 go1.1 版本 (2013-05-13) 中。

免責宣告

我是 felixge，就職於 Datadog ，主要工作內容為 Go 的持續效能優化 。你應該瞭解下。我們也在招聘: ).

本頁面的資訊可認為正確，但不提供任何保證。歡迎反饋！