trace view 視圖簡介

在go代碼里，我們可以通過trace.Start和trace.Stop方法開啟和關(guān)閉trace統(tǒng)計，之后我們會得到一個trace文件，可以用go tool trace命令打開它·。

go tool trace -http=:8080  trace799152559

在瀏覽器的打開界面，可以看到trace view視圖包含了幾個維度的統(tǒng)計信息。

view trace 和 goroutine analysis 都是時間線的視圖，不過觀看的角度不同，view trace 是從processor(Gpm模型中的p) 角度，goroutine analysis 則是從協(xié)程角度。

接著是各種類型的profile 視圖，包含Network,Sync block,syscall block,scheduler latancy ，這些都可以用于分析系統(tǒng)延遲。

然后是用戶自定義的埋點統(tǒng)計，由于本節(jié)主要是看原生的trace view視圖含義，所以可以先略去這部分。

接著是minimum mutator utilization的視圖，它可以用于分析垃圾回收對應(yīng)用程序的影響。因為協(xié)程在分配內(nèi)存時，在某些條件下也會觸發(fā)垃圾回收，這將導(dǎo)致這部分時間內(nèi)，協(xié)程不能執(zhí)行用戶程序邏輯，所以這個視圖能夠看到cpu用了多少時間在執(zhí)行業(yè)務(wù)程序，多少時間用于垃圾回收。

接下來，我們仔細分析下各部分視圖的含義。

view trace

如上圖所示，整個view trace 分為兩個部分，stats和procs部分。

stats

stats 部分統(tǒng)計了在時間線上協(xié)程，線程數(shù)量，以及堆棧大小的變化情況。

當點擊某個一欄數(shù)據(jù)時，還會顯示統(tǒng)計詳情，比如點擊時間線上線程這一欄，

如上圖所示，trace view視圖最下方會出現(xiàn)當前時刻，處于運行狀態(tài)和系統(tǒng)調(diào)用狀態(tài)的線程數(shù)量。

procs

stats部分比較好理解，我們再來看看procs部分，首先來看下GC這一欄。

GC這一欄也就是視圖中時間線上藍色這一段表示程序在這段時間內(nèi)，在進行垃圾回收。注意垃圾回收并不是全過程都會STW的，所以在GC這段時間，應(yīng)用程序還是會對外提供服務(wù)的。并且點擊藍色區(qū)域，在視圖下方還會顯示GC開始的堆棧。

注意: golang的垃圾回收除了定時掃描回收內(nèi)存，還會在分配內(nèi)存時，判斷正在執(zhí)行的協(xié)程是否需要執(zhí)行垃圾回收邏輯，如果需要，則會執(zhí)行g(shù)cStart的邏輯，mallocgc就是golang進行內(nèi)存分配的函數(shù)，所以你可以看到圖中的gc正是由于當前協(xié)程分配內(nèi)存才觸發(fā)執(zhí)行的，并且同一時期，只能有一個協(xié)程執(zhí)行g(shù)cStart邏輯。

接著簡單說下Network和syscall 事件，它們在時間線上的點都是解除阻塞時的時間點。

然后來看proc這一欄，proc代表的是processor ，它數(shù)量一般與cpu核心數(shù)相同，也可以通過GOMAXPROCS 設(shè)置其數(shù)量，協(xié)程需要放到proc隊里里進行調(diào)度執(zhí)行，proc的時間線上顯示的則是各個協(xié)程在其上的運行時間。放大trace視圖后會看的更加明顯。如下圖所示:

trace視圖中，按w是放大，s是縮小，a是左移，d是右移。

這里其實要特別注意的是Outgoing flow 并不是直接導(dǎo)致協(xié)程在p隊列上被切走的事件，實際上導(dǎo)致協(xié)程被切走的事件是阻塞事件，Outgoing flow 指的是阻塞事件之后被喚醒的那個時候的事件埋點。

實際上，當前的trace view 視圖繪制的時間線不會對阻塞事件進行繪制，只會對EvGoUnblock 事件進行繪制（具體為啥這樣設(shè)計，我也不知道了????‍♀?）不過從協(xié)程離開p隊列時的堆棧也足夠說明協(xié)程被切走的原因了。

goroutine analysis

接著我們來看下trace文件中對協(xié)程信息的分析。

點擊goroutine analysis，出現(xiàn)下面的截圖:

左邊是協(xié)程創(chuàng)建時候的堆棧，右邊N 代碼在這行代碼上一共創(chuàng)建了多少個協(xié)程。隨便選擇一行點進去，可以出現(xiàn)下面的截圖,

如上圖所示，有各種的profile graph，這里是對下面所有協(xié)程進行統(tǒng)一分析得到的graph圖 ，分別是:

Network Wait Time(網(wǎng)絡(luò)調(diào)用時等待，直到數(shù)據(jù)可達時被喚醒)

Sync Block Time(mutex，channel，wait.Group產(chǎn)生的阻塞)

Blocking Syscall Time(系統(tǒng)調(diào)用產(chǎn)生的阻塞)

Scheduler Wait Time(協(xié)程阻塞后被喚醒并不會立馬執(zhí)行，而是在隊列里等待被調(diào)度，這個時間就是等待被調(diào)度的時間)

而最下面的表格則是每個協(xié)程在這些維度上的消耗時間,這里要注意下兩個gc相關(guān)的時間只有GC sweeping 才會阻塞協(xié)程 ，GC sweeping指的是協(xié)程在清除回收內(nèi)存時的處理時間，而GC pause 指的是采樣過程中整個gc的時長，這一列每個協(xié)程都是一樣的。

請注意，GC 過程中只有發(fā)送STW時才會讓協(xié)程阻塞。

profile graph

關(guān)于trcace 分析數(shù)據(jù) 除了像剛剛的特定堆棧產(chǎn)生的協(xié)程做各種延遲維度的分析，trace界面還提供了一個看所有協(xié)程的延遲維度的profile graph, 兩者的原理都是一致的，只是后者原數(shù)據(jù)多一些。

拿其中一個維度Scheduler Wait Time的 graph舉例:

指向每個函數(shù)框的箭頭都攜帶了一個時間，例如 273.31us，它代表 函數(shù)servserv.init.func1函數(shù)等待協(xié)程調(diào)度的等待時間，注意這個時間不包含它的子函數(shù)的時間。時間越大，函數(shù)框越大，所以，你在看此類的圖的時候，找最大的框就能發(fā)現(xiàn)延遲所在。

Minimum mutator utilization

最后我們來看下Minimum mutator utilization 這個視圖。這個視圖能夠觀測到垃圾回收對應(yīng)用程序的影響。

如上圖所示，縱坐標表示應(yīng)用除gc外，占用cpu的比例。值越高，說明應(yīng)用得到的cpu資源越多，gc影響越小，最大值是1表示100%得到cpu資源。圖中，最后應(yīng)用cpu占用率達到了100%，可以暫時不用去管gc方面的影響。如果發(fā)現(xiàn)圖中cpu資源長時間不能漲上去，則說明程序受gc影響比較大，應(yīng)該對gc進行優(yōu)化，像下面這種情況就應(yīng)該優(yōu)化gc了。

以上就是golang trace view視圖詳解的詳細內(nèi)容，更多關(guān)于golang trace view的資料請關(guān)注腳本之家其它相關(guān)文章！