Golang环境变量之GODEBUG

GODEBUG 是 golang 中一个控制runtime调度变量的变量,其值为一个用逗号隔开的 name=val对列表,常见有以下几个命名变量。

allocfreetrace

设置allocfreetrace = 1会导致对每个分配进行概要分析,并在每个对象的分配上打印堆栈跟踪并释放它们。

clobberfree

设置 clobberfree=1会使垃圾回收器在释放对象的时候,对象里的内存内容可能是错误的。

cgocheck

cgo相关。

设置 cgocheck=0 将禁用当包使用cgo非法传递给go指针到非go代码的检查。如果值为1(默认值)会启用检测,但可能会丢失有一些错误。如果设置为2的话,则不会丢失错误。但会使程序变慢。

efence

设置 efence=1会使回收器运行在一个模式。每个对象都在一个唯一的页和地址,且永远也不会被回收。

gccheckmark

GC相关。

设置 gccheckmark=1 启用验证垃圾回收器的并发标记,通过在STW时第二个标记阶段来实现,如果在第二阶段的时候,找到一个可达对象,但未找到并发标记,则GC会发生Panic。

gcpacertrace

GC相关。

设置 gcpacertrace=1可使gc打印关于并发 pacer 内部状态的信息

gcshrinkstackoff

GC相关。

设置 gcshrinkstackoff=1可禁止goroutine移动到小stack。这种模式下,goroutine stack只能增长。简单来说就是一个关闭收缩的开关。

gcstoptheworld

GC 相关。

设置 gcstoptheworld=1可禁止并发垃圾回收,使每个gc就是一个事件。设置 gcstoptheworld=2 会在垃圾回收后进行并发扫描。

gctrace

GC 相关。

设置 gctrade=1 会使垃圾回收器在每次GC打印单行标准错误,汇总收集的内存量和暂停的时间。格式可能会更换。

如果输出行以(forced)结尾,则说明此GC是通过调用 runtime.GC 来触发的。这个调试变量非常常见。如 GODEBUG=gotrace=1 go run main.go

输出字段意义:
gc # @#s #%: #+#+# ms clock, #+#/#/#+# ms cpu, #->#-># MB, # MB goal, # P
where the fields are as follows:
gc # the GC number, incremented at each GC
@#s time in seconds since program start
#% percentage of time spent in GC since program start
#+...+# wall-clock/CPU times for the phases of the GC
#->#-># MB heap size at GC start, at GC end, and live heap
# MB goal goal heap size
# P number of processors used
The phases are stop-the-world (STW) sweep termination, concurrent
mark and scan, and STW mark termination. The CPU times
for mark/scan are broken down in to assist time (GC performed in
line with allocation), background GC time, and idle GC time.
If the line ends with "(forced)", this GC was forced by a
runtime.GC() call.

➜  gotest GODEBUG=gctrace=1 go run main.go
gc 1 @0.115s 0%: 0.067+0.92+0.003 ms clock, 0.26+0.41/0.78/0.011+0.015 ms cpu, 4->4->0 MB, 5 MB goal, 4 P
gc 2 @0.194s 0%: 0.056+1.5+0.003 ms clock, 0.22+1.3/0.27/1.6+0.012 ms cpu, 4->4->0 MB, 5 MB goal, 4 P
gc 3 @0.303s 0%: 0.24+1.5+0.004 ms clock, 0.98+0.20/0.32/1.5+0.016 ms cpu, 4->4->0 MB, 5 MB goal, 4 P
gc 4 @0.344s 0%: 0.12+0.45+0.003 ms clock, 0.51+0/0.41/0.81+0.012 ms cpu, 4->4->0 MB, 5 MB goal, 4 P

字段解释

垃圾回收信息

