用 GODEBUG 看調度跟蹤

讓 Go 更強大的緣由之一莫過於它的 GODEBUG 工具，GODEBUG 的設置可讓 Go 程序在運行時輸出調試信息，能夠根據你的要求很直觀的看到你想要的調度器或垃圾回收等詳細信息，而且還不須要加裝其它的插件，很是方便，今天咱們將先講解 GODEBUG 的調度器相關內容，但願對你有所幫助。

不過在開始前，沒接觸過的小夥伴得先補補以下前置知識，便於更好的瞭解調試器輸出的信息內容。

原文地址：用 GODEBUG 看調度跟蹤

前置知識

Go scheduler 的主要功能是針對在處理器上運行的 OS 線程分發可運行的 Goroutine，而咱們一提到調度器，就離不開三個常常被提到的縮寫，分別是：

• G：Goroutine，實際上咱們每次調用 go func 就是生成了一個 G。
• P：處理器，通常爲處理器的核數，能夠經過 GOMAXPROCS 進行修改。
• M：OS 線程

這三者交互實際來源於 Go 的 M: N 調度模型，也就是 M 必須與 P 進行綁定，而後不斷地在 M 上循環尋找可運行的 G 來執行相應的任務，若是想具體瞭解能夠詳細閱讀 《Go Runtime Scheduler》，咱們抽其中的工做流程圖進行簡單分析，以下:

1. 當咱們執行 go func() 時，實際上就是建立一個全新的 Goroutine，咱們稱它爲 G。
2. 新建立的 G 會被放入 P 的本地隊列（Local Queue）或全局隊列（Global Queue）中，準備下一步的動做。
3. 喚醒或建立 M 以便執行 G。
4. 不斷地進行事件循環
5. 尋找在可用狀態下的 G 進行執行任務
6. 清除後，從新進入事件循環

而在描述中有提到全局和本地這兩類隊列，其實在功能上來說都是用於存放正在等待運行的 G，可是不一樣點在於，本地隊列有數量限制，不容許超過 256 個。而且在新建 G 時，會優先選擇 P 的本地隊列，若是本地隊列滿了，則將 P 的本地隊列的一半的 G 移動到全局隊列，這其實能夠理解爲調度資源的共享和再平衡。

另外咱們能夠看到圖上有 steal 行爲，這是用來作什麼的呢，咱們都知道當你建立新的 G 或者 G 變成可運行狀態時，它會被推送加入到當前 P 的本地隊列中。但其實當 P 執行 G 完畢後，它也會 「幹活」，它會將其從本地隊列中彈出 G，同時會檢查當前本地隊列是否爲空，若是爲空會隨機的從其餘 P 的本地隊列中嘗試竊取一半可運行的 G 到本身的名下。例子以下：

在這個例子中，P2 在本地隊列中找不到能夠運行的 G，它會執行 work-stealing 調度算法，隨機選擇其它的處理器 P1，並從 P1 的本地隊列中竊取了三個 G 到它本身的本地隊列中去。至此，P一、P2 都擁有了可運行的 G，P1 多餘的 G 也不會被浪費，調度資源將會更加平均的在多個處理器中流轉。

GODEBUG

GODEBUG 變量能夠控制運行時內的調試變量，參數以逗號分隔，格式爲：name=val。本文着重點在調度器觀察上，將會使用以下兩個參數：

• schedtrace：設置 schedtrace=X 參數可使運行時在每 X 毫秒發出一行調度器的摘要信息到標準 err 輸出中。
• scheddetail：設置 schedtrace=X 和 scheddetail=1 可使運行時在每 X 毫秒發出一次詳細的多行信息，信息內容主要包括調度程序、處理器、OS 線程 和 Goroutine 的狀態。

演示代碼

func main() {
    wg := sync.WaitGroup{}
    wg.Add(10)
    for i := 0; i < 10; i++ {
        go func(wg *sync.WaitGroup) {
            var counter int
            for i := 0; i < 1e10; i++ {
                counter++
            }
            wg.Done()
        }(&wg)
    }

    wg.Wait()
}

