godebug

godebug。

package main

import (
    "log"
    "runtime"
    "time"
)

func test() {
    //slice 会动态扩容，用slice来做堆内存申请
    container := make([]int, 8)

    log.Println(" ===> loop begin.")
    for i := 0; i < 32*1000*1000; i++ {
        container = append(container, i)
    }
    log.Println(" ===> loop end.")
}

func main() {
    log.Println("Start.")

    test()

    log.Println("force gc.")
    runtime.GC() //强制调用gc回收

    log.Println("Done.")

    time.Sleep(3600 * time.Second) //睡眠，保持程序不退出
}

GODEBUG='gctrace=1' go run main.go

设置gctrace=1会使得垃圾回收器在每次回收时汇总所回收内存的大小以及耗时，并将这些内容汇总成单行内容打印到标准错误输出中。

格式：

gc # @#s #%: #+#+# ms clock, #+#/#/#+# ms cpu, #->#-># MB, # MB goal, # P

含义：

gc #        GC次数的编号，每次GC时递增
@#s         距离程序开始执行时的时间
#%          GC占用的执行时间百分比
#+...+#     GC使用的时间
#->#-># MB  GC开始，结束，以及当前活跃堆内存的大小，单位M
# MB goal   全局堆内存大小
# P         使用processor的数量

如果每条信息最后，以(forced)结尾，那么该信息是由runtime.GC()调用触发

我们来选择其中一行来解释一下：

gc 18 @0.414s 3%: 0.031+143+0.004 ms clock, 0.25+0/0.14/143+0.033 ms cpu, 582->582->197 MB, 583 MB goal, 8 P

该条信息含义如下：

gc 18: GC 调试的编号为18
@0.414s：此时程序已经运行了0.414秒
3%：0.414秒其中GC模块占用了3%的时间
0.031+143+0.004 ms clock：垃圾回收的时间，分别为STW清扫的时间+并发标记和扫描的时间+STW标记的时间
0.25+0/0.14/143+0.033 ms cpu：垃圾回收占用CPU时间
582->582->197 MB：GC开始前堆内存582M，GC结束后堆内存582M，当前活跃的堆内存197M
583 MB goal：全局堆内存大小
8 P：本次GC用了8个Processor

