引言

服務(wù)監(jiān)控系列文章

服務(wù)監(jiān)控系列視頻

關(guān)于go tool trace的使用，網(wǎng)上有相當(dāng)多的資料，但拿我之前初學(xué)golang的經(jīng)驗(yàn)來(lái)講，很多資料都沒(méi)有把go tool trace中的相關(guān)指標(biāo)究竟是統(tǒng)計(jì)的哪些方法，統(tǒng)計(jì)了哪段區(qū)間講解清楚。所以這篇文章不僅僅會(huì)介紹go tool trace的使用，也會(huì)對(duì)其統(tǒng)計(jì)的原理進(jìn)行剖析。

golang版本 go1.17.12

先簡(jiǎn)單說(shuō)下go tool trace 的使用場(chǎng)景，在分析延遲性問(wèn)題的時(shí)候，go tool trace能起到很重要的作用，因?yàn)樗鼤?huì)記錄各種延遲事件并且對(duì)其進(jìn)行時(shí)長(zhǎng)分析，連關(guān)鍵代碼位置也能找出來(lái)。

關(guān)于trace的實(shí)戰(zhàn)案例，之前有出過(guò)一個(gè)視頻(一次系統(tǒng)延遲分析案例)，歡迎瀏覽

接著我們簡(jiǎn)單看下golang 里如何使用trace 功能。

go trace 使用

package main
import (
	_ "net/http/pprof"
	"os"
	"runtime/trace"
)
func main() {
	f, _ := os.Create("trace.out")
	defer f.Close()
	trace.Start(f)
	defer trace.Stop()
  ......
}

使用trace的功能其實(shí)比較容易，用trace.Start 便可以開啟trace的事件采樣功能，trace.Stop 則停止采用，采樣的數(shù)據(jù)會(huì)記錄到trace.Start 傳來(lái)的輸出流參數(shù)里，這里我是將一個(gè)名為trace.out 的文件作為輸出流參數(shù)傳入。

采樣結(jié)束后便可以通過(guò) go tool trace trace.out命令對(duì)采樣文件進(jìn)行分析了。

go tool trace 命令默認(rèn)會(huì)使用本地隨機(jī)一個(gè)端口來(lái)啟動(dòng)一個(gè)http服務(wù)，頁(yè)面顯示如下:

接著我會(huì)分析下各個(gè)鏈接對(duì)應(yīng)的統(tǒng)計(jì)信息以及背后進(jìn)行統(tǒng)計(jì)的原理，好的，接下來(lái)，正戲開始。

統(tǒng)計(jì)原理介紹

平時(shí)在使用prometheus對(duì)應(yīng)用服務(wù)進(jìn)行監(jiān)控時(shí)，我們主要還是采用埋點(diǎn)的方式，同樣，go runtime內(nèi)部也是采用這樣的方式對(duì)代碼運(yùn)行過(guò)程中的各種事件進(jìn)行埋點(diǎn)，最后讀取 整理后的埋點(diǎn)數(shù)據(jù)，形成我們?cè)诰W(wǎng)頁(yè)上看的trace監(jiān)控圖。

// src/runtime/trace.go:517
func traceEvent(ev byte, skip int, args ...uint64) {
	mp, pid, bufp := traceAcquireBuffer()
    .....
}

每次要記錄相應(yīng)的事件時(shí)，都會(huì)調(diào)用traceEvent方法，ev代表的是事件枚舉，skip 是看棧幀需要跳躍的層數(shù)，args 在某些事件需要傳入特定參數(shù)時(shí)傳入。

在traceEvent 內(nèi)部同時(shí)也會(huì)獲取到當(dāng)前事件發(fā)生時(shí)的線程信息，協(xié)程信息，p運(yùn)行隊(duì)列信息，并把這些信息同事件一起記錄到一個(gè)緩沖區(qū)里。

// src/runtime/trace/trace.go:120 
func Start(w io.Writer) error {
	tracing.Lock()
	defer tracing.Unlock()
	if err := runtime.StartTrace(); err != nil {
		return err
	}
	go func() {
		for {
			data := runtime.ReadTrace()
			if data == nil {
				break
			}
			w.Write(data)
		}
	}()
	atomic.StoreInt32(&tracing.enabled, 1)
	return nil
}

