Go 環境變量 - GODEBUG 詳解

簡介

GODEBUG 環境變量可以控制程序運行時的調度信息輸出,方便開發者瞭解內部細節。

語法是通過逗號分割多個鍵值對,例如:

# 運行 main.go, 每秒輸出 1 次調度信息GODEBUG=scheddetail=1,schedtrace=1000 go run main.go

常用參數

G3YBAp

示例程序

本文後面的幾個用例,全部使用該程序演示。

package main

import (
 "sync"
 "time"
)

func main() {
 var wg sync.WaitGroup

 for i := 0; i < 10; i++ {
  wg.Add(1)

  go func() {
   defer wg.Done()

   time.Sleep(1 * time.Second)
  }()
 }

 wg.Wait()
}

輸出調度基礎信息

執行命令

GODEBUG=schedtrace=1000 go run main.go

# 輸出如下
SCHED 0ms: gomaxprocs=idleprocs=threads=spinningthreads=idlethreads=runqueue=[1 0 0 0 0 0 0 0]

...

SCHED 0ms: gomaxprocs=idleprocs=threads=spinningthreads=idlethreads=runqueue=[0 0 0 0 0 0 0 0]
SCHED 0ms: gomaxprocs=idleprocs=threads=spinningthreads=idlethreads=runqueue=[9 0 0 0 0 0 0 0]
SCHED 1007ms: gomaxprocs=idleprocs=threads=13 spinningthreads=idlethreads=runqueue=[0 0 0 0 0 0 0 0]

輸出結果說明

mGZAz7

輸出 GC 時內存示例

執行命令

GODEBUG=gctrace=1 go run main.go

# 輸出如下
gc 1 @0.028s 1%: 0.058+1.1+0.19 ms clock, 0.46+0/1.0/0.36+1.5 ms cpu, 3->4->0 MB, 4 MB goal, 0 MB stacks, 0 MB globals, 8 P
gc 2 @0.034s 1%: 0.083+0.63+0.005 ms clock, 0.66+0.094/0.51/0.27+0.044 ms cpu, 3->3->0 MB, 4 MB goal, 0 MB stacks, 0 MB globals, 8 P
gc 3 @0.039s 1%: 0.031+0.66+0.042 ms clock, 0.25+0.091/0.49/0.39+0.34 ms cpu, 3->4->0 MB, 4 MB goal, 0 MB stacks, 0 MB globals, 8 P
gc 4 @0.043s 2%: 0.027+0.70+0.14 ms clock, 0.22+0.039/0.50/0.34+1.1 ms cpu, 3->3->0 MB, 4 MB goal, 0 MB stacks, 0 MB globals, 8 P

...

gc 1 @0.002s 4%: 0.012+0.78+0.005 ms clock, 0.098+0.49/0.58/0.32+0.040 ms cpu, 4->6->5 MB, 4 MB goal, 0 MB stacks, 0 MB globals, 8 P
gc 2 @0.015s 2%: 0.016+1.3+0.034 ms clock, 0.12+0.022/1.1/0.90+0.27 ms cpu, 9->9->7 MB, 10 MB goal, 0 MB stacks, 0 MB globals, 8 P

輸出結果說明

X8Wuo7 | 名稱 | 描述 |

下面以最後一行輸出爲例進行說明:

gc 2 @0.015s 2%: 0.016+1.3+0.034 ms clock, 0.12+0.022/1.1/0.90+0.27 ms cpu, 9->9->7 MB, 10 MB goal, 0 MB stacks, 0 MB globals, 8 P

YTNGiQ

輸出調度完整信息

執行命令

GODEBUG=scheddetail=1,schedtrace=1000 go run main.go

# 輸出如下
SCHED 0ms: gomaxprocs=idleprocs=threads=spinningthreads=idlethreads=runqueue=gcwaiting=nmidlelocked=stopwait=sysmonwait=0
  P0: status=schedtick=syscalltick=m=runqsize=gfreecnt=timerslen=0
  P1: status=schedtick=syscalltick=m=-1 runqsize=gfreecnt=timerslen=0
  
...

  P7: status=schedtick=syscalltick=m=-1 runqsize=gfreecnt=timerslen=0
  M5: p=curg=-1 mallocing=throwing=preemptoff= locks=dying=spinning=true blocked=false lockedg=-1
  
...

  M0: p=curg=mallocing=throwing=preemptoff= locks=dying=spinning=false blocked=false lockedg=1
  G1: status=2(chan receive) m=lockedm=0
  
...

  G4: status=4(GC scavenge wait) m=-1 lockedm=-1

...

