Go 中的性能分析和執行跟蹤

Go 提供了一些優秀的診斷工具來幫助我們深入分析應用程序的執行情況。

這篇文章核心關注點是：分析和執行跟蹤器。

這兩個工具都非常重要，它們應該成爲任何對優化感興趣的 Go 開發人員的核心工具集的一部分。 

首先，我們來討論下性能分析。

性能分析 Profiling

分析工具提供了對應用程序執行的洞察力。它使我們能夠解決性能問題、檢測競爭、定位內存泄漏等。

這些信息可以通過幾個分析工具來收集：

• CPU— 確定應用程序的時間花在了哪裏

• Goroutine— 報告正在運行的 goroutines 堆棧跟蹤

• Heap— 報告堆內存分配以監視當前內存使用情況並檢查可能的內存泄漏

• Mutex— 報告鎖爭情況來分析代碼中互斥鎖使用行爲以及應用程序是否在鎖定調用上花費了太多時間

• Block— 顯示 goroutines 阻塞等待同步原語的位置

性能分析是通過 分析器(profiler) 工具進行檢測來實現的，在 Go 中使用稱爲 pprof。 

首先，讓我們瞭解如何和何時啓用 pprof，然後再討論最關鍵的配置分析類型。

開啓 pprof

有幾種方法可以啓用 pprof。例如，我們可以使用 net/http/pprof 包通過 HTTP 提供分析數據：

package main

import (
    "fmt"
    "log"
    "net/http"
    _ "net/http/pprof" // Blank import to pprof
)

func main() {
    // Exposes an HTTP endpoint
    http.HandleFunc("/", func(w http.ResponseWriter, r *http.Request) {
        fmt.Fprintf(w, "")
    })
    log.Fatal(http.ListenAndServe(":80", nil))
}

導入  net/http/pprof 的作用是，我們可以通過 http://host/debug/pprof  來訪問 pprof。

