golang?pprof監控系列go?trace統計原理與使用方法是什么

這篇文章主要介紹“golang pprof監控系列go trace統計原理與使用方法是什么”，在日常操作中，相信很多人在golang pprof監控系列go trace統計原理與使用方法是什么問題上存在疑惑，小編查閱了各式資料，整理出簡單好用的操作方法，希望對大家解答”golang pprof監控系列go 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 則停止采用，采樣的數據會記錄到trace.Start 傳來的輸出流參數里，這里我是將一個名為trace.out 的文件作為輸出流參數傳入。

采樣結束后便可以通過 go tool trace trace.out命令對采樣文件進行分析了。

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

接著我會分析下各個鏈接對應的統計信息以及背后進行統計的原理，好的，接下來，正戲開始。

統計原理介紹

平時在使用prometheus對應用服務進行監控時，我們主要還是采用埋點的方式，同樣，go runtime內部也是采用這樣的方式對代碼運行過程中的各種事件進行埋點，最后讀取 整理后的埋點數據，形成我們在網頁上看的trace監控圖。

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

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

在traceEvent 內部同時也會獲取到當前事件發生時的線程信息，協程信息，p運行隊列信息，并把這些信息同事件一起記錄到一個緩沖區里。

// 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方法的時候，同時會啟動一個協程不斷讀取緩沖區中的內容到strace.Start 的參數中。

在示例代碼里，trace.Start 方法傳入名為trace.out文件的輸出流參數,所以在采樣過程中，runtime會將采集到的事件字節流輸出到trace.out文件，trace.out文件在被讀取出的時候 是用了一個叫做Event的結構體來表示這些監控事件。

// 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在運行協程時，是將協程調度到P上運行的，G 是協程id，還有棧id StkID ，棧幀 Stk，以及事件發生時可以攜帶的一些參數Args，SArgs。 Type 是事件的枚舉字段，Ts是事件發生的時間戳信息，Link 是與事件關聯的其他事件，用于計算關聯事件的耗時。

拿計算系統調用耗時來說，系統調用相關的事件有GoSysExit,GoSysCall 分別是系統調用退出事件和系統調用開始事件，所以GoSysExit.Ts - GoSysCall.Ts 就是系統調用的耗時。

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

很明顯Link 字段不是在runtime 記錄監控事件時設置的，而是在讀取trace.out里的監控事件時，將事件信息按照協程id分組后 進行設置的。同一個協程的 GoSysExit.Ts - GoSysCall.Ts 就是該協程的系統調用耗時。

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

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

Goroutine analysis

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

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

讓我們點擊下 Goroutine analysis

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

你可能會好奇，是怎樣確定這10個協程是由同一段代碼執行的？runtime在記錄協程開始執行的事件EvGoStart 時，是會把棧幀也記錄下來的，而棧幀中包含函數名和程序計數器(PC)的值，在Goroutine analysis 頁面 中就是協程就是按PC的值進行分組的。 以下是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 的路由上(注意路由已經不是s結尾了)，由它的處理函數進行處理。點擊后如圖所示:

現在看到的就是針對這10個協程分別的系統調用，阻塞，調度延遲，gc這些統計信息。

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

然后來看下 表格里的各項指標:

Execution

是協程在采樣這段時間內的執行時間。

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

停頓則是由鎖block，系統調用阻塞，網絡等待，搶占調度造成的。

Network wait

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

Sync block，Blocking syscall,Scheduler wait

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

Sync block 時長是由于 鎖 sync.mutex ，通道channel，wait group，select case語句產生的阻塞都會記錄到這里。 下面是相關代碼片段。

// 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 就是系統調用造成的阻塞了。

Scheduler wait 是協程從可執行狀態到執行狀態的時間段，注意協程是可執行狀態時 是會放到p 運行隊列等待被調度的，只有被調度后，才會真正開始執行代碼。 這里涉及到golang gpm模型的理解，這里就不再展開了。

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

各種profile 圖

還記得最開始分析trace.out生成的網頁時，Goroutine analysis 下面是什么嗎？是各種分析延遲相關的profile 圖，數據的來源和我們講Goroutine analysis 時分析單個Goroutine 的等待時間的指標是一樣的，不過這里是針對所有goroutine而言。

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

到此，關于“golang pprof監控系列go trace統計原理與使用方法是什么”的學習就結束了，希望能夠解決大家的疑惑。理論與實踐的搭配能更好的幫助大家學習，快去試試吧！若想繼續學習更多相關知識，請繼續關注億速云網站，小編會繼續努力為大家帶來更多實用的文章！