目录
- 1.几种常见方法
- 1.1.设置环境变量 GODEBUG打印GC日志
- 1.2.使用 debug.ReadGCStats
- 1.3.使用 runtime.ReadMemStats
- 2.GC日志打印示例
- 3.参考
在Go语言中,可以通过设置环境变量和使用运行时包中的调试功能来打印垃圾回收(GC)的信息。
1.几种常见方法
1.1.设置环境变量 GODEBUG打印GC日志
通过设置 GODEBUG 环境变量来启用GC的详细日志。
具体来说,设置 GODEBUG=gctrace=1 可以打印GC的详细信息。
示例
在运行Go程序时,设置环境变量:
GODEBUG=gctrace=1 go run your_program.go
或者在代码中设置环境变量:
package mainimport ("os""runtime"
)func main() {// 设置环境变量os.Setenv("GODEBUG", "gctrace=1")// 触发GC以查看日志runtime.GC()// 你的程序逻辑
}
1.2.使用 debug.ReadGCStats
可以使用 runtime/debug 包中的 SetGCPercent 函数来调整GC的频率,并通过 PrintGCStats 函数打印GC的统计信息。
示例
package mainimport ("fmt""runtime/debug""time"
)func main() {// 设置GC的频率debug.SetGCPercent(100)// 启动一个goroutine定期打印GC统计信息go func() {var stats debug.GCStatsfor {time.Sleep(10 * time.Second)debug.ReadGCStats(&stats)fmt.Printf("GC Stats: %+v\n", stats)}}()// 模拟一些内存分配for i := 0; i < 10; i++ {_ = make([]byte, 10<<20) // 10 MBtime.Sleep(1 * time.Second)}
}
output:
GC Stats: {
LastGC:2024-08-24 11:41:57.930373 +0800 CST
NumGC:10
PauseTotal:657.732µs
Pause:[38.41µs 79.84µs 41.56µs 44.338µs 45.675µs 75.914µs 98.979µs 94.937µs 107.504µs 30.575µs] PauseEnd:[2024-08-24 11:41:57.930373 +0800 CST 2024-08-24 11:41:56.928724 +0800 CST 2024-08-24 11:41:55.926835 +0800 CST 2024-08-24 11:41:54.924951 +0800 CST 2024-08-24 11:41:53.922546 +0800 CST 2024-08-24 11:41:52.920353 +0800 CST 2024-08-24 11:41:51.917256 +0800 CST 2024-08-24 11:41:50.914207 +0800 CST 2024-08-24 11:41:49.912043 +0800 CST 2024-08-24 11:41:48.90515 +0800 CST]
PauseQuantiles:[]}
1.3.使用 runtime.ReadMemStats
可以使用 runtime 包中的 ReadMemStats 函数来获取GC的统计信息,并手动打印这些信息。
示例
package mainimport ("fmt""runtime""time"
)func main() {// 启动一个goroutine定期打印GC统计信息go func() {var m runtime.MemStatsfor {time.Sleep(10 * time.Second)runtime.ReadMemStats(&m)fmt.Printf("Alloc = %v MiB", m.Alloc/1024/1024)fmt.Printf("\tTotalAlloc = %v MiB", m.TotalAlloc/1024/1024)fmt.Printf("\tSys = %v MiB", m.Sys/1024/1024)fmt.Printf("\tNumGC = %v\n", m.NumGC)}}()// 模拟一些内存分配for i := 0; i < 10; i++ {_ = make([]byte, 10<<20) // 10 MBtime.Sleep(1 * time.Second)}
}
output:
Alloc = 0 MiB TotalAlloc = 100 MiB Sys = 20 MiB NumGC = 10
小结
- 设置环境变量 GODEBUG:通过设置 GODEBUG=gctrace=1 可以启用GC的详细日志。
- 使用 runtime/debug 包:可以使用 SetGCPercent 和 ReadGCStats 函数来调整GC频率和打印GC统计信息。
- 使用 runtime 包:可以使用 ReadMemStats 函数来获取和打印GC的统计信息。
通过这些方法,你可以方便地获取和打印GC的日志信息,以便进行性能调优和问题排查。
2.GC日志打印示例
以下是一个完整的示例,展示了如何在运行Go程序时通过设置环境变量来打印垃圾回收(GC)日志。这个示例程序还会模拟一些内存分配,以便触发垃圾回收。
示例代码
首先,创建一个Go程序文件,例如 main.go,并将以下代码粘贴到文件中:
package mainimport ("fmt""runtime""time"
)func main() {// 启动一个goroutine定期打印GC统计信息go func() {var m runtime.MemStatsfor {time.Sleep(10 * time.Second)runtime.ReadMemStats(&m)fmt.Printf("Alloc = %v MiB", m.Alloc/1024/1024)fmt.Printf("\tTotalAlloc = %v MiB", m.TotalAlloc/1024/1024)fmt.Printf("\tSys = %v MiB", m.Sys/1024/1024)fmt.Printf("\tNumGC = %v\n", m.NumGC)}}()// 模拟一些内存分配以触发GCfor i := 0; i < 10; i++ {_ = make([]byte, 10<<20) // 10 MBtime.Sleep(1 * time.Second)}
}
运行示例
在终端中运行以下命令来设置环境变量并运行Go程序:
GODEBUG=gctrace=1 go run main.go
解释
- 设置环境变量:通过在运行程序时设置 GODEBUG=gctrace=1 环境变量,启用GC的详细日志。
- 定期打印GC统计信息:程序启动一个goroutine,每10秒钟打印一次GC的统计信息,包括已分配的内存、总分配的内存、系统内存和GC的次数。
- 模拟内存分配:在主goroutine中,每秒钟分配10MB的内存,共分配10次,以触发垃圾回收。
GC日志示例
运行程序后,会在终端中看到类似以下的GC日志输出:
gc 1 @0.065s 0%: 0.010+2.7+0.003 ms clock, 0.10+0.16/2.9/2.1+0.034 ms cpu, 4->4->0 MB, 5 MB goal, 10 P
gc 2 @0.125s 0%: 0.027+0.47+0.003 ms clock, 0.27+0.097/1.0/0.43+0.033 ms cpu, 4->4->0 MB, 5 MB goal, 10 P
gc 3 @0.180s 0%: 0.031+1.0+0.10 ms clock, 0.31+0.75/0.80/1.0+1.0 ms cpu, 4->4->0 MB, 5 MB goal, 10 P
gc 4 @0.399s 1%: 0.76+2.6+4.3 ms clock, 7.6+2.0/1.8/0+43 ms cpu, 4->4->1 MB, 5 MB goal, 10 P
gc 5 @0.477s 1%: 0.25+2.6+0.004 ms clock, 2.5+0.38/1.0/2.0+0.042 ms cpu, 4->4->1 MB, 5 MB goal, 10 P
gc 6 @0.491s 1%: 0.092+9.8+0.003 ms clock, 0.92+0/10/1.9+0.033 ms cpu, 4->4->0 MB, 5 MB goal, 10 P
gc 7 @0.518s 1%: 0.093+0.62+0.004 ms clock, 0.93+0.19/1.0/0.23+0.049 ms cpu, 4->4->0 MB, 5 MB goal, 10 P
gc 8 @0.528s 1%: 0.043+0.98+0.004 ms clock, 0.43+0.13/0.95/0.62+0.047 ms cpu, 4->4->1 MB, 5 MB goal, 10 P
# command-line-arguments
gc 1 @0.018s 1%: 0.008+1.8+0.025 ms clock, 0.083+0.13/2.6/1.9+0.25 ms cpu, 4->4->2 MB, 5 MB goal, 10 P
gc 2 @0.033s 1%: 0.011+1.0+0.046 ms clock, 0.11+0.58/1.7/2.6+0.46 ms cpu, 5->5->4 MB, 6 MB goal, 10 P
# command-line-arguments
gc 1 @0.003s 8%: 0.028+4.2+0.059 ms clock, 0.28+0.16/5.9/2.8+0.59 ms cpu, 4->6->5 MB, 5 MB goal, 10 P
gc 2 @0.024s 4%: 0.007+3.0+0.069 ms clock, 0.076+0.042/3.1/1.9+0.69 ms cpu, 9->9->8 MB, 10 MB goal, 10 P
gc 3 @0.134s 1%: 0.019+1.7+0.065 ms clock, 0.19+0.98/2.3/2.0+0.65 ms cpu, 16->16->9 MB, 17 MB goal, 10 P
gc 9 @1.225s 0%: 0.26+1.0+0.19 ms clock, 2.6+0.40/1.2/1.0+1.9 ms cpu, 4->4->0 MB, 5 MB goal, 10 P
gc 1 @0.001s 6%: 0.036+1.3+0.064 ms clock, 0.36+0/0.77/1.1+0.64 ms cpu, 10->10->10 MB, 11 MB goal, 10 P
gc 2 @1.004s 0%: 0.072+1.2+0.023 ms clock, 0.72+0/1.3/0+0.23 ms cpu, 20->20->0 MB, 21 MB goal, 10 P
gc 3 @2.011s 0%: 0.036+0.12+0.003 ms clock, 0.36+0/0.19/0.031+0.035 ms cpu, 10->10->0 MB, 11 MB goal, 10 P
gc 4 @3.015s 0%: 0.11+0.78+0.010 ms clock, 1.1+0/1.0/0.007+0.10 ms cpu, 10->10->0 MB, 11 MB goal, 10 P
gc 5 @4.020s 0%: 0.13+1.1+0.031 ms clock, 1.3+0/0.38/0+0.31 ms cpu, 10->10->0 MB, 11 MB goal, 10 P
gc 6 @5.022s 0%: 0.10+0.54+0.007 ms clock, 1.0+0/0.65/0+0.079 ms cpu, 10->10->0 MB, 11 MB goal, 10 P
gc 7 @6.024s 0%: 0.13+0.65+0.008 ms clock, 1.3+0/0.75/0+0.081 ms cpu, 10->10->0 MB, 11 MB goal, 10 P
gc 8 @7.027s 0%: 0.094+0.73+0.008 ms clock, 0.94+0/0.83/0+0.082 ms cpu, 10->10->0 MB, 11 MB goal, 10 P
gc 9 @8.029s 0%: 0.14+0.68+0.008 ms clock, 1.4+0/0.84/0+0.081 ms cpu, 10->10->0 MB, 11 MB goal, 10 P
gc 10 @9.031s 0%: 0.076+0.43+0.008 ms clock, 0.76+0/0.59/0+0.084 ms cpu, 10->10->0 MB, 11 MB goal, 10 P
Alloc = 0 MiB TotalAlloc = 100 MiB Sys = 32 MiB NumGC = 10
这些GC日志是Go运行时在垃圾回收过程中生成的详细信息。每一行日志记录了一个GC周期的相关信息。
以下是对这些日志的详细解释:
每一行GC日志的格式如下:
gc N @T S%: M1+M2+M3 ms clock, C1+C2/C3/C4+C5 ms cpu, A->B->C MB, D MB goal, P P
字段解释
- gc N:表示这是第N次垃圾回收。
- @T:表示垃圾回收发生的时间点,单位是秒(s),从程序启动开始计算。
- S%:表示垃圾回收器在总CPU时间中所占的百分比。
- M1+M2+M3 ms clock:表示垃圾回收的三个阶段(标记、清理、其他)所花费的总时间,单位是毫秒(ms)。
- C1+C2/C3/C4+C5 ms cpu:表示垃圾回收的各个阶段在CPU上所花费的时间,单位是毫秒(ms)。
- C1:STW(Stop-The-World)标记开始时间。
- C2:并发标记时间。
- C3:并发清理时间。
- C4:并发清理结束时间。
- C5:STW标记结束时间。
- A->B->C MB:表示垃圾回收前、垃圾回收后和垃圾回收过程中分配的内存量,单位是MB。
- D MB goal:表示垃圾回收的目标内存量,单位是MB。
- P P:表示参与垃圾回收的处理器数量。
示例解释
以下是对示例日志的详细解释:
gc 1 @0.065s 0%: 0.010+2.7+0.003 ms clock, 0.10+0.16/2.9/2.1+0.034 ms cpu, 4->4->0 MB, 5 MB goal, 10 P
* gc 1:这是第1次垃圾回收。
* @0.065s:垃圾回收发生在程序启动后的0.065秒。
* **0%**:垃圾回收器在总CPU时间中所占的百分比为0%。
* 0.010+2.7+0.003 ms clock:垃圾回收的三个阶段(标记、清理、其他)所花费的总时间分别是0.010ms、2.7ms和0.003ms。
* 0.10+0.16/2.9/2.1+0.034 ms cpu:垃圾回收的各个阶段在CPU上所花费的时间分别是0.10ms、0.16ms、2.9ms、2.1ms和0.034ms。
* 4->4->0 MB:垃圾回收前、垃圾回收后和垃圾回收过程中分配的内存量分别是4MB、4MB和0MB。
* 5 MB goal:垃圾回收的目标内存量是5MB。
* 10 P:参与垃圾回收的处理器数量是10个。
3.参考
gc-guide
runtime