schedtrace

$ GODEBUG=schedtrace=1000 ./awesomeProject 
SCHED 0ms: gomaxprocs=4 idleprocs=1 threads=5 spinningthreads=1 idlethreads=0 runqueue=0 [0 0 0 0]
SCHED 1000ms: gomaxprocs=4 idleprocs=0 threads=5 spinningthreads=0 idlethreads=0 runqueue=0 [1 2 2 1]
SCHED 2000ms: gomaxprocs=4 idleprocs=0 threads=5 spinningthreads=0 idlethreads=0 runqueue=0 [1 2 2 1]
SCHED 3001ms: gomaxprocs=4 idleprocs=0 threads=5 spinningthreads=0 idlethreads=0 runqueue=0 [1 2 2 1]
SCHED 4010ms: gomaxprocs=4 idleprocs=0 threads=5 spinningthreads=0 idlethreads=0 runqueue=0 [1 2 2 1]
SCHED 5011ms: gomaxprocs=4 idleprocs=0 threads=5 spinningthreads=0 idlethreads=0 runqueue=0 [1 2 2 1]
SCHED 6012ms: gomaxprocs=4 idleprocs=0 threads=5 spinningthreads=0 idlethreads=0 runqueue=0 [1 2 2 1]
SCHED 7021ms: gomaxprocs=4 idleprocs=0 threads=5 spinningthreads=0 idlethreads=0 runqueue=4 [0 1 1 0]
SCHED 8023ms: gomaxprocs=4 idleprocs=0 threads=5 spinningthreads=0 idlethreads=0 runqueue=4 [0 1 1 0]
SCHED 9031ms: gomaxprocs=4 idleprocs=0 threads=5 spinningthreads=0 idlethreads=0 runqueue=4 [0 1 1 0]
SCHED 10033ms: gomaxprocs=4 idleprocs=0 threads=5 spinningthreads=0 idlethreads=0 runqueue=4 [0 1 1 0]
SCHED 11038ms: gomaxprocs=4 idleprocs=0 threads=5 spinningthreads=0 idlethreads=0 runqueue=4 [0 1 1 0]
SCHED 12044ms: gomaxprocs=4 idleprocs=0 threads=5 spinningthreads=0 idlethreads=0 runqueue=4 [0 1 1 0]
SCHED 13051ms: gomaxprocs=4 idleprocs=0 threads=5 spinningthreads=0 idlethreads=0 runqueue=4 [0 1 1 0]
SCHED 14052ms: gomaxprocs=4 idleprocs=2 threads=5 
...

• sched：每一行都表明調度器的調試信息，後面提示的毫秒數表示啓動到如今的運行時間，輸出的時間間隔受 schedtrace 的值影響。
• gomaxprocs：當前的 CPU 核心數（GOMAXPROCS 的當前值）。
• idleprocs：空閒的處理器數量，後面的數字表示當前的空閒數量。
• threads：OS 線程數量，後面的數字表示當前正在運行的線程數量。
• spinningthreads：自旋狀態的 OS 線程數量。
• idlethreads：空閒的線程數量。
• runqueue：全局隊列中中的 Goroutine 數量，然後面的 [0 0 1 1] 則分別表明這 4 個 P 的本地隊列正在運行的 Goroutine 數量。

在上面咱們有提到 「自旋線程」 這個概念，若是你以前沒有了解過相關概念，一聽 「自旋」 確定會比較懵，咱們引用 《Head First of Golang Scheduler》 的內容來講明：

自旋線程的這個說法，是由於 Go Scheduler 的設計者在考慮了 「OS 的資源利用率」 以及 「頻繁的線程搶佔給 OS 帶來的負載」 以後，提出了 「Spinning Thread」 的概念。也就是當 「自旋線程」 沒有找到可供其調度執行的 Goroutine 時，並不會銷燬該線程 ，而是採起 「自旋」 的操做保存了下來。雖然看起來這是浪費了一些資源，可是考慮一下 syscall 的情景就能夠知道，比起 「自旋"，線程間頻繁的搶佔以及頻繁的建立和銷燬操做可能帶來的危害會更大。

