『每周譯Go』Go 中的阻塞分析

Go 中的阻塞分析有助于您分析程序在等待下列阻塞操作上的花費(fèi)時(shí)間：

• select
• chan send
• chan receive
• semacquire ( Mutex.Lock, RWMutex.RLock , RWMutex.Lock, WaitGroup.Wait)
• notifyListWait ( Cond.Wait) 只有當(dāng) Go 通過將 goroutine 置于等待狀態(tài)來暫停執(zhí)行時(shí)，時(shí)間才會(huì)被跟蹤。例如 Mutex.Lock()，如果鎖可以立即或通過少量自旋被獲得，那么這樣的操作將不會(huì)出現(xiàn)在您的分析結(jié)果中。

上面的操作是 Go 運(yùn)行時(shí)使用的等待狀態(tài)的子集，下面的操作將不會(huì)出現(xiàn)在分析文件中：

• time.Sleep（但是 time.After, time.Tick 和其他封裝了 channel 的操作會(huì)顯示出來）
• 垃圾回收
• 系統(tǒng)調(diào)用（例如網(wǎng)絡(luò) I/O，文件 I/O 等）
• 運(yùn)行時(shí)內(nèi)部鎖（例如 stopTheWorld）
• cgo 阻塞調(diào)用
• 永遠(yuǎn)阻塞的事件（例如在 nil 通道上發(fā)送/接收）
• 阻止尚未完成的事件

在某些場(chǎng)景下， Goroutine Profiling (debug=2) 可能是阻塞分析的一個(gè)很好的文檔，因?yàn)樗w了所有等待狀態(tài)，并且可以顯示尚未完成且正在進(jìn)行的阻塞事件。

阻塞分析器默認(rèn)是被禁用的。您可以通過按下面方式通過傳遞 rate > 0 來啟用它。

runtime.SetBlockProfileRate(rate)

參數(shù) rate 會(huì)影響分析器的精度和開銷。在文檔中，rate 是這樣描述的：

SetBlockProfileRate 控制 goroutine 阻塞事件在阻塞分析中的比例。分析器旨在對(duì)每個(gè)阻塞事件耗時(shí)以納秒級(jí)進(jìn)行平均采樣。如果想要囊括全部的阻塞事件，可將 rate 置為 1。完全關(guān)閉則置為 0。

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

• rate <= 0 完全禁用分析器（默認(rèn)設(shè)置）
• rate == 1 跟蹤每個(gè)阻塞事件，不論事件的 duration 是多少。
• rate => 2 設(shè)置納秒采樣率。每一個(gè) duration >= rate的事件都能被追蹤到。對(duì)于 duration < rate 的事件，分析器將會(huì)隨機(jī)采樣 duration / rate 的事件。例如，假設(shè)您的事件耗時(shí) 100ns ，rate 值設(shè)為 1000ns ，那么事件就有 10% 的概率被分析器追蹤。

阻塞持續(xù)時(shí)間在程序的整個(gè)生命周期內(nèi)聚合（啟用分析時(shí)）。要獲取導(dǎo)致阻塞事件及其累積持續(xù)時(shí)間的當(dāng)前堆棧信息的 pprof 格式的快照，您可以調(diào)用：

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

為了方便，你可以使用 github.com/pkg/profile 或 net/http/pprof 通過 http 查看分析，再或者使用持續(xù)分析器 在生產(chǎn)環(huán)境中自動(dòng)收集數(shù)據(jù)。

此外，您可以使用runtime.BlockProfile API 以結(jié)構(gòu)化格式獲取相同的信息。

當(dāng) blockprofilerate >= 10000 (10μs) 時(shí)，對(duì)生產(chǎn)環(huán)境應(yīng)用的影響可以忽略不計(jì)，也包括那些爭(zhēng)搶非常嚴(yán)重的應(yīng)用。

實(shí)現(xiàn)細(xì)節(jié)

阻塞分析基本是在 Go 運(yùn)行時(shí)內(nèi)部實(shí)現(xiàn)的（有關(guān)代碼，可以點(diǎn)擊描述中的鏈接）。

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 分支預(yù)測(cè)，開銷實(shí)際上是 0。

當(dāng)開啟阻塞分析時(shí)，每一個(gè)阻塞操作都會(huì)有兩個(gè) cputicks() 調(diào)用的開銷。在 amd64 上，這是通過使用了 RDTSC 指令 優(yōu)化后的匯編來完成的，并且在我的機(jī)器上花費(fèi)了可忽略不計(jì)的 ~10ns/op 。

根據(jù)設(shè)置的 blockprofilerate（在精度一節(jié)有更多相關(guān)內(nèi)容），阻塞事件最終可能會(huì)被保存。這意味著堆棧跟蹤信息被收集，此動(dòng)作在我的機(jī)器 上耗時(shí)~1μs（堆棧深度=16）。通過增加相關(guān) blockRecord 計(jì)數(shù)和周期的方式，堆棧會(huì)作為鍵更新一個(gè)內(nèi)部哈希表。

type blockRecord struct {
    count  int64
    cycles int64
}

更新哈希表的開銷大概和收集堆棧跟蹤信息差不多，不過我還沒測(cè)過。

基準(zhǔn)

