Golang 大殺器之跟蹤剖析 trace

煎魚發表於2019-07-12

在 Go 中有許許多多的分析工具，在之前我有寫過一篇《Golang 大殺器之效能剖析 PProf》來介紹 PProf，如果有小夥伴感興趣可以去我部落格看看。

但單單使用 PProf 有時候不一定足夠完整，因為在真實的程式中還包含許多的隱藏動作，例如 Goroutine 在執行時會做哪些操作？執行/阻塞了多長時間？在什麼時候阻止？在哪裡被阻止的？誰又鎖/解鎖了它們？GC 是怎麼影響到 Goroutine 的執行的？這些東西用 PProf 是很難分析出來的，但如果你又想知道上述的答案的話，你可以用本文的主角 go tool trace 來開啟新世界的大門。目錄如下：

初步瞭解

import (
    "os"
    "runtime/trace"
)

func main() {
    trace.Start(os.Stderr)
    defer trace.Stop()

    ch := make(chan string)
    go func() {
        ch <- "EDDYCJY"
    }()

    <-ch
}

生成跟蹤檔案：

$ go run main.go 2> trace.out

啟動視覺化介面：

$ go tool trace trace.out
2019/06/22 16:14:52 Parsing trace...
2019/06/22 16:14:52 Splitting trace...
2019/06/22 16:14:52 Opening browser. Trace viewer is listening on http://127.0.0.1:57321

檢視視覺化介面：

View trace：檢視跟蹤
Goroutine analysis：Goroutine 分析
Network blocking profile：網路阻塞概況
Synchronization blocking profile：同步阻塞概況
Syscall blocking profile：系統呼叫阻塞概況
Scheduler latency profile：排程延遲概況
User defined tasks：使用者自定義任務
User defined regions：使用者自定義區域
Minimum mutator utilization：最低 Mutator 利用率

Scheduler latency profile

在剛開始檢視問題時，除非是很明顯的現象，否則不應該一開始就陷入細節，因此我們一般先檢視 “Scheduler latency profile”，我們能通過 Graph 看到整體的呼叫開銷情況，如下：

演示程式比較簡單，因此這裡就兩塊，一個是 trace 本身，另外一個是 channel 的收發。

Goroutine analysis

第二步看 “Goroutine analysis”，我們能通過這個功能看到整個執行過程中，每個函式塊有多少個有 Goroutine 在跑，並且觀察每個的 Goroutine 的執行開銷都花費在哪個階段。如下：

通過上圖我們可以看到共有 3 個 goroutine，分別是 runtime.main、runtime/trace.Start.func1、main.main.func1，那麼它都做了些什麼事呢，接下來我們可以通過點選具體細項去觀察。如下：

同時也可以看到當前 Goroutine 在整個呼叫耗時中的佔比，以及 GC 清掃和 GC 暫停等待的一些開銷。如果你覺得還不夠，可以把圖表下載下來分析，相當於把整個 Goroutine 執行時掰開來看了，這塊能夠很好的幫助我們對 Goroutine 執行階段做一個的剖析，可以得知到底慢哪，然後再決定下一步的排查方向。如下：

名稱	含義	耗時
Execution Time	執行時間	3140ns
Network Wait Time	網路等待時間	0ns
Sync Block Time	同步阻塞時間	0ns
Blocking Syscall Time	呼叫阻塞時間	0ns
Scheduler Wait Time	排程等待時間	14ns
GC Sweeping	GC 清掃	0ns
GC Pause	GC 暫停	0ns

View trace

在對當前程式的 Goroutine 執行分佈有了初步瞭解後，我們再通過 “檢視跟蹤” 看看之間的關聯性，如下：

這個跟蹤圖粗略一看，相信有的小夥伴會比較懵逼，我們可以依據註解一塊塊檢視，如下：

時間線：顯示執行的時間單元，根據時間維度的不同可以調整區間，具體可執行 shift + ? 檢視幫助手冊。
堆：顯示執行期間的記憶體分配和釋放情況。
協程：顯示在執行期間的每個 Goroutine 執行階段有多少個協程在執行，其包含 GC 等待（GCWaiting）、可執行（Runnable）、執行中（Running）這三種狀態。
OS 執行緒：顯示在執行期間有多少個執行緒在執行，其包含正在呼叫 Syscall（InSyscall）、執行中（Running）這兩種狀態。
虛擬處理器：每個虛擬處理器顯示一行，虛擬處理器的數量一般預設為系統核心數。
協程和事件：顯示在每個虛擬處理器上有什麼 Goroutine 正在執行，而連線行為代表事件關聯。

點選具體的 Goroutine 行為後可以看到其相關聯的詳細資訊，這塊很簡單，大家實際操作一下就懂了。文字解釋如下：

Start：開始時間
Wall Duration：持續時間
Self Time：執行時間
Start Stack Trace：開始時的堆疊資訊
End Stack Trace：結束時的堆疊資訊
Incoming flow：輸入流
Outgoing flow：輸出流
Preceding events：之前的事件
Following events：之後的事件
All connected：所有連線的事件

View Events

我們可以通過點選 View Options-Flow events、Following events 等方式，檢視我們應用執行中的事件流情況。如下：

通過分析圖上的事件流，我們可得知這程式從 G1 runtime.main 開始執行，在執行時建立了 2 個 Goroutine，先是建立 G18 runtime/trace.Start.func1，然後再是 G19 main.main.func1 。而同時我們可以通過其 Goroutine Name 去了解它的呼叫型別，如：runtime/trace.Start.func1 就是程式中在 main.main 呼叫了 runtime/trace.Start 方法，然後該方法又利用協程建立了一個閉包 func1 去進行呼叫。