在我們啟動(dòng)trace.Start方法的時(shí)候，同時(shí)會(huì)啟動(dòng)一個(gè)協(xié)程不斷讀取緩沖區(qū)中的內(nèi)容到strace.Start 的參數(shù)中。

在示例代碼里，trace.Start 方法傳入名為trace.out文件的輸出流參數(shù),所以在采樣過(guò)程中，runtime會(huì)將采集到的事件字節(jié)流輸出到trace.out文件，trace.out文件在被讀取出的時(shí)候 是用了一個(gè)叫做Event的結(jié)構(gòu)體來(lái)表示這些監(jiān)控事件。

// Event describes one event in the trace.
type Event struct {
	Off   int       // offset in input file (for debugging and error reporting)
	Type  byte      // one of Ev*
	seq   int64     // sequence number
	Ts    int64     // timestamp in nanoseconds
	P     int       // P on which the event happened (can be one of TimerP, NetpollP, SyscallP)
	G     uint64    // G on which the event happened
	StkID uint64    // unique stack ID
	Stk   []*Frame  // stack trace (can be empty)
	Args  [3]uint64 // event-type-specific arguments
	SArgs []string  // event-type-specific string args
	// linked event (can be nil), depends on event type:
	// for GCStart: the GCStop
	// for GCSTWStart: the GCSTWDone
	// for GCSweepStart: the GCSweepDone
	// for GoCreate: first GoStart of the created goroutine
	// for GoStart/GoStartLabel: the associated GoEnd, GoBlock or other blocking event
	// for GoSched/GoPreempt: the next GoStart
	// for GoBlock and other blocking events: the unblock event
	// for GoUnblock: the associated GoStart
	// for blocking GoSysCall: the associated GoSysExit
	// for GoSysExit: the next GoStart
	// for GCMarkAssistStart: the associated GCMarkAssistDone
	// for UserTaskCreate: the UserTaskEnd
	// for UserRegion: if the start region, the corresponding UserRegion end event
	Link *Event
}

來(lái)看下Event事件里包含哪些信息： P 是運(yùn)行隊(duì)列，go在運(yùn)行協(xié)程時(shí)，是將協(xié)程調(diào)度到P上運(yùn)行的，G 是協(xié)程id，還有棧id StkID ，棧幀 Stk，以及事件發(fā)生時(shí)可以攜帶的一些參數(shù)Args，SArgs。 Type 是事件的枚舉字段，Ts是事件發(fā)生的時(shí)間戳信息，Link 是與事件關(guān)聯(lián)的其他事件，用于計(jì)算關(guān)聯(lián)事件的耗時(shí)。

拿計(jì)算系統(tǒng)調(diào)用耗時(shí)來(lái)說(shuō)，系統(tǒng)調(diào)用相關(guān)的事件有GoSysExit,GoSysCall 分別是系統(tǒng)調(diào)用退出事件和系統(tǒng)調(diào)用開始事件，所以GoSysExit.Ts - GoSysCall.Ts 就是系統(tǒng)調(diào)用的耗時(shí)。

特別提示: runtime 內(nèi)部用到的監(jiān)控事件枚舉在src/runtime/trace.go:39 位置 ，而 在讀取文件中的監(jiān)控事件用到的枚舉是 在src/internal/trace/parser.go:1028 ，雖然是兩套，但是值是一樣的。

很明顯Link 字段不是在runtime 記錄監(jiān)控事件時(shí)設(shè)置的，而是在讀取trace.out里的監(jiān)控事件時(shí)，將事件信息按照協(xié)程id分組后 進(jìn)行設(shè)置的。同一個(gè)協(xié)程的 GoSysExit.Ts - GoSysCall.Ts 就是該協(xié)程的系統(tǒng)調(diào)用耗時(shí)。

接下來(lái)我們來(lái)挨個(gè)分析下trace頁(yè)面的統(tǒng)計(jì)信息以及背后的統(tǒng)計(jì)原理。