scheddetail

若是咱們想要更詳細的看到調度器的完整信息時，咱們能夠增長 scheddetail 參數，就可以更進一步的查看調度的細節邏輯，以下：

$ GODEBUG=scheddetail=1,schedtrace=1000 ./awesomeProject
SCHED 1000ms: gomaxprocs=4 idleprocs=0 threads=5 spinningthreads=0 idlethreads=0 runqueue=0 gcwaiting=0 nmidlelocked=0 stopwait=0 sysmonwait=0
  P0: status=1 schedtick=2 syscalltick=0 m=3 runqsize=3 gfreecnt=0
  P1: status=1 schedtick=2 syscalltick=0 m=4 runqsize=1 gfreecnt=0
  P2: status=1 schedtick=2 syscalltick=0 m=0 runqsize=1 gfreecnt=0
  P3: status=1 schedtick=1 syscalltick=0 m=2 runqsize=1 gfreecnt=0
  M4: p=1 curg=18 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=false lockedg=-1
  M3: p=0 curg=22 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=false lockedg=-1
  M2: p=3 curg=24 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=false lockedg=-1
  M1: p=-1 curg=-1 mallocing=0 throwing=0 preemptoff= locks=1 dying=0 spinning=false blocked=false lockedg=-1
  M0: p=2 curg=26 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=false lockedg=-1
  G1: status=4(semacquire) m=-1 lockedm=-1
  G2: status=4(force gc (idle)) m=-1 lockedm=-1
  G3: status=4(GC sweep wait) m=-1 lockedm=-1
  G17: status=1() m=-1 lockedm=-1
  G18: status=2() m=4 lockedm=-1
  G19: status=1() m=-1 lockedm=-1
  G20: status=1() m=-1 lockedm=-1
  G21: status=1() m=-1 lockedm=-1
  G22: status=2() m=3 lockedm=-1
  G23: status=1() m=-1 lockedm=-1
  G24: status=2() m=2 lockedm=-1
  G25: status=1() m=-1 lockedm=-1
  G26: status=2() m=0 lockedm=-1

在這裏咱們抽取了 1000ms 時的調試信息來查看，信息量比較大，咱們先從每個字段開始瞭解。以下：

G

• status：G 的運行狀態。
• m：隸屬哪個 M。
• lockedm：是否有鎖定 M。

在第一點中咱們有提到 G 的運行狀態，這對於分析內部流轉很是的有用，共涉及以下 9 種狀態：

狀態	值	含義
_Gidle	0	剛剛被分配，尚未進行初始化。
_Grunnable	1	已經在運行隊列中，尚未執行用戶代碼。
_Grunning	2	不在運行隊列裏中，已經能夠執行用戶代碼，此時已經分配了 M 和 P。
_Gsyscall	3	正在執行系統調用，此時分配了 M。
_Gwaiting	4	在運行時被阻止，沒有執行用戶代碼，也不在運行隊列中，此時它正在某處阻塞等待中。
_Gmoribund_unused	5	還沒有使用，可是在 gdb 中進行了硬編碼。
_Gdead	6	還沒有使用，這個狀態多是剛退出或是剛被初始化，此時它並無執行用戶代碼，有可能有也有可能沒有分配堆棧。
_Genqueue_unused	7	還沒有使用。
_Gcopystack	8	正在複製堆棧，並無執行用戶代碼，也不在運行隊列中。

在理解了各種的狀態的意思後，咱們結合上述案例看看，以下：

G1: status=4(semacquire) m=-1 lockedm=-1
G2: status=4(force gc (idle)) m=-1 lockedm=-1
G3: status=4(GC sweep wait) m=-1 lockedm=-1
G17: status=1() m=-1 lockedm=-1
G18: status=2() m=4 lockedm=-1

在這個片斷中，G1 的運行狀態爲 _Gwaiting，並無分配 M 和鎖定。這時候你可能好奇在片斷中括號裏的是什麼東西呢，實際上是由於該 status=4 是表示 Goroutine 在運行時時被阻止，而阻止它的事件就是 semacquire 事件，是由於 semacquire 會檢查信號量的狀況，在合適的時機就調用 goparkunlock 函數，把當前 Goroutine 放進等待隊列，並把它設爲 _Gwaiting 狀態。

那麼在實際運行中還有什麼緣由會致使這種現象呢，咱們一塊兒看看，以下：

waitReasonZero                                    // ""
    waitReasonGCAssistMarking                         // "GC assist marking"
    waitReasonIOWait                                  // "IO wait"
    waitReasonChanReceiveNilChan                      // "chan receive (nil chan)"
    waitReasonChanSendNilChan                         // "chan send (nil chan)"
    waitReasonDumpingHeap                             // "dumping heap"
    waitReasonGarbageCollection                       // "garbage collection"
    waitReasonGarbageCollectionScan                   // "garbage collection scan"
    waitReasonPanicWait                               // "panicwait"
    waitReasonSelect                                  // "select"
    waitReasonSelectNoCases                           // "select (no cases)"
    waitReasonGCAssistWait                            // "GC assist wait"
    waitReasonGCSweepWait                             // "GC sweep wait"
    waitReasonChanReceive                             // "chan receive"
    waitReasonChanSend                                // "chan send"
    waitReasonFinalizerWait                           // "finalizer wait"
    waitReasonForceGGIdle                             // "force gc (idle)"
    waitReasonSemacquire                              // "semacquire"
    waitReasonSleep                                   // "sleep"
    waitReasonSyncCondWait                            // "sync.Cond.Wait"
    waitReasonTimerGoroutineIdle                      // "timer goroutine (idle)"
    waitReasonTraceReaderBlocked                      // "trace reader (blocked)"
    waitReasonWaitForGCCycle                          // "wait for GC cycle"
    waitReasonGCWorkerIdle                            // "GC worker (idle)"

咱們經過以上 waitReason 能夠了解到 Goroutine 會被暫停運行的緣由要素，也就是會出如今括號中的事件。

M

• p：隸屬哪個 P。
• curg：當前正在使用哪一個 G。
• runqsize：運行隊列中的 G 數量。
• gfreecnt：可用的G（狀態爲 Gdead）。
• mallocing：是否正在分配內存。
• throwing：是否拋出異常。
• preemptoff：不等於空字符串的話，保持 curg 在這個 m 上運行。

P

• status：P 的運行狀態。
• schedtick：P 的調度次數。
• syscalltick：P 的系統調用次數。
• m：隸屬哪個 M。
• runqsize：運行隊列中的 G 數量。
• gfreecnt：可用的G（狀態爲 Gdead）。

狀態	值	含義
_Pidle	0	剛剛被分配，尚未進行進行初始化。
_Prunning	1	當 M 與 P 綁定調用 acquirep 時，P 的狀態會改變爲 _Prunning。
_Psyscall	2	正在執行系統調用。
_Pgcstop	3	暫停運行，此時系統正在進行 GC，直至 GC 結束後纔會轉變到下一個狀態階段。
_Pdead	4	廢棄，再也不使用。

總結

經過本文咱們學習到了調度的一些基礎知識，再經過神奇的 GODEBUG 掌握了觀察調度器的方式方法，你想一想，是否是能夠和我上一篇文章的 go tool trace 來結合使用呢，在實際的使用中，相似的辦法有不少，組合巧用是重點。

參考

• Debugging performance issues in Go programs
• A whirlwind tour of Go’s runtime environment variables
• Go調度器系列（2）宏觀看調度器
• Go's work-stealing scheduler
• Scheduler Tracing In Go
• Head First of Golang Scheduler
• goroutine 的狀態切換
• Environment_Variables