請注意，即使在生產環境中啓用 pprof 也是安全的 (https://go.dev/doc/diagnostics#profiling)。影響性能的分析，比如 CPU 分析，默認情況下是不啓用的，也不會連續運行。它們僅在特定時間段內被激活。

現在我們已經瞭解瞭如何公開 pprof 訪問路由，接下來討論最常見的幾種分析。

CPU 分析

CPU 分析器依賴於操作系統和信號。

當它被激活時，應用程序默認通過 SIGPROF 信號要求操作系統每 10 毫秒中斷一次。當應用程序收到 SIGPROF 時，它會暫停當前活動並將執行轉移到分析器。

分析器收集諸如當前 goroutine 活動之類的數據，並彙總可以檢索的執行統計信息；然後停止分析並繼續執行直到下一次的 SIGPROF。

我們可以訪問 /debug/pprof/profile 路由來激活 CPU 分析。默認情況下，訪問此路由會執行 30 秒的 CPU 分析。在 30 秒內，我們的應用程序每 10 毫秒中斷一次。

請注意，可以更改這兩個默認值：使用 seconds 參數將分析應該持續多長時間傳遞給路由（例如 /debug/pprof/profile?seconds=15），也可以更改中斷率（甚至小於 10 毫秒）。

但多數情況下，10 毫秒應該足夠了，在減小這個值（意味着增加頻率）時，我們應該注意不要對性能產生影響。30 秒後，就可以下載 CPU 分析器的結果。

注意： 

也可以通過  -cpuprofile 標誌來開啓 CPU 分析器，比如在運行基準測試時就可以用這種方式。

例如，執行以下命令後可通過 /debug/pprof/profile 下載到相同的分析結果文件。

$ go test -bench=. -cpuprofile profile.out

從這個文件，我們可以使用 go tool 來查看結果分析：

$ go tool pprof -http=:8080 <file>

此命令會打開一個顯示調用圖的 Web UI。

圖 1 顯示了一個示例。箭頭越大，這條分支就越是熱路徑。通過分析此圖表就可以進一步分析程序的執行情況。

圖 1 程序在 30 秒內的調用圖

例如，圖 2 中的圖表告訴我們，在 30 秒內，*FetchResponse 接收者的decode方法花費了 0.06 秒。在這 0.06 秒中，0.02 秒用於RecordBatch.decode，0.01 秒用於makemap（創建一個 map）。

圖 2 調用圖示例

我們還可以從具有不同表示形式的 Web UI 訪問此類信息。例如，Top 視圖按執行時間對函數進行排序，而 Flame Graph 可視化執行時間層次結構。UI 甚至可以逐行顯示源代碼中執行最耗時的部分。

注意: 

我們還可以通過命令行深入分析數據。然而，這篇文章中專注於 Web UI。

多虧了這些數據，我們可以大致瞭解應用程序的行爲方式：

• 對 runtime.mallogc 的調用過多，意味着我們可以嘗試減少過多的小堆分配

• 在通道操作或互斥鎖上花費太多時間，可能表明過度競爭正在損害應用程序的性能

• 在 syscall.Read 或 syscall.Write 上花費太多時間，意味着應用程序在內核模式下花費了大量時間。處理 I/O 緩衝可能是改進的途徑

這些是可以從 CPU 分析器中獲得的信息。瞭解最頻繁的代碼路徑和識別程序瓶頸是很有價值，但它不會確定超過特定頻率，因爲 CPU 分析器是以固定速度執行分析的（默認情況下爲 10 毫秒）。

爲了獲得更細粒度的分析數據，我們應該使用跟蹤器 (tracing)，將在本文後面討論。

注意: 

我們還可以爲不同的功能附加標籤。例如，想象一個從不同客戶端調用的通用函數，要跟蹤兩個客戶端花費的時間，可以使用 pprof.Labels。

堆分析

堆分析允許我們獲得有關當前堆使用情況的統計信息。

與 CPU 分析一樣，堆分析也是基於採樣的。可以改變採樣頻率，但不應該過於細化，因爲採樣頻率提升越多，堆分析收集數據所需的額外工作就越多。默認情況下，樣本在每 512 KB 堆分配一次就執行一次。

訪問 /debug/pprof/heap/，會得到難以閱讀的原始數據。但是，可以使用 /debug/pprof/heap/?debug=0 下載堆分析文件，然後使用  go tool（與上一節中的命令相同）打開，就可以使用 Web UI 來分析數據。

圖 3 顯示了堆圖的示例。調用MetadataResponse.decode方法會導致分配 1536 KB 的堆數據（佔總堆的 6.32%）。

但是，這 1536 KB 中有 0 塊是由該函數直接分配的，因此我們需要檢查第二層的調用。TopicMetadata.decode 方法分配了 1536 KB 中的 512 KB；其餘的——1024 KB——是用另一種方法分配的。

圖 3 堆分配圖示

這就是我們如何通過調用鏈分析應用程序哪個部分佔用了大量堆分配。還可以查看不同的採樣類型：

• alloc_objects— 分配的對象總數

• alloc_space— 分配的內存總量

• inuse_objects— 已分配但尚未釋放的對象數

• inuse_space— 已分配但尚未釋放的內存量

堆分析的另一個非常有用的功能是跟蹤內存泄漏。

基於 GC 類的語言，通常的過程如下：

1. 觸發 GC

2. 下載堆數據

3. 等待幾秒 / 分鐘

4. 觸發另一個 GC

5. 下載另一個堆數據

6. 比較

在下載數據之前強制執行 GC 是一種防止錯誤假設的方法。如果在沒有先運行 GC 的情況下看到保留對象的峯值，我們無法確定這是泄漏還是下一次 GC 將收集的對象。

使用 pprof，可以下載堆分析文件並同時強制執行 GC。

Go 中的過程如下：

1. 訪問 /debug/pprof/heap?gc=1（觸發 GC 並下載堆分析文件）

2. 等待幾秒 / 分鐘

3. 再次訪問 /debug/pprof/heap?gc=1

4. 使用 go tool 比較兩個堆配置文件：

$ go tool pprof -http=:8080 -diff_base <file2> <file1>

圖 4 顯示了可以訪問的數據類型。例如，newTopicProducer方法（左上角）佔用的堆內存量減少了 (–513 KB)。

相比之下，updateMetadata（右下角）持有的數量增加了（+512 KB）。

緩慢增加是正常的。例如，第二個堆分析文件可能是在服務調用過程中計算出來的。可以重複此過程或等待更長時間；重要的部分是跟蹤特定對象分配的穩步增長。

圖 4 兩份堆分析文件的差異

注意: 

與堆相關的另一種分析類型是 allocs_，它報告分配。__堆分析顯示堆內存的當前狀態。要了解自應用程序啓動以來過去的內存分配情況，我們可以使用分配分析。_如前所述，由於堆棧分配的成本很低，因此它不是此分析的一部分，該分析僅關注堆。

Goroutine 分析

goroutine 分析可以反映出應用程序中所有當前 goroutine 的堆棧跟蹤。可以使用 /debug/pprof/goroutine/?debug=0 下載文件並再次使用 go tool。圖 5 顯示了可以獲得的信息類型。

圖 5 Goroutine 圖示

我們可以看到應用程序的當前狀態以及每個函數創建了多少 goroutine。在這種情況下，withRecover 創建了 296 個正在進行的 goroutines (63%)，其中 29 個與調用 responseFeeder 有關。

如果懷疑 goroutine 泄漏，這種信息也很有用。可以查看 goroutine 分析器數據以瞭解系統的哪一部分是可疑的。

Block 阻塞分析

block 分析可以反映出正在進行的 goroutines 阻塞等待同步原語的位置。

可能性包括：

• 在無緩衝通道上發送或接收

• 向已滿的通道發送數據

• 從空通道接收數據

• 互斥鎖競爭

• 網絡或文件系統等待

塊分析還記錄了 goroutine 等待的時間，可以通過 /debug/pprof/block 訪問。如果我們懷疑性能因阻塞調用而受到損害，此分析文件可能會非常有用。

默認情況下不啓用 block 分析，必須顯式調用 runtime.SetBlockProfileRate 來啓用它。此函數控制報告的 goroutine 阻塞事件的比例。

啓用後，即使我們不調用 /debug/pprof/block，分析器也會繼續在後臺收集數據。如果我們想設置高速率，請謹慎行事，以免對性能產生影響。

注意: 

如果我們遇到死鎖或懷疑 goroutines 處於阻塞狀態，完整的 goroutine 堆棧轉儲 ([/debug/pprof/goroutine/?debug=2](https://teivah.medium.com/debug/ pprof/goroutine/?debug=2)) 創建所有當前 goroutine 堆棧跟蹤的轉儲，作爲分析的第一步，這將是很有幫助的。

例如，以下轉儲顯示 Sarama goroutine 在通道接收操作中阻塞了 1,420 分鐘：

goroutine 2494290 [chan receive, 1420 minutes]:
github.com/Shopify/sarama.(*syncProducer).SendMessages(0xc00071a090,
[CA]{0xc0009bb800, 0xfb, 0xfb})
    /app/vendor/github.com/Shopify/sarama/sync_producer.go:117 +0x149

Mutex 互斥鎖分析

最後一個分析類型與阻塞有關，但僅與互斥鎖有關。當我們懷疑應用程序花費大量時間等待互斥鎖而影響了正常執行時，可以使用互斥量分析。它可以通過 /debug/pprof/mutex 訪問。

此分析的工作方式類似於阻塞。默認情況下它是禁用的：必須使用 runtime.SetMutexProfileFraction 來啓用，並控制報告中互斥鎖爭用事件的比例。

以下是關於分析的一些附加說明：

• 這裏沒有提及 threadcreate 分析，因爲它自 2013 年以來已經無法使用 (https://github.com/golang/go/issues/6104)

• 確保一次只啓用一個分析器：例如，不要同時啓用 CPU 和堆分析器。這樣做會導致錯誤的觀察

• pprof 是可擴展的，我們可以使用 pprof.Profile 創建自定義分析

至此，已經看到了可以啓用的最重要的分析，它們可以幫助瞭解應用程序的執行方式和可能的優化途徑。

通常，建議啓用 pprof，即使在生產中也是如此，因爲在大多數情況下，它在其足跡和可以從中獲得的分析能力之間提供了極好的平衡。某些分析（例如 CPU 分析）會導致性能下降，但僅在啓用它們期間纔會發生。

現在讓我們看看執行跟蹤器。

執行跟蹤器（Execution Tracer）

執行跟蹤器是一種工具，可以使用 go tool 捕獲各種運行時事件，使它們可用於可視化。它對以下方面有幫助：

• 瞭解運行時事件，例如 GC 如何執行

• 理解 goroutines 是如何執行的

• 識別不良的並行執行

讓我們以 Go 中的併發並不總是更快 [1] 帖子爲例來嘗試一下。這裏討論了歸併排序算法的兩個並行版本。第一個版本的問題是並行化不佳，導致創建了太多的 goroutine。

讓我們看看跟蹤器如何幫助驗證這一說法。

爲第一個版本編寫一個基準測試，並使用 -trace 標誌執行以開啓執行跟蹤器：

$ go test -bench=. -v -trace=trace.out

NOTE: 還可以使用 /debug/pprof/trace?debug=0 路由下載遠程跟蹤文件。

這一命令創建了一個 trace.out 文件，我們可以通過 go tool 來打開它：

$ go tool trace trace.out
2021/11/26 21:36:03 Parsing trace...
2021/11/26 21:36:31 Splitting trace...
2021/11/26 21:37:00 Opening browser. Trace viewer is listening on
    http://127.0.0.1:54518

打開瀏覽器訪問此地址，就可以單擊 View Trace 查看特定時間範圍內的所有軌跡，如圖 6 所示。

該圖表示了大約 150 毫秒。我們可以看到多個有用的指標，例如 goroutine 數量和堆大小。堆大小穩定增長，直到觸發 GC。還可以觀察每個 CPU 內核的 Go 應用程序的活動。時間範圍從用戶級代碼開始；然後執行 STW，佔用四個 CPU 內核大約 40 毫秒。

圖 6 顯示 goroutine 活動和運行時事件，如 GC 階段

關於併發性，我們可以看到這個版本使用了機器上所有可用的 CPU 內核。

然而，圖 7 放大了 1 毫秒的一部分。每個條對應於一個 goroutine 執行。有太多的小條看起來不對：這意味着執行的並行化很差。

圖 7 太多的小條意味着並行執行不佳

圖 8 進一步放大以查看這些 goroutine 是如何編排的。大約 50% 的 CPU 時間沒有花在執行應用程序代碼上。空白表示 Go 運行時啓動和編排新 goroutine 所需的時間。

圖 8 大約 50% 的 CPU 時間花在處理 goroutine 切換上

將其與第二個並行實現進行比較，後者快了大約一個數量級。圖 9 再次放大到 1 毫秒的時間範圍。

圖 9 空白的數量已明顯減少，證明 CPU 已被更充分地佔用

每個 goroutine 需要更多的時間來執行，並且空白的數量已經顯着減少。因此，CPU 比第一個版本更忙於執行應用程序代碼。CPU 時間的每一毫秒都得到了更有效的利用，這解釋了基準測試的差異。

請注意，跟蹤的粒度是每個 goroutine，而不是像 CPU 分析那樣的每個函數。但是，可以使用 runtime/trace 包定義用戶級任務以獲取每個函數或函數組的分析能力。

例如，假設一個函數計算斐波那契數，然後使用原子操作將其寫入全局變量。可以定義兩個不同的任務：

var v int64
// Creates a fibonacci task
ctx, fibTask := trace.NewTask(context.Background(), "fibonacci")
trace.WithRegion(ctx, "main", func() {
    v = fibonacci(10)
})
fibTask.End()

// Creates a store task
ctx, fibStore := trace.NewTask(ctx, "store")
trace.WithRegion(ctx, "main", func() {
    atomic.StoreInt64(&result, v)
})
fibStore.End()

使用 go tool 可以獲得關於這兩個任務如何執行的更精確的信息。

在前面的跟蹤 UI（圖 12）中我們可以看到每個 goroutine 的每個任務的邊界。在用戶定義的任務中，我們可以遵循持續時間分佈（見圖 10）。

圖 10 用戶級別任務分佈

我們看到，在大多數情況下，fibonacci 任務的執行時間不到 15 微秒，而 store 任務的執行時間不到 6309 納秒。

在上一節中，我們討論了可以從 CPU 分析中獲得的不同分類信息。與用戶級跟蹤中獲得的數據相比，主要區別是什麼？

• CPU 分析：– 基於採樣 – 每個函數 – 不低於採樣率（默認爲 10 毫秒）

• 用戶級跟蹤：– 不是基於樣本的 – 每個 goroutine 執行（除非使用 runtime/trace 包） – 時間執行不受任何速率的約束

總之，執行跟蹤器是瞭解應用程序如何執行的強大工具。正如在歸併排序示例中看到的那樣，可以識別出並行執行不佳的情況。

然而，跟蹤器的粒度仍然是每個 goroutine，除非手動使用 runtime/trace 與 CPU 分析進行比較，例如，在優化應用程序時，可以同時使用分析和執行跟蹤器來充分利用標準的 Go 診斷工具。

這篇文章摘自我的書《10__0 個 Go 錯誤以及如何避免它們》[2]， 於 2022 年 8 月發佈。

100 個 Go 錯誤以及如何避免它們。展示如何用慣用的、富有表現力的代碼替換 Go 中的常見編程問題。在其中，將探索許多有趣的示例和案例研究，同時學習如何發現自己的應用程序中可能出現的錯誤。

同時，這裏是 GitHub 存庫，總結了本書中的所有錯誤：https://github.com/teivah/100-go-mistakes

相關鏈接：

[1]https://medium.com/@teivah/concurrency-isnt-always-faster-in-go-de325168907c

[2]https://www.manning.com/books/100-go-mistakes-and-how-to-avoid-them

原文地址：

https://teivah.medium.com/profiling-and-execution-tracing-in-go-a5e646970f5b

原文作者：

Teiva Harsanyi

本文永久鏈接： https://github.com/gocn/translator/edit/master/2022/w53_Profiling_and_Execution_Tracing_in_Go.md

譯者：Fivezh

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