GODEBUG='gctrace=1' go run main.go 
gc 1 @0.015s 1%: 0.013+0.50+0.004 ms clock, 0.10+0.65/0.66/0.003+0.036 ms cpu, 4->4->0 MB, 5 MB goal, 8 P
gc 2 @0.033s 1%: 0.095+0.50+0.058 ms clock, 0.76+0.21/0.47/0.16+0.46 ms cpu, 4->4->0 MB, 5 MB goal, 8 P
gc 3 @0.096s 0%: 0.044+0.34+0.019 ms clock, 0.35+0.13/0.39/0.66+0.15 ms cpu, 4->4->0 MB, 5 MB goal, 8 P
gc 4 @0.125s 0%: 0.083+0.28+0.011 ms clock, 0.66+0.14/0.38/0.63+0.093 ms cpu, 4->4->0 MB, 5 MB goal, 8 P
gc 5 @0.152s 0%: 0.085+0.35+0.027 ms clock, 0.68+0.094/0.35/0.80+0.22 ms cpu, 4->4->0 MB, 5 MB goal, 8 P
gc 6 @0.204s 0%: 0.30+4.0+0.087 ms clock, 2.4+2.2/3.2/0+0.69 ms cpu, 4->4->1 MB, 5 MB goal, 8 P
gc 7 @0.228s 1%: 0.27+0.40+0.001 ms clock, 2.1+0/0.61/1.2+0.015 ms cpu, 4->4->0 MB, 5 MB goal, 8 P
gc 8 @0.242s 1%: 0.081+0.31+0.002 ms clock, 0.65+0.16/0.50/0.89+0.019 ms cpu, 4->4->0 MB, 5 MB goal, 8 P
gc 9 @0.255s 1%: 0.18+0.54+0.054 ms clock, 1.4+0.43/0.76/0.64+0.43 ms cpu, 4->4->1 MB, 5 MB goal, 8 P
gc 10 @0.264s 1%: 0.031+0.47+0.003 ms clock, 0.24+0.12/0.65/1.4+0.028 ms cpu, 4->4->1 MB, 5 MB goal, 8 P
# command-line-arguments
gc 1 @0.002s 10%: 0.023+3.2+0.004 ms clock, 0.18+1.0/4.1/2.1+0.035 ms cpu, 4->6->5 MB, 5 MB goal, 8 P
gc 2 @0.025s 3%: 0.008+1.7+0.013 ms clock, 0.065+0.14/2.3/0.56+0.10 ms cpu, 9->9->8 MB, 10 MB goal, 8 P
gc 3 @0.137s 1%: 0.21+1.3+0.023 ms clock, 1.6+0.75/2.2/0.76+0.18 ms cpu, 14->15->9 MB, 16 MB goal, 8 P
2021/04/01 21:46:56 Start.
2021/04/01 21:46:56  ===> loop begin.
gc 1 @0.002s 1%: 0.013+1.1+0.003 ms clock, 0.10+0/0.53/0.25+0.026 ms cpu, 4->5->1 MB, 5 MB goal, 8 P
gc 2 @0.004s 3%: 0.007+2.1+0.002 ms clock, 0.056+0/1.0/0.15+0.020 ms cpu, 4->6->3 MB, 5 MB goal, 8 P
gc 3 @0.007s 4%: 0.010+1.9+0.002 ms clock, 0.081+0/1.7/0.14+0.022 ms cpu, 8->8->2 MB, 9 MB goal, 8 P
gc 4 @0.009s 5%: 0.008+0.76+0.003 ms clock, 0.064+0/0.68/0.31+0.029 ms cpu, 6->6->3 MB, 7 MB goal, 8 P
gc 5 @0.010s 3%: 0.021+4.9+0.016 ms clock, 0.17+0/0.10/1.2+0.12 ms cpu, 8->13->10 MB, 9 MB goal, 8 P
gc 6 @0.015s 5%: 0.076+4.4+0.002 ms clock, 0.61+0/4.4/0.13+0.023 ms cpu, 17->17->7 MB, 20 MB goal, 8 P
gc 7 @0.020s 5%: 0.023+1.3+0.002 ms clock, 0.18+0/0.11/1.4+0.018 ms cpu, 15->15->8 MB, 16 MB goal, 8 P
gc 8 @0.022s 6%: 0.029+1.7+0.002 ms clock, 0.23+0.009/1.7/0.048+0.019 ms cpu, 19->19->10 MB, 20 MB goal, 8 P
gc 9 @0.024s 4%: 0.030+7.8+0.003 ms clock, 0.24+0/0.15/7.9+0.026 ms cpu, 24->24->13 MB, 25 MB goal, 8 P
gc 10 @0.032s 5%: 0.032+2.5+0.002 ms clock, 0.26+0.017/2.4/0.056+0.019 ms cpu, 30->30->17 MB, 31 MB goal, 8 P
gc 11 @0.035s 4%: 0.058+6.2+0.002 ms clock, 0.46+0/0.19/6.0+0.023 ms cpu, 38->38->21 MB, 39 MB goal, 8 P
gc 12 @0.043s 6%: 0.027+17+0.003 ms clock, 0.22+0/17/0.14+0.030 ms cpu, 47->47->26 MB, 48 MB goal, 8 P
gc 13 @0.061s 5%: 0.032+34+0.019 ms clock, 0.25+0/4.8/0.22+0.15 ms cpu, 59->101->74 MB, 60 MB goal, 8 P
gc 14 @0.097s 6%: 0.068+34+0.003 ms clock, 0.54+0/34/0.19+0.027 ms cpu, 126->126->51 MB, 149 MB goal, 8 P
gc 15 @0.133s 6%: 0.028+11+0.002 ms clock, 0.22+0/0.14/11+0.023 ms cpu, 116->116->64 MB, 117 MB goal, 8 P
gc 16 @0.146s 4%: 0.082+74+0.012 ms clock, 0.66+0/12/0.18+0.10 ms cpu, 145->246->182 MB, 146 MB goal, 8 P
gc 17 @0.224s 6%: 0.033+81+0.014 ms clock, 0.26+0/81/0.27+0.11 ms cpu, 308->308->227 MB, 364 MB goal, 8 P
gc 18 @0.414s 3%: 0.031+143+0.004 ms clock, 0.25+0/0.14/143+0.033 ms cpu, 582->582->197 MB, 583 MB goal, 8 P
2021/04/01 21:46:57  ===> loop end.
2021/04/01 21:46:57 force gc.
gc 19 @0.559s 3%: 0.056+43+0.003 ms clock, 0.45+0/0.14/43+0.028 ms cpu, 444->444->0 MB, 445 MB goal, 8 P (forced)
gc 20 @0.603s 3%: 0.045+0.13+0.001 ms clock, 0.36+0/0.192021/04/01 21:46:57 Done.
/0.065+0.014 ms cpu, 0->0->0 MB, 4 MB goal, 8 P (forced)
GC forced
gc 11 @120.572s 0%: 0.51+2.2+0.023 ms clock, 4.1+0/1.0/3.4+0.18 ms cpu, 3->3->0 MB, 4 MB goal, 8 P
GC forced
gc 21 @120.607s 0%: 0.066+0.16+0.004 ms clock, 0.53+0/0.23/0.18+0.036 ms cpu, 0->0->0 MB, 4 MB goal, 8 P
GC forced
gc 12 @240.708s 0%: 0.19+0.71+0.007 ms clock, 1.5+0/1.0/2.2+0.058 ms cpu, 0->0->0 MB, 4 MB goal, 8 P
GC forced
gc 22 @246.992s 0%: 0.035+0.17+0.004 ms clock, 0.28+0/0.20/0.13+0.033 ms cpu, 0->0->0 MB, 4 MB goal, 8 P

gc 19：这一行是在test()函数执行完后打印的，444->444->0 MB, 445 MB goal, 表示GC已经把444M的内存标记为非活跃的内存。
gc 20：0->0->0 MB, 4 MB goal表示垃圾回收器中的全局堆内存大小由 445M 下降为 4M。

在test()函数执行完后，程序中的切片容器所申请的堆空间都被垃圾回收器回收了。如果此时在top指令查询内存的时候，如果依然是445+MB，说明垃圾回收器回收了应用层的内存后，（可能）并不会立即将内存归还给系统。