gc 1 @0.115s 0%: 0.018+1.3+0.076 ms clock, 0.054+0.35/1.0/3.0+0.23 ms cpu, 4->4->3 MB, 5 MB goal, 4 P`。

1 :表示第一次执行
@0.115s :表示当前程序执行的总时间,从程序开始时计时。
0% :垃圾回收时间占用的百分比
0.067+0.92+0.003 ms clock :垃圾回收的时间,分别为STW(stop-the-world)清扫时间, 并发标记和扫描的时间,STW标记的时间
0.26+0.41/0.78/0.011+0.015 ms cpu :垃圾回收占用cpu时间
4->4->0 MB :堆的大小,三个数字分别表示GC开始前堆的大小,GC后堆的大小 和 当前存活堆的大小
5 MB goal :整体堆的大小
4 P :使用的处理器数量

在gc后的内存回收到系统时,会有一些概要信息,如
scvg0: inuse: 426, idle: 0, sys: 427, released: 0, consumed: 427 (MB)

426 :使用多少M内存
0 :剩下要清除的内存
427 :系统映射的内存
0 :释放的系统内存
427 :申请的系统内存

madvdontneed

设置 madvdontneed=1 将会在Linux上当内存返回内核时使用 MADV_DONTNEED 代替 MADV_FREE

memprofilerate

设置memprofilerate=X 将会更新 runtime.MemProfileRate 的值。如果设置为 0 将禁用内存性能分析。有关默认值,请参考 MemProfileRate 的描述。

invalidptr

// TODO

sbrk

设置sbrk=1会使用一个碎片回收器代替内存分配器和垃圾回收器。它从操作系统获取内存,并且永远也不会回收任何内存。

scavenge

设置 scavenge=1 将启用heap scavenger的调试模式。

scavtrace

//TODO

scheddetail

调度相关。

设置为schedtrace=Xscheddetail=1 会使调度器每 X 毫秒打印详细的多行信息,调度器的描述状态,处理器、线程和goroutines。

package main

import "sync"

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()
}

输出结果

➜  gotest GODEBUG=schedtrace=1000,scheddetail=1000 go run main.go
SCHED 0ms: gomaxprocs=4 idleprocs=2 threads=6 spinningthreads=1 idlethreads=2 runqueue=0 gcwaiting=0 nmidlelocked=0 stopwait=0 sysmonwait=0
  P0: status=1 schedtick=1 syscalltick=0 m=0 runqsize=0 gfreecnt=0 timerslen=0
  P1: status=0 schedtick=2 syscalltick=0 m=-1 runqsize=0 gfreecnt=0 timerslen=0
  P2: status=1 schedtick=0 syscalltick=0 m=5 runqsize=0 gfreecnt=0 timerslen=0
  P3: status=0 schedtick=0 syscalltick=0 m=-1 runqsize=0 gfreecnt=0 timerslen=0
  M5: p=2 curg=-1 mallocing=0 throwing=0 preemptoff= locks=1 dying=0 spinning=true blocked=false lockedg=-1
  M4: p=-1 curg=-1 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=true lockedg=-1
  M3: p=-1 curg=-1 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=true lockedg=-1
  M2: p=-1 curg=-1 mallocing=0 throwing=0 preemptoff= locks=2 dying=0 spinning=false blocked=false lockedg=-1
  M1: p=-1 curg=17 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=false lockedg=17
  M0: p=0 curg=1 mallocing=0 throwing=0 preemptoff= locks=3 dying=0 spinning=false blocked=false lockedg=1
  G1: status=2(chan receive) m=0 lockedm=0
  G17: status=6() m=1 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(GC scavenge wait) m=-1 lockedm=-1
SCHED 0ms: gomaxprocs=4 idleprocs=1 threads=5 spinningthreads=1 idlethreads=0 runqueue=0 gcwaiting=0 nmidlelocked=0 stopwait=0 sysmonwait=0
  P0: status=1 schedtick=0 syscalltick=0 m=4 runqsize=1 gfreecnt=0 timerslen=0
  P1: status=1 schedtick=0 syscalltick=0 m=2 runqsize=0 gfreecnt=0 timerslen=0
  P2: status=0 schedtick=0 syscalltick=0 m=-1 runqsize=0 gfreecnt=0 timerslen=0
  P3: status=0 schedtick=0 syscalltick=0 m=-1 runqsize=0 gfreecnt=0 timerslen=0
  M4: p=0 curg=-1 mallocing=0 throwing=0 preemptoff= locks=1 dying=0 spinning=false blocked=false lockedg=-1

输出的内容比较的多,每行的信息属于谁只要看首列字母即可,如果是G开头的话,则是表示的是 GoRoutine, G0、G1、GN后面的数字表示是G的编号,是唯一的。如果是P的话,则就是处理器相关的信息,当然M就是线程了,每种资源都有多个,他们之间状态是来回变化的,由于阻塞或调度的原因。SCHED 则表示当前的调度信息。

建议看一下每行相关的字段意义,这样有助于理解 runtime。如 P 行输出行里的字段 statusschedticksyscalltickmrunqsize 全是 P 结构体的字段。

P相关字段

  • status 当前P的状态,参考这里
  • schedtick 调度次数
  • syscalltick P系统调用次数
  • m 当前P绑定的M
  • runqsize P本地的运行队列,存放的全是待执行的Goroutine
  • gfreecnt 可用的G(状态Gdead)

M相关字段

  • p 当前m绑定的P
  • curg 当前绑定的G
  • mallocing 分配内存状态
  • throwing 是否抛出异常
  • preemptoff 如果非空,则保持curg 运行在当前m。
  • locks
  • dying 死亡?
  • spinning 是否自旋
  • blocked 当前阻塞
  • lockedg 当前锁定的g

G相关字段

  • status 当前G 的状态,参考这里
  • m 当前G分配到的M, -1表示未分配
  • lockedm 当前G锁定的m

schedtrace

调度相关。

设置 schedtrade=X 会使调度器每X毫秒打印一行标准错误,汇总调度器的状态。

package main

import "sync"

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()
}

输出结果

➜  gotest GODEBUG=schedtrace=1000 go run main.go
SCHED 0ms: gomaxprocs=4 idleprocs=2 threads=4 spinningthreads=1 idlethreads=0 runqueue=0 [1 0 0 0]
SCHED 1ms: gomaxprocs=4 idleprocs=2 threads=7 spinningthreads=1 idlethreads=2 runqueue=0 [0 0 0 0]
SCHED 3ms: gomaxprocs=4 idleprocs=2 threads=7 spinningthreads=1 idlethreads=2 runqueue=0 [0 0 0 0]
SCHED 10ms: gomaxprocs=4 idleprocs=1 threads=7 spinningthreads=1 idlethreads=1 runqueue=0 [7 7 0 0]
SCHED 15ms: gomaxprocs=4 idleprocs=0 threads=7 spinningthreads=1 idlethreads=0 runqueue=0 [3 1 3 0]
SCHED 18ms: gomaxprocs=4 idleprocs=0 threads=7 spinningthreads=0 idlethreads=0 runqueue=0 [1 1 3 1]
SCHED 22ms: gomaxprocs=4 idleprocs=0 threads=8 spinningthreads=0 idlethreads=0 runqueue=1 [1 1 3 1]
SCHED 24ms: gomaxprocs=4 idleprocs=0 threads=8 spinningthreads=0 idlethreads=1 runqueue=0 [0 0 0 0]
SCHED 25ms: gomaxprocs=4 idleprocs=0 threads=8 spinningthreads=0 idlethreads=1 runqueue=0 [0 0 0 0]
SCHED 29ms: gomaxprocs=4 idleprocs=0 threads=8 spinningthreads=1 idlethreads=0 runqueue=0 [0 6 0 0]
SCHED 30ms: gomaxprocs=4 idleprocs=1 threads=8 spinningthreads=1 idlethreads=1 runqueue=0 [0 0 0 0]
......

我们这时设置的是 schedtrace=1000,即1秒输出一次,

  • SCHED:每一行都表示一次调度器的调试信息,后面提示的毫秒数表示启动到现在的运行时间,输出的时间间隔受 schedtrace 的值影响。
  • gomaxprocs:当前的 CPU 核心数(GOMAXPROCS 的当前值)。
  • idleprocs:空闲的处理器数量,后面的数字表示当前的空闲数量。
  • threads:OS 线程数量,后面的数字表示当前正在运行的线程数量。
  • spinningthreads:自旋状态的 OS 线程数量。
  • idlethreads:空闲的线程数量。
  • runqueue:全局队列中 Goroutine 数量,而后面的 [3 1 3 0] 则分别代表这 4 个 P 的本地队列正在运行的 Goroutine 数量。

如果想打印更详情的信息,可能可以与 scheddetail 一起使用,如GODEBUG=schedtrace=1000,scheddetail=1 go run main.go ,会打印出每个G/P/M之间的切换状态详情。

推荐使用pprof查看,目前这种方式不是太友好。

tracebackancestors

//TODO

asyncpreemptoff

异步抢占

以上几个调试变量,经常使用的有gotraceschedtracescheddetail,其中gotrace主要是观察gc的情况,schedtrace 和 scheddetail 主要是观察调度的情况。

另外netnet/httpcrypto/tls 包也引用了GODEUBG中的调度变量,具体参考包的文档。

原文:https://blog.haohtml.com/archives/21778

参考

©著作权归作者所有,转载或内容合作请联系作者
  • 序言:七十年代末,一起剥皮案震惊了整个滨河市,随后出现的几起案子,更是在滨河造成了极大的恐慌,老刑警刘岩,带你破解...
    沈念sama阅读 203,324评论 5 476
  • 序言:滨河连续发生了三起死亡事件,死亡现场离奇诡异,居然都是意外死亡,警方通过查阅死者的电脑和手机,发现死者居然都...
    沈念sama阅读 85,303评论 2 381
  • 文/潘晓璐 我一进店门,熙熙楼的掌柜王于贵愁眉苦脸地迎上来,“玉大人,你说我怎么就摊上这事。” “怎么了?”我有些...
    开封第一讲书人阅读 150,192评论 0 337
  • 文/不坏的土叔 我叫张陵,是天一观的道长。 经常有香客问我,道长,这世上最难降的妖魔是什么? 我笑而不...
    开封第一讲书人阅读 54,555评论 1 273
  • 正文 为了忘掉前任,我火速办了婚礼,结果婚礼上,老公的妹妹穿的比我还像新娘。我一直安慰自己,他们只是感情好,可当我...
    茶点故事阅读 63,569评论 5 365
  • 文/花漫 我一把揭开白布。 她就那样静静地躺着,像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上,一...
    开封第一讲书人阅读 48,566评论 1 281
  • 那天,我揣着相机与录音,去河边找鬼。 笑死,一个胖子当着我的面吹牛,可吹牛的内容都是我干的。 我是一名探鬼主播,决...
    沈念sama阅读 37,927评论 3 395
  • 文/苍兰香墨 我猛地睁开眼,长吁一口气:“原来是场噩梦啊……” “哼!你这毒妇竟也来了?” 一声冷哼从身侧响起,我...
    开封第一讲书人阅读 36,583评论 0 257
  • 序言:老挝万荣一对情侣失踪,失踪者是张志新(化名)和其女友刘颖,没想到半个月后,有当地人在树林里发现了一具尸体,经...
    沈念sama阅读 40,827评论 1 297
  • 正文 独居荒郊野岭守林人离奇死亡,尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 35,590评论 2 320
  • 正文 我和宋清朗相恋三年,在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 37,669评论 1 329
  • 序言:一个原本活蹦乱跳的男人离奇死亡,死状恐怖,灵堂内的尸体忽然破棺而出,到底是诈尸还是另有隐情,我是刑警宁泽,带...
    沈念sama阅读 33,365评论 4 318
  • 正文 年R本政府宣布,位于F岛的核电站,受9级特大地震影响,放射性物质发生泄漏。R本人自食恶果不足惜,却给世界环境...
    茶点故事阅读 38,941评论 3 307
  • 文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹,春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 29,928评论 0 19
  • 文/苍兰香墨 我抬头看了看天上的太阳。三九已至,却和暖如春,着一层夹袄步出监牢的瞬间,已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 31,159评论 1 259
  • 我被黑心中介骗来泰国打工, 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留,地道东北人。 一个月前我还...
    沈念sama阅读 42,880评论 2 349
  • 正文 我出身青楼,却偏偏与公主长得像,于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子,可洞房花烛夜当晚...
    茶点故事阅读 42,399评论 2 342

推荐阅读更多精彩内容