View trace是每個(gè)事件的時(shí)間線構(gòu)成的監(jiān)控圖，在生產(chǎn)環(huán)境下1s都會(huì)產(chǎn)生大量的事件，我認(rèn)為直接看這張圖還是會(huì)讓人眼花繚亂。 所以還是跳過(guò)它吧，從Goroutine analysis開始分析。

Goroutine analysis

go tool trace最終引用的代碼位置是在go/src/cmd/trace 包下，main函數(shù)會(huì)啟動(dòng)一個(gè)http服務(wù)，并且注冊(cè)一些處理函數(shù)，我們點(diǎn)擊Goroutine analysis 其實(shí)就是請(qǐng)求到了其中一個(gè)處理函數(shù)上。 下面這段代碼是注冊(cè)的goroutine的處理函數(shù)點(diǎn)擊Goroutine analysis 就會(huì)映射到 /goroutines 路由上。

// src/cmd/trace/goroutines.go:22
func init() {
	http.HandleFunc("/goroutines", httpGoroutines)
	http.HandleFunc("/goroutine", httpGoroutine)
}

讓我們點(diǎn)擊下 Goroutine analysis

進(jìn)入到了一個(gè)顯示代碼調(diào)用位置的列表，列表中的每個(gè)代碼位置都是事件EvGoStart 協(xié)程開始運(yùn)行時(shí)的位置，其中N代表 在采用期間 在這個(gè)位置上有N個(gè)協(xié)程開始過(guò)運(yùn)行。

你可能會(huì)好奇，是怎樣確定這10個(gè)協(xié)程是由同一段代碼執(zhí)行的？runtime在記錄協(xié)程開始執(zhí)行的事件EvGoStart 時(shí)，是會(huì)把棧幀也記錄下來(lái)的，而棧幀中包含函數(shù)名和程序計(jì)數(shù)器(PC)的值，在Goroutine analysis 頁(yè)面 中就是協(xié)程就是按PC的值進(jìn)行分組的。 以下是PC賦值的代碼片段。

// src/internal/trace/goroutines.go:176
case EvGoStart, EvGoStartLabel:
			g := gs[ev.G]
			if g.PC == 0 {
				g.PC = ev.Stk[0].PC
				g.Name = ev.Stk[0].Fn
			}

我們?cè)冱c(diǎn)擊第一行鏈接 nfw/nfw_base/fw/routine.(*Worker).TryRun.func1 N=10 ,這里點(diǎn)擊第一行的鏈接將會(huì)映射到 /goroutine 的路由上(注意路由已經(jīng)不是s結(jié)尾了)，由它的處理函數(shù)進(jìn)行處理。點(diǎn)擊后如圖所示:

現(xiàn)在看到的就是針對(duì)這10個(gè)協(xié)程分別的系統(tǒng)調(diào)用，阻塞，調(diào)度延遲，gc這些統(tǒng)計(jì)信息。

接著我們從上到下挨個(gè)分析: Execution Time 是指著10個(gè)協(xié)程的執(zhí)行時(shí)間占所有協(xié)程執(zhí)行的比例。 接著是用于分析網(wǎng)絡(luò)等待時(shí)間，鎖block時(shí)間，系統(tǒng)調(diào)用阻塞時(shí)間 ，調(diào)度等待時(shí)間的圖片，這些都是分析系統(tǒng)延遲，阻塞問(wèn)題的利器。 這里就不再分析圖了，相信網(wǎng)上會(huì)有很多這種資料。

然后來(lái)看下 表格里的各項(xiàng)指標(biāo):

Execution

是協(xié)程在采樣這段時(shí)間內(nèi)的執(zhí)行時(shí)間。

記錄的方式也很簡(jiǎn)單，在讀取event事件時(shí)，是按時(shí)間線從前往后讀取，每次讀取到協(xié)程開始執(zhí)行的時(shí)間時(shí)，會(huì)記錄下協(xié)程的開始執(zhí)行的時(shí)間戳(時(shí)間戳是包含在Event結(jié)構(gòu)里的)，讀取到協(xié)程停頓事件時(shí)，則會(huì)把停頓時(shí)刻的時(shí)間戳減去開始執(zhí)行的時(shí)間戳 得到 一小段的執(zhí)行時(shí)間，將這小段的時(shí)間 累加到該協(xié)程的總執(zhí)行時(shí)間上。