不管怎樣，就您的應(yīng)用程序開銷而言，所有這些意味著什么？這通常意味著阻塞分析是低開銷的。除非您的應(yīng)用程序由于爭(zhēng)用而花費(fèi)幾乎所有時(shí)間暫停和取消暫停 goroutine，這樣的話即使對(duì)每個(gè)阻塞事件進(jìn)行了采樣，您也可能無法看到可衡量的影響。

話雖如此，下面的基準(zhǔn)測(cè)試結(jié)果（詳情見Methodology(https://github.com/DataDog/go-profiler-notes/tree/main/bench/) ）會(huì)讓您了解到阻塞分析在理論最壞情況下的開銷。圖 chan(cap=0) 展示了通過無緩沖通道發(fā)送消息時(shí)blockprofilerate 從 1 到 1000 的工作負(fù)載 ，可看到吞吐量顯著的下降。圖 chan(cap=128) 使用的是緩沖通道，開銷大大減少，所以對(duì)于不會(huì)將所有時(shí)間耗費(fèi)在通道通信開銷上的應(yīng)用程序可能是無關(guān)緊要的。

值得注意的是，我無法基于負(fù)載看到互斥鎖的開銷。我認(rèn)為是互斥鎖在爭(zhēng)搶時(shí)在暫停 goroutine 之前使用的是自旋鎖。如果有人對(duì)在 Go 中能表現(xiàn)出非自旋鎖爭(zhēng)搶的工作負(fù)載方面有好的想法，請(qǐng)告訴我！

無論如何，請(qǐng)記住，下圖顯示了專門設(shè)計(jì)用于觸發(fā)您可以想象的最壞阻塞分析開銷的工作負(fù)載。實(shí)際應(yīng)用程序通常不會(huì)看到顯著的開銷，尤其是在使用 blockprofilerate>= 10000(10μs) 時(shí)。

block_linux_x86_64

內(nèi)存使用情況

阻塞分析利用共享哈希表進(jìn)行映射，即使表為空時(shí)也會(huì)使用 1.4 MiB 內(nèi)存。除非您在程序中明確禁用堆分析，否則無論您是否使用了阻塞分析器，哈希表都會(huì)被分配內(nèi)存。

此外，每個(gè)唯一的堆棧跟蹤都會(huì)占用一些額外的內(nèi)存。runtime.MemStats 的 BuckHashSys 字段允許您在運(yùn)行時(shí)檢查使用情況。未來，我可能會(huì)嘗試提供有關(guān)這方面的其他信息以及真實(shí)數(shù)據(jù)。

時(shí)間初始化

第一次調(diào)用 runtime.SetBlockProfileRate() 會(huì)耗費(fèi) 100ms是因?yàn)樗噲D測(cè)量掛鐘和TSC時(shí)鐘之間的速度比率。然而，最近關(guān)于異步搶占的更改破壞了此代碼，因此現(xiàn)在該調(diào)用耗時(shí)僅在 ~10ms。

采樣偏差

在 Go 1.17 之前，阻塞分析器偏向于不頻繁的長(zhǎng)事件而不是頻繁的短事件。一個(gè)詳細(xì)的分析說明此問題。

時(shí)間戳計(jì)數(shù)器

amd64 和其他平臺(tái)使用 TSC 實(shí)現(xiàn)了cputicks() 功能。這種技術(shù)歷來受到頻率縮放和其他類型 CPU 功率轉(zhuǎn)換問題的挑戰(zhàn)。現(xiàn)代 CPU 提供不變的 TSCs ，但是仍有一些 Go 語言用戶在提出該問題。我不知道這些是否是由于硬件損壞還是多路系統(tǒng)問題所引入的，但希望將來對(duì)此進(jìn)行更多研究。

另請(qǐng)注意時(shí)間初始化部分中的錯(cuò)誤描述，可能會(huì)影響將 cputicks 轉(zhuǎn)換為掛鐘時(shí)間的精度。

堆棧深度

阻塞分析的最大堆棧深度為32。在更深的堆棧深度發(fā)生的阻塞事件仍將包含在阻塞分析中，但是結(jié)果數(shù)據(jù)可能就很難被處理了。

自旋鎖

如前所述，存在爭(zhēng)搶的 Go 互斥鎖將先自旋一段時(shí)間，然后才服從調(diào)度器程序。如果自旋成功，阻塞事件就會(huì)跟蹤不到。所以阻塞分析器更偏向于持續(xù)時(shí)間較長(zhǎng)的事件。

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

阻塞時(shí)間不受掛鐘時(shí)間的限制。多個(gè) goroutine 可以同時(shí)花費(fèi)時(shí)間阻塞，這意味著分析中可以看到累積的阻塞持續(xù)時(shí)間超過程序運(yùn)行時(shí)間。

阻塞分析器目前不支持分析器標(biāo)簽，但這在未來很有可能被實(shí)現(xiàn)。

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

contentions/count delay/nanoseconds 用于創(chuàng)建分析文件的blockprofilerate 沒有包括在這里，也不屬于分析器標(biāo)簽。

$ 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/[email protected]/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 實(shí)現(xiàn)，并首次出現(xiàn)在 go1.1 版本 (2013-05-13) 中。

我是 felixge，就職于 Datadog ，主要工作內(nèi)容為 Go 的持續(xù)性能優(yōu)化 。你應(yīng)該了解下。我們也在招聘: ).

本頁(yè)面的信息可認(rèn)為正確，但不提供任何保證。歡迎反饋！