Go 工程師必學(xué)：Go 大殺器之跟蹤剖析 Trace
本文轉(zhuǎn)載自微信公眾號(hào)「腦子進(jìn)煎魚了」，作者陳煎魚。轉(zhuǎn)載本文請(qǐng)聯(lián)系腦子進(jìn)煎魚了公眾號(hào)。
大家好，我是煎魚。
前段時(shí)間分享了《Go 程序崩了?煎魚教你用 PProf 工具來救火!》，但有時(shí)候單單使用 pprof 還不一定足夠完整觀查并解決問題，因?yàn)樵谡鎸?shí)的程序中還包含許多的隱藏動(dòng)作，例如：
- Goroutine 在執(zhí)行時(shí)會(huì)做哪些操作?
- Goroutine 執(zhí)行/阻塞了多長(zhǎng)時(shí)間?
- Syscall 在什么時(shí)候被阻止?在哪里被阻止的?
- 誰(shuí)又鎖/解鎖了 Goroutine ?
- GC 是怎么影響到 Goroutine 的執(zhí)行的?
這些東西用 pprof 是很難分析出來的，但如果你又想知道上述的答案的話，你可以用本章節(jié)的主角 go tool trace 來打開新世界的大門。
一起愉快地開始吸魚之路。
初步了解
- import (
- "os"
- "runtime/trace"
- )
- func main() {
- trace.Start(os.Stderr)
- defer trace.Stop()
- ch := make(chan string)
- go func() {
- ch <- "Go語(yǔ)言編程之旅"
- }()
- <-ch
- }
生成跟蹤文件：
- $ go run main.go 2> trace.out
啟動(dòng)可視化界面：
- $ 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：網(wǎng)絡(luò)阻塞概況
Synchronization blocking profile：同步阻塞概況
Syscall blocking profile：系統(tǒng)調(diào)用阻塞概況
Scheduler latency profile：調(diào)度延遲概況
User defined tasks：用戶自定義任務(wù)
User defined regions：用戶自定義區(qū)域
Minimum mutator utilization：最低 Mutator 利用率
調(diào)度延遲概況
在剛開始查看問題時(shí)，除非是很明顯的現(xiàn)象，否則不應(yīng)該一開始就陷入細(xì)節(jié)。
因此我們一般先查看 “Scheduler latency profile”，我們能通過 Graph 看到整體的調(diào)用開銷情況，如下：
演示程序比較簡(jiǎn)單，因此這里就兩塊，一個(gè)是 trace 本身，另外一個(gè)是 channel 的收發(fā)。
Goroutine 分析
第二步看 “Goroutine analysis”，我們能通過這個(gè)功能看到整個(gè)運(yùn)行過程中，每個(gè)函數(shù)塊有多少個(gè)有 Goroutine 在跑。
觀察每個(gè)的 Goroutine 的運(yùn)行開銷都花費(fèi)在哪個(gè)階段。如下：
通過上圖我們可以看到共有 3 個(gè) goroutine，分別是：
- runtime.main。
- runtime/trace.Start.func1。
- main.main.func1。
它們都做了些什么事呢，我們可以通過點(diǎn)擊具體細(xì)項(xiàng)去觀察。如下：
同時(shí)也可以看到當(dāng)前 Goroutine 在整個(gè)調(diào)用耗時(shí)中的占比，以及 GC 清掃和 GC 暫停等待的一些開銷。
如果你覺得還不夠，可以把圖表下載下來分析，相當(dāng)于把整個(gè) Goroutine 運(yùn)行時(shí)掰開來看了，這塊能夠很好的幫助我們對(duì) Goroutine 運(yùn)行階段做一個(gè)的剖析，可以得知到底慢哪，然后再?zèng)Q定下一步的排查方向。
如下：
| 名稱 | 含義 | 耗時(shí) |
|---|---|---|
| Execution Time | 執(zhí)行時(shí)間 | 3140ns |
| Network Wait Time | 網(wǎng)絡(luò)等待時(shí)間 | 0ns |
| Sync Block Time | 同步阻塞時(shí)間 | 0ns |
| Blocking Syscall Time | 調(diào)用阻塞時(shí)間 | 0ns |
| Scheduler Wait Time | 調(diào)度等待時(shí)間 | 14ns |
| GC Sweeping | GC 清掃 | 0ns |
| GC Pause | GC 暫停 | 0ns |
查看跟蹤
在對(duì)當(dāng)前程序的 Goroutine 運(yùn)行分布有了初步了解后，我們?cè)偻ㄟ^ “查看跟蹤” 看看之間的關(guān)聯(lián)性，如下：
這個(gè)跟蹤圖粗略一看，相信有的小伙伴會(huì)比較懵逼，我們可以依據(jù)注解一塊塊查看，如下：
- 時(shí)間線：顯示執(zhí)行的時(shí)間單元，根據(jù)時(shí)間維度的不同可以調(diào)整區(qū)間，具體可執(zhí)行 shift + ? 查看幫助手冊(cè)。
- 堆：顯示執(zhí)行期間的內(nèi)存分配和釋放情況。
- 協(xié)程：顯示在執(zhí)行期間的每個(gè) Goroutine 運(yùn)行階段有多少個(gè)協(xié)程在運(yùn)行，其包含 GC 等待(GCWaiting)、可運(yùn)行(Runnable)、運(yùn)行中(Running)這三種狀態(tài)。
- OS 線程：顯示在執(zhí)行期間有多少個(gè)線程在運(yùn)行，其包含正在調(diào)用 Syscall(InSyscall)、運(yùn)行中(Running)這兩種狀態(tài)。
- 虛擬處理器：每個(gè)虛擬處理器顯示一行，虛擬處理器的數(shù)量一般默認(rèn)為系統(tǒng)內(nèi)核數(shù)。
- 協(xié)程和事件：顯示在每個(gè)虛擬處理器上有什么 Goroutine 正在運(yùn)行，而連線行為代表事件關(guān)聯(lián)。
點(diǎn)擊具體的 Goroutine 行為后可以看到其相關(guān)聯(lián)的詳細(xì)信息，這塊很簡(jiǎn)單，大家實(shí)際操作一下就懂了。文字解釋如下：
- Start：開始時(shí)間
- Wall Duration：持續(xù)時(shí)間
- Self Time：執(zhí)行時(shí)間
- Start Stack Trace：開始時(shí)的堆棧信息
- End Stack Trace：結(jié)束時(shí)的堆棧信息
- Incoming flow：輸入流
- Outgoing flow：輸出流
- Preceding events：之前的事件
- Following events：之后的事件
- All connected：所有連接的事件
查看事件
我們可以通過點(diǎn)擊 View Options-Flow events、Following events 等方式，查看我們應(yīng)用運(yùn)行中的事件流情況。如下：
通過分析圖上的事件流，我們可得知：
這程序從 G1 runtime.main 開始運(yùn)行。
在運(yùn)行時(shí)創(chuàng)建了 2 個(gè) Goroutine：
- 先是創(chuàng)建 G18 runtime/trace.Start.func1。
- 再是創(chuàng)建 G19 main.main.func1。
同時(shí)我們可以通過其 Goroutine Name 去了解它的調(diào)用類型。如下：
runtime/trace.Start.func1 就是程序中在 main.main 調(diào)用了 runtime/trace.Start 方法。
緊接著該方法又利用協(xié)程創(chuàng)建了一個(gè)閉包 func1 去進(jìn)行調(diào)用。
在這里我們結(jié)合開頭的代碼去看的話，很明顯就是 ch 的輸入輸出的過程了。
實(shí)戰(zhàn)演練
凌晨三點(diǎn)，突然生產(chǎn)環(huán)境突然出現(xiàn)了問題，機(jī)智的你早已埋好 _ "net/http/pprof" 這個(gè)神奇的工具。
被告警電話叫醒的你，迷迷糊糊地通過特定的方式執(zhí)行了如下命令：
- $ curl http://127.0.0.1:6060/debug/pprof/trace\?seconds\=20 > trace.out
- $ go tool trace trace.out
查看跟蹤
你很快的看到了熟悉的 List 界面，然后不信邪點(diǎn)開了 View trace 界面，如下：
完全看懵的你，穩(wěn)住，對(duì)著合適的區(qū)域執(zhí)行快捷鍵 W 不斷地放大時(shí)間線，如下：
經(jīng)過初步排查，你發(fā)現(xiàn)上述絕大部分的 G 竟然都和 google.golang.org/grpc.(*Server).Serve.func 有關(guān)，關(guān)聯(lián)的一大串也是 Serve 所觸發(fā)的相關(guān)動(dòng)作。
這時(shí)候有經(jīng)驗(yàn)的你心里已經(jīng)有了初步結(jié)論，你可以繼續(xù)追蹤 View trace 深入進(jìn)去。
不過建議先鳥瞰全貌，因此我們?cè)偻驴?“Network blocking profile” 和 “Syscall blocking profile” 所提供的信息。
網(wǎng)絡(luò)阻塞概況
系統(tǒng)調(diào)用阻塞概況
通過對(duì)以上三項(xiàng)的跟蹤分析，加上這個(gè)泄露，這個(gè)阻塞的耗時(shí)，這個(gè)涉及的內(nèi)部方法名，很明顯就是哪位又忘記關(guān)閉客戶端連接了。
這時(shí)候我們就可以接下進(jìn)行下一步的排查和修改了。
總結(jié)
通過本文我們習(xí)得了 go tool trace 的武林秘籍，它能夠跟蹤捕獲各種執(zhí)行中的事件，例如：
- Goroutine 的創(chuàng)建/阻塞/解除阻塞。
- Syscall 的進(jìn)入/退出/阻止，GC 事件。
- Heap 的大小改變。
- Processor 啟動(dòng)/停止等等。
希望你能夠用好 Go 的兩大殺器 pprof + trace 組合，此乃排查好搭檔，誰(shuí)用誰(shuí)清楚，即使他并不是絕對(duì)的萬(wàn)能。
