Go 調度器跟蹤
這是William Kennedy寫的第二篇文章： Scheduler Tracing In Go , 第一篇為Stack Traces In Go。
本文主要介紹如何跟蹤Go的調度器Scheduler的活動。
介紹
我喜歡Go的原因之一就是能夠產生概要(profiling)和調試信息。當你的程序運行時， GODEBUG 環境變量可以產生運行時的調試信息。你可以請求垃圾回收器和調度器(scheduler)的摘要信息和細節。關鍵是你不需要額外創建單獨的編譯程序就可以實現。
在本文中，我將演示如何理解一個簡單的并發Go程序的調度器跟蹤信息。如果你已經有Go調度器的基本概念，對閱讀本文會很有幫助， 在開始下面的介紹前我建議你閱讀下面的兩篇文章：
代碼
下面的代碼就是用來演示用的例子。
列表1
package main
import (
"sync"
"time"
)
func main() {
var wg sync.WaitGroup
wg.Add(10)
for i :=0; i <10; i++ {
go work(&wg)
}
wg.Wait()
// Wait to see the global run queue deplete.
time.Sleep(3 * time.Second)
}
func work(wg *sync.WaitGroup) {
time.Sleep(time.Second)
var counter int
for i :=0; i <1e10; i++ {
counter++
}
wg.Done()
}
|
列表1的第12行使用一個for循環創建10個goroutine，第16行main函數中等待所有的goroutine完成任務。第22行的work函數先sleep 1秒，然后計數 10億次。一旦計數完成，調用waitGroup的Done方法然后返回。
首先 go build 程序，然后運行時設置GODEBUG環境變量。這個變量會被運行時讀取，所以Go命令也會產生跟蹤信息。如果在運行 go run 命令的時候設置了GODEBUG變量，在程序運行之前就會看到跟蹤信息。
所以還是讓我們先編譯程序：
gobuild example.go
調度器摘要信息
schedtrace參數告訴運行時打印一行調度器的摘要信息到標準err輸出中，時間間隔可以指定，單位毫秒，如下所示：
GOMAXPROCS=1GODEBUG=schedtrace=1000./example
譯者注： 如果在windows下可以運行 set GOMAXPROCS=1 && set GODEBUG=schedtrace=1000 && example
程序開始后每個一秒就會打印一行調度器的概要信息，程序本身沒有任何輸出，所以我們只關注輸出的跟蹤信息。讓我們先看前兩行：
SCHED 0ms:gomaxprocs=1idleprocs=0threads=2spinningthreads=0idlethreads=0 runqueue=0[1] SCHED 1009ms:gomaxprocs=1idleprocs=0threads=3spinningthreads=0idlethreads=1 runqueue=0[9]
讓我們分解每一個項，看看它們分別代表什么含義。
| 輸出項 | 意義 |
|---|---|
| 1009ms | 自從程序開始的毫秒數 |
| gomaxprocs=1 | 配置的處理器數(邏輯的processor，也就是Go模型中的P,會通過操作系統的線程綁定到一個物理處理器上) |
| threads=3 | 運行期管理的線程數，目前三個線程 |
| idlethreads=1 | 空閑的線程數,當前一個線程空閑，兩個忙 |
| idleprocs=0 | 空閑的處理器數,當前0個空閑 |
| runqueue=0 | 在全局的run隊列中的goroutine數，目前所有的goroutine都被移動到本地run隊列 |
| [9] | 本地run隊列中的goroutine數，目前9個goroutine在本地run隊列中等待 |
Go運行時給了我們很多有用的摘要信息。當我們看第一秒的跟蹤數據時，我們看到一個goroutine正在運行，而其它9個都在等待：
圖1中處理器由字符P代表，線程由M代表，goroutine由G代表。我們看到全局run隊列為空，處理器正在執行一個goroutine。其余9在本地隊列中等待。
如果我們配置多個處理器會怎樣呢？讓我們增加GOMAXPROCS 看看輸出結果:
GOMAXPROCS=2GODEBUG=schedtrace=1000./example SCHED 0ms:gomaxprocs=2idleprocs=1threads=2spinningthreads=0 idlethreads=0runqueue=0[00] SCHED 1002ms:gomaxprocs=2idleprocs=0threads=4spinningthreads=1 idlethreads=1runqueue=0[04] SCHED 2006ms:gomaxprocs=2idleprocs=0threads=4spinningthreads=0 idlethreads=1runqueue=0[44] … SCHED 6024ms:gomaxprocs=2idleprocs=0threads=4spinningthreads=0 idlethreads=1runqueue=2[33] … SCHED 10049ms:gomaxprocs=2idleprocs=0threads=4spinningthreads=0 idlethreads=1runqueue=4[22] … SCHED 13067ms:gomaxprocs=2idleprocs=0threads=4spinningthreads=0 idlethreads=1runqueue=6[11] … SCHED 17084ms:gomaxprocs=2idleprocs=0threads=4spinningthreads=0 idlethreads=1runqueue=8[00] … SCHED 21100ms:gomaxprocs=2idleprocs=2threads=4spinningthreads=0 idlethreads=2runqueue=0[00]
讓我們將視線放在第二秒：
SCHED 2002ms: gomaxprocs=2idleprocs=0threads=4spinningthreads=0 idlethreads=1runqueue=0[44] 2002ms : Thisisthetraceforthe2secondmark. gomaxprocs=2:2processors are configuredforthis program. threads=4:4threads exist.2forprocessorsand2fortheruntime. idlethreads=1:1idle thread (3threadsrunning). idleprocs=0:0processors are idle (2processors busy). runqueue=0: All runnable goroutines have been movedtoalocalrunqueue. [44] :4goroutines are waiting inside eachlocalrunqueue.
讓我們看第二秒的信息，可以看到goroutine是如何被處理器運行的。我們也可以看到有8個goroutine在本地run隊列中等待，每個本地run隊列包含4個等待的goroutine。
讓我們再來看第6秒的信息：
SCHED 6024ms:gomaxprocs=2idleprocs=0threads=4spinningthreads=0 idlethreads=1runqueue=2[33] idleprocs=0:0processors are idle (2processors busy). runqueue=2:2goroutines returnedandare waiting to be terminated. [33] :3goroutines are waiting inside each local run queue.
第6秒數據有些變化，如圖3所示，兩個goroutine完成了它們的任務，放回到全局run隊列中。當然我們還是有兩個goruntine在運行(G6,G7)，每個P運行一個。每個本地run隊列中還有3個goroutine在等待。
注意:
在很多情況下goroutine在終止前并沒有被放回到全局run隊列。本文中的例子比較特殊，它的方法體是一個for循環，并沒有調用其它函數，而且運行時間超過10ms。10毫秒是調度器的調度標桿，過了10毫秒的執行時間，調度器就會嘗試占用(preempt)這個goroutine。本例中的goroutine沒有被占用是因為它們沒有調用其它函數。本例中一旦goroutine執行到wg.Done調用，它們立即被占用，然后移動到全局run隊列等待終止。
在17秒我們看到只有兩個goroutine還在運行:
SCHED 17084ms:gomaxprocs=2idleprocs=0threads=4spinningthreads=0 idlethreads=1runqueue=8[00] idleprocs=0:0processors are idle (2processors busy). runqueue=8:8goroutines returnedandare waiting to be terminated. [00] : No goroutines are waiting inside any local run queue.
從圖4可以看出，8個goroutine被移動到全局run隊列等待終止。兩個goroutine(G12和G13)還在運行，本地run隊列都為空。
最后在第21秒：
SCHED 21100ms:gomaxprocs=2idleprocs=2threads=4spinningthreads=0 idlethreads=2runqueue=0[00] idleprocs=2:2processors are idle (0processors busy). runqueue=0: All the goroutines that wereinthe queue have been terminated. [00] : No goroutines are waiting inside any local run queue.
如圖5所示，這時那10個goroutine都已經完成任務被終止。
調度器跟蹤信息的細節
調度器的摘要信息很有幫助，但是有時候你需要更深入的了解它的細節。在這種情況下，我們可以使用scheddetail 參數，可以提供處理器P,線程M和goroutine G的細節。讓我們再運行一下程序，增加scheddetail 參數:
GOMAXPROCS=2GODEBUG=schedtrace=1000,scheddetail=1./example
下面的日志是第4秒的輸出：
SCHED 4028ms:gomaxprocs=2idleprocs=0threads=4spinningthreads=0 idlethreads=1runqueue=2gcwaiting=0nmidlelocked=0stopwait=0sysmonwait=0 P0: status=1schedtick=10syscalltick=0m=3runqsize=3gfreecnt=0 P1: status=1schedtick=10syscalltick=1m=2runqsize=3gfreecnt=0 M3: p=0curg=4mallocing=0throwing=0gcing=0locks=0dying=0helpgc=0spinning=0blocked=0lockedg=-1 M2: p=1curg=10mallocing=0throwing=0gcing=0locks=0dying=0helpgc=0spinning=0blocked=0lockedg=-1 M1: p=-1curg=-1mallocing=0throwing=0gcing=0locks=1dying=0helpgc=0spinning=0blocked=0lockedg=-1 M0: p=-1curg=-1mallocing=0throwing=0gcing=0locks=0dying=0helpgc=0spinning=0blocked=0lockedg=-1 G1: status=4(semacquire)m=-1lockedm=-1 G2: status=4(force gc (idle))m=-1lockedm=-1 G3: status=4(GC sweep wait)m=-1lockedm=-1 G4: status=2(sleep)m=3lockedm=-1 G5: status=1(sleep)m=-1lockedm=-1 G6: status=1(stack growth)m=-1lockedm=-1 G7: status=1(sleep)m=-1lockedm=-1 G8: status=1(sleep)m=-1lockedm=-1 G9: status=1(stack growth)m=-1lockedm=-1 G10: status=2(sleep)m=2lockedm=-1 G11: status=1(sleep)m=-1lockedm=-1 G12: status=1(sleep)m=-1lockedm=-1 G13: status=1(sleep)m=-1lockedm=-1 G17: status=4(timer goroutine (idle))m=-1lockedm=-1
摘要信息是類似的，但是包含了處理器、線程和goroutine的信息。首先看一下處理器P的信息：
P0: status=1schedtick=10syscalltick=0m=3runqsize=3gfreecnt=0 P1: status=1schedtick=10syscalltick=1m=2runqsize=3gfreecnt=0
我們設置了兩個處理器，因此有兩行數據。下面是線程的信息：
M3: p=0curg=4mallocing=0throwing=0gcing=0locks=0dying=0helpgc=0 spinning=0blocked=0lockedg=-1 M2: p=1curg=10mallocing=0throwing=0gcing=0locks=0dying=0helpgc=0 spinning=0blocked=0lockedg=-1 M1: p=-1curg=-1mallocing=0throwing=0gcing=0locks=1dying=0helpgc=0 spinning=0blocked=0lockedg=-1 M0: p=-1curg=-1mallocing=0throwing=0gcing=0locks=0dying=0helpgc=0 spinning=0blocked=0lockedg=-1
在摘要信息中我們看到線程設置為4(threads=4)，所以下面會有4行關于線程M的信息。而且日志細節顯示了哪個線程隸屬哪個處理器 M3: p=0 ：
P0: status=1schedtick=10syscalltick=0m=3runqsize=3gfreecnt=0 M3: p=0curg=4mallocing=0throwing=0gcing=0locks=0dying=0helpgc=0 spinning=0blocked=0lockedg=-1
我們看到線程M3隸屬P0。
G代表goroutine。第4秒我們看到有14個goroutine, 但是自程序啟動已經創建了17個線程。我們怎么知道的17個線程呢，這是從最后的goroutine的標志 G17 得到:
G17: status=4(timer goroutine (idle))m=-1lockedm=-1
如果程序持續創建goroutine，這個數會線性的增大。如果使用標準庫net/http處理http請求，因為每個連接都會創建一個goroutine，我們可以根據這個數據得到多少request被處理，當然得在程序不會創建其它的goroutine情況下這個數才能作為預估的數量。
讓我們看看運行main函數的goroutine：
G1: status=4(semacquire)m=-1lockedm=-1
可以看到這個goroutine的status是4, 阻塞在semacquire上(WaitGroup的Wait方法)。
為了更好的理解其它goroutine的狀態，我們需要了解每個status值代表的含義。下面是一個列表：
status: http://golang.org/src/runtime/runtime.h Gidle, // 0 Grunnable, // 1 runnable and on a run queue Grunning, // 2 running Gsyscall, // 3 performing a syscall Gwaiting, // 4 waiting for the runtime Gmoribund_unused, // 5 currently unused, but hardcoded in gdb scripts Gdead, // 6 goroutine is dead Genqueue, // 7 only the Gscanenqueue is used Gcopystack, // 8 in this state when newstack is moving the stack
看看我們創建的10個goroutine,現在我們能更好的理解它們的狀態：
// Goroutines running ina processor. (idleprocs=0) G4: status=2(sleep)m=3lockedm=-1– Thread M3 / Processor P0 G10: status=2(sleep)m=2lockedm=-1– Thread M2 / Processor P1 // Goroutines waiting to be run on a particular processor. (runqsize=3) G5: status=1(sleep)m=-1lockedm=-1 G7: status=1(sleep)m=-1lockedm=-1 G8: status=1(sleep)m=-1lockedm=-1 // Goroutines waiting to be run on a particular processor. (runqsize=3) G11: status=1(sleep)m=-1lockedm=-1 G12: status=1(sleep)m=-1lockedm=-1 G13: status=1(sleep)m=-1lockedm=-1 // Goroutines waiting on the global run queue. (runqueue=2) G6: status=1(stack growth)m=-1lockedm=-1 G9: status=1(stack growth)m=-1lockedm=-1
了解了調度器的基本概念和我們的程序的行為，我們可以深入了解Go是如何進行調度的，每個P,M,G的狀態。
結論
GODEBUG變量非常好，可以深入了解調度器的行為。它也可以告訴你你的程序的行為。如果你想了解更多，動手寫一些簡單的程序，跟蹤調度器的運行,然后就可以跟蹤更復雜的程序了。