停頓則是由鎖block，系統(tǒng)調(diào)用阻塞，網(wǎng)絡(luò)等待，搶占調(diào)度造成的。

Network wait

顧名思義，網(wǎng)絡(luò)等待時(shí)長(zhǎng)， 其實(shí)也是和Execution類似的記錄方式，首先記錄下協(xié)程在網(wǎng)絡(luò)等待時(shí)刻的時(shí)間戳，由于event是按時(shí)間線讀取的，當(dāng)讀取到unblock事件時(shí)，再去看協(xié)程上一次是不是網(wǎng)絡(luò)等待事件，如果是的話，則將當(dāng)前時(shí)刻時(shí)間戳減去 網(wǎng)絡(luò)等待時(shí)刻的時(shí)間戳，得到的這一小段時(shí)間，累加到該協(xié)程的總網(wǎng)絡(luò)等待時(shí)長(zhǎng)上。

Sync block，Blocking syscall,Scheduler wait

這三個(gè)時(shí)長(zhǎng) 計(jì)算方式和前面兩張也是類似的，不過(guò)注意下與之相關(guān)聯(lián)的事件的觸發(fā)條件是不同的。

Sync block 時(shí)長(zhǎng)是由于 鎖 sync.mutex ，通道channel，wait group，select case語(yǔ)句產(chǎn)生的阻塞都會(huì)記錄到這里。 下面是相關(guān)代碼片段。

// src/internal/trace/goroutines.go:192
case EvGoBlockSend, EvGoBlockRecv, EvGoBlockSelect,
			EvGoBlockSync, EvGoBlockCond:
			g := gs[ev.G]
			g.ExecTime += ev.Ts - g.lastStartTime
			g.lastStartTime = 0
			g.blockSyncTime = ev.Ts

Blocking syscall 就是系統(tǒng)調(diào)用造成的阻塞了。

Scheduler wait 是協(xié)程從可執(zhí)行狀態(tài)到執(zhí)行狀態(tài)的時(shí)間段，注意協(xié)程是可執(zhí)行狀態(tài)時(shí) 是會(huì)放到p 運(yùn)行隊(duì)列等待被調(diào)度的，只有被調(diào)度后，才會(huì)真正開始執(zhí)行代碼。 這里涉及到golang gpm模型的理解，這里就不再展開了。

后面兩欄就是GC 占用total時(shí)間的一個(gè)百分比了，golang 的gc相關(guān)的知識(shí)也不繼續(xù)展開了。

各種profile 圖

還記得最開始分析trace.out生成的網(wǎng)頁(yè)時(shí)，Goroutine analysis 下面是什么嗎？是各種分析延遲相關(guān)的profile 圖，數(shù)據(jù)的來(lái)源和我們講Goroutine analysis 時(shí)分析單個(gè)Goroutine 的等待時(shí)間的指標(biāo)是一樣的，不過(guò)這里是針對(duì)所有g(shù)oroutine而言。

Network blocking profile (?)
Synchronization blocking profile (?)
Syscall blocking profile (?)
Scheduler latency profile (?)

關(guān)于golang 的這個(gè)trace工具，還允許用戶可以自定義監(jiān)控事件 ，生成的trace網(wǎng)頁(yè)里，User-defined tasks，User-defined regions 就是記錄用戶自定義的一些監(jiān)控事件，這部分的應(yīng)用等到以后再講了。

Minimum mutator utilization 是一個(gè)看gc 對(duì)程序影響情況的曲線圖，這個(gè)等以后有機(jī)會(huì)講gc時(shí)再詳細(xì)談?wù)劻恕?/p>

以上就是golang pprof 監(jiān)控系列 go trace統(tǒng)計(jì)原理與使用解析的詳細(xì)內(nèi)容，更多關(guān)于golang pprof監(jiān)控go trace統(tǒng)計(jì)的資料請(qǐng)關(guān)注腳本之家其它相關(guān)文章！