Golang 大殺器之跟蹤剖析 trace

原文地址：Golang 大殺器之跟蹤剖析 trace

在 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 運行分佈有了初步瞭解後，咱們再經過 「查看跟蹤」 看看之間的關聯性，以下：

這個跟蹤圖粗略一看，相信有的小夥伴會比較懵逼，咱們能夠依據註解一塊塊查看，以下：

1. 時間線：顯示執行的時間單元，根據時間維度的不一樣能夠調整區間，具體可執行 shift + ? 查看幫助手冊。
2. 堆：顯示執行期間的內存分配和釋放狀況。
3. 協程：顯示在執行期間的每一個 Goroutine 運行階段有多少個協程在運行，其包含 GC 等待（GCWaiting）、可運行（Runnable）、運行中（Running）這三種狀態。
4. OS 線程：顯示在執行期間有多少個線程在運行，其包含正在調用 Syscall（InSyscall）、運行中（Running）這兩種狀態。
5. 虛擬處理器：每一個虛擬處理器顯示一行，虛擬處理器的數量通常默認爲系統內核數。
6. 協程和事件：顯示在每一個虛擬處理器上有什麼 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 去進行調用。

在這裏咱們結合開頭的代碼去看的話，很明顯就是 ch 的輸入輸出的過程了。

結合實戰

今天生產環境忽然出現了問題，機智的你早已埋好 _ "net/http/pprof" 這個神奇的工具，你麻利的執行了以下命令：

• curl http://127.0.0.1:6060/debug/pprof/trace?seconds=20 > trace.out
• go tool trace trace.out

View trace

你很快的看到了熟悉的 List 界面，而後不信邪點開了 View trace 界面，以下：

徹底看懵的你，穩住，對着合適的區域執行快捷鍵 W 不斷地放大時間線，以下：

通過初步排查，你發現上述絕大部分的 G 居然都和 google.golang.org/grpc.(*Server).Serve.func 有關，關聯的一大串也是 Serve 所觸發的相關動做。

這時候有經驗的你內心已經有了初步結論，你能夠繼續追蹤 View trace 深刻進去，不過我建議先鳥瞰全貌，所以咱們再往下看 「Network blocking profile」 和 「Syscall blocking profile」 所提供的信息，以下：

Network blocking profile

Syscall blocking profile

經過對以上三項的跟蹤分析，加上這個泄露，這個阻塞的耗時，這個涉及的內部方法名，很明顯就是哪位又忘記關閉客戶端鏈接了，趕忙改改改。

總結

經過本文咱們習得了 go tool trace 的武林祕籍，它可以跟蹤捕獲各類執行中的事件，例如 Goroutine 的建立/阻塞/解除阻塞，Syscall 的進入/退出/阻止，GC 事件，Heap 的大小改變，Processor 啓動/中止等等。

但願你可以用好 Go 的兩大殺器 pprof + trace 組合，此乃排查好搭檔，誰用誰清楚，即便他並不萬能。

參考

• https://about.sourcegraph.com...
• https://www.itcodemonkey.com/...
• https://making.pusher.com/go-...
• https://golang.org/cmd/trace/
• https://docs.google.com/docum...
• https://godoc.org/runtime/trace