您好,登錄后才能下訂單哦!
這篇文章主要介紹“golang pprof監(jiān)控系列g(shù)o trace統(tǒng)計原理與使用方法是什么”,在日常操作中,相信很多人在golang pprof監(jiān)控系列g(shù)o trace統(tǒng)計原理與使用方法是什么問題上存在疑惑,小編查閱了各式資料,整理出簡單好用的操作方法,希望對大家解答”golang pprof監(jiān)控系列g(shù)o trace統(tǒng)計原理與使用方法是什么”的疑惑有所幫助!接下來,請跟著小編一起來學(xué)習(xí)吧!
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命令對采樣文件進行分析了。
go tool trace 命令默認(rèn)會使用本地隨機一個端口來啟動一個http服務(wù),頁面顯示如下:
接著我會分析下各個鏈接對應(yīng)的統(tǒng)計信息以及背后進行統(tǒng)計的原理,好的,接下來,正戲開始。
平時在使用prometheus對應(yīng)用服務(wù)進行監(jiān)控時,我們主要還是采用埋點的方式,同樣,go runtime內(nèi)部也是采用這樣的方式對代碼運行過程中的各種事件進行埋點,最后讀取 整理后的埋點數(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分組后 進行設(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開始分析。
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
進入到了一個顯示代碼調(diào)用位置的列表,列表中的每個代碼位置都是事件EvGoStart 協(xié)程開始運行時的位置,其中N代表 在采用期間 在這個位置上有N個協(xié)程開始過運行。
你可能會好奇,是怎樣確定這10個協(xié)程是由同一段代碼執(zhí)行的?runtime在記錄協(xié)程開始執(zhí)行的事件EvGoStart 時,是會把棧幀也記錄下來的,而棧幀中包含函數(shù)名和程序計數(shù)器(PC)的值,在Goroutine analysis 頁面 中就是協(xié)程就是按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 的路由上(注意路由已經(jīng)不是s結(jié)尾了),由它的處理函數(shù)進行處理。點擊后如圖所示:
現(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):
是協(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)度造成的。
顧名思義,網(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ò)等待時長上。
這三個時長 計算方式和前面兩張也是類似的,不過注意下與之相關(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ù)展開了。
還記得最開始分析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 pprof監(jiān)控系列g(shù)o trace統(tǒng)計原理與使用方法是什么”的學(xué)習(xí)就結(jié)束了,希望能夠解決大家的疑惑。理論與實踐的搭配能更好的幫助大家學(xué)習(xí),快去試試吧!若想繼續(xù)學(xué)習(xí)更多相關(guān)知識,請繼續(xù)關(guān)注億速云網(wǎng)站,小編會繼續(xù)努力為大家?guī)砀鄬嵱玫奈恼拢?/p>
免責(zé)聲明:本站發(fā)布的內(nèi)容(圖片、視頻和文字)以原創(chuàng)、轉(zhuǎn)載和分享為主,文章觀點不代表本網(wǎng)站立場,如果涉及侵權(quán)請聯(lián)系站長郵箱:is@yisu.com進行舉報,并提供相關(guān)證據(jù),一經(jīng)查實,將立刻刪除涉嫌侵權(quán)內(nèi)容。