SCHED 1008ms: gomaxprocs=idleprocs=threads=14 spinningthreads=idlethreads=runqueue=gcwaiting=nmidlelocked=stopwait=sysmonwait=0
  P0: status=schedtick=262 syscalltick=826 m=-1 runqsize=gfreecnt=timerslen=0

...

  P7: status=schedtick=17 syscalltick=307 m=-1 runqsize=gfreecnt=timerslen=0
  M13: p=-1 curg=-1 mallocing=throwing=preemptoff= locks=dying=spinning=false blocked=true lockedg=-1

...

  M0: p=-1 curg=-1 mallocing=throwing=preemptoff= locks=dying=spinning=false blocked=true lockedg=-1
  G1: status=4(semacquire) m=-1 lockedm=-1
  G17: status=6() m=lockedm=1
  G2: status=4(force gc (idle)) m=-1 lockedm=-1
  G3: status=4(GC sweep wait) m=-1 lockedm=-1
  G4: status=4(sleep) m=-1 lockedm=-1
  G5: status=4(finalizer wait) m=-1 lockedm=-1
  G12: status=6() m=-1 lockedm=-1
  G22: status=6() m=-1 lockedm=-1
  G10: status=4(GC worker (idle)) m=-1 lockedm=-1

...

  G78: status=4(select) m=-1 lockedm=10
  G146: status=4(chan receive) m=-1 lockedm=-1

輸出結果說明

P 的相關輸出說明,以下面這行輸出爲例:

P0: status=schedtick=syscalltick=m=runqsize=gfreecnt=timerslen=0

uyvB0a

P 的狀態列表

const (
 // 處理器沒有在執行代碼或者調度,位於空閒列表或者被可以改變其狀態的結構持有
 _Pidle = iota
 
 // 處理器被線程 M 持有,並且正在執行代碼或者調度
 _Prunning
 
 // 處理器沒有在執行代碼,線程陷入系統調用
 _Psyscall
 
 // 處理器被線程 M 持有,由於 GC 被停止
 _Pgcstop
 
 // 處理器不再被使用
 _Pdead
)

M 的相關輸出說明,以下面這行輸出爲例:

M0: p=curg=mallocing=throwing=preemptoff= locks=dying=spinning=false blocked=false lockedg=1

7gkM3N

G 的相關輸出說明,以下面這行輸出爲例:

G1: status=2(chan receive) m=lockedm=0

rMKz0F

G 的狀態列表

const (
 // goroutine 剛被分配並且還沒有被初始化
    _Gidle = iota // 0

 // goroutine 處於運行隊列中,沒有在執行代碼,沒有棧的所有權
 _Grunnable // 1

 // goroutine 可以執行代碼並且擁有有棧的所有權,M 和 P 已經設置並且有效
 _Grunning // 2

 // goroutine 正在執行系統調用,沒有在執行代碼,擁有棧的所有權但是不在運行隊列中,此外,M 已經設置
 _Gsyscall // 3

 // goroutine 處於阻塞中,沒有在執行代碼並且不在運行隊列中,但是可能存在於 Channel 的等待隊列上
 _Gwaiting // 4

 // 沒有使用這個狀態,但是被硬編碼到了 gbd 腳本中
 _Gmoribund_unused // 5

 // goroutine 沒有被使用 (可能已經退出或剛剛初始化),沒有在執行代碼,可能存在分配的棧
 _Gdead // 6

 // 沒有使用這個狀態
 _Genqueue_unused // 7

 // goroutine 的棧正在被移動,沒有在執行代碼並且不在運行隊列中
 _Gcopystack // 8

 // goroutine 由於搶佔而阻塞,等待喚醒
 _Gpreempted // 9

 // GC 正在掃描棧空間,沒有在執行代碼,可以與上述其他狀態同時存在
 _Gscan          = 0x1000
)

可視化

國外的大佬 Dave Cheney 開發了一個工具,可以實時可視化 GC trace 數據,項目地址 在這裏 [1]。

圖片來源: https://dave.cheney.net/2014/07/11/visualising-the-go-garbage-collector

Reference

參考資料

[1] 在這裏: https://github.com/davecheney/gcvis

[2] Go Hacking.md: hacking.md

[3] runtime: https://pkg.go.dev/runtime

[4] scheduler-trace: https://github.com/golang/go/wiki/Performance#scheduler-trace

[5] GODEBUG: https://ydkgo.netlify.app/docs/profiling/godebug/readme/

[6] Go Environment Variables: https://pkg.go.dev/runtime#hdr-Environment_Variables

[7] Scheduler Tracing In Go: https://www.ardanlabs.com/blog/2015/02/scheduler-tracing-in-go.html

本文由 Readfog 進行 AMP 轉碼,版權歸原作者所有。
來源https://mp.weixin.qq.com/s/AunOvSWc0g-y5DgkxwP2AQ