引言

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

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

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

golang版本 go1.17.12

先簡單說下go tool trace 的使用場景，在分析延遲性問題的時候，go tool trace能起到很重要的作用，因為它會記錄各種延遲事件并且對其進(jìn)行時長分析，連關(guān)鍵代碼位置也能找出來。

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

接著我們簡單看下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的功能其實比較容易，用trace.Start 便可以開啟trace的事件采樣功能，trace.Stop 則停止采用，采樣的數(shù)據(jù)會記錄到trace.Start 傳來的輸出流參數(shù)里，這里我是將一個名為trace.out 的文件作為輸出流參數(shù)傳入。

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

go tool trace 命令默認(rèn)會使用本地隨機一個端口來啟動一個http服務(wù)，頁面顯示如下:

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

統(tǒng)計原理介紹

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

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

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

在traceEvent 內(nèi)部同時也會獲取到當(dāng)前事件發(fā)生時的線程信息，協(xié)程信息，p運行隊列信息，并把這些信息同事件一起記錄到一個緩沖區(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
}

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

在示例代碼里，trace.Start 方法傳入名為trace.out文件的輸出流參數(shù),所以在采樣過程中，runtime會將采集到的事件字節(jié)流輸出到trace.out文件，trace.out文件在被讀取出的時候 是用了一個叫做Event的結(jié)構(gòu)體來表示這些監(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
}

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

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

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

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

接下來我們來挨個分析下trace頁面的統(tǒng)計信息以及背后的統(tǒng)計原理。

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

Goroutine analysis

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

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

讓我們點擊下 Goroutine analysis

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

你可能會好奇，是怎樣確定這10個協(xié)程是由同一段代碼執(zhí)行的？runtime在記錄協(xié)程開始執(zhí)行的事件EvGoStart 時，是會把棧幀也記錄下來的，而棧幀中包含函數(shù)名和程序計數(shù)器(PC)的值，在Goroutine analysis 頁面 中就是協(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
			}

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

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

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

然后來看下 表格里的各項指標(biāo):

Execution

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

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

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

Network wait

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

Sync block，Blocking syscall,Scheduler wait

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

Sync block 時長是由于 鎖 sync.mutex ，通道channel，wait group，select case語句產(chǎn)生的阻塞都會記錄到這里。 下面是相關(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)的時間段，注意協(xié)程是可執(zhí)行狀態(tài)時 是會放到p 運行隊列等待被調(diào)度的，只有被調(diào)度后，才會真正開始執(zhí)行代碼。 這里涉及到golang gpm模型的理解，這里就不再展開了。

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

各種profile 圖

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

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

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

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

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

最新評論