京公网安备11010502063487号CPU profile 看不到 goroutine 在等什么。执行追踪记录每个 goroutine 的阻塞、唤醒、调度,可以回答“它在哪里等了多久”。这篇不用网页界面,用命令行把 trace 导成 pprof 和事件文本,并用程序自己的计时校验 trace 给出的数字。
trace 文件 5592 字节
Type: delay
Showing nodes accounting for 537.23ms, 100% of 537.23ms total
flat flat% sum% cum cum%
314.33ms 58.51% 58.51% 314.33ms 58.51% sync.(*Mutex).Lock
122.83ms 22.86% 81.37% 122.83ms 22.86% sync.(*WaitGroup).Wait
100.08ms 18.63% 100% 100.08ms 18.63% runtime.chanrecv1
0 0% 100% 314.33ms 58.51% main.holdLock
0 0% 100% 122.83ms 22.86% main.main
0 0% 100% 314.33ms 58.51% main.main.func2
0 0% 100% 100.08ms 18.63% runtime.(*wakeableSleep).sleep
0 0% 100% 100.08ms 18.63% runtime.traceStartReadCPU.func1go tool trace -pprof=sync 把 goroutine 阻塞在同步原语上的时间按调用栈汇总。4 个 goroutine 争锁的例子里,Mutex.Lock 记了 314.33 ms、归到 main.holdLock;另外混进了运行时自己的 goroutine 的 100 ms(traceStartReadCPU),读这类结果要认得哪些是运行时内部的项。
程序自己量的:20 个 goroutine 从创建到第一次运行的等待之和 3559 ms;从创建到结束的总时间之和 5090 ms,减去它们各自的 20 ms 空转 = 4690 ms 的排队时间
trace 文件 5157 字节
Type: delay
Showing nodes accounting for 1531.07ms, 80.32% of 1906.32ms total
Dropped 7 nodes (cum <= 9.53ms)
Showing top 8 nodes out of 9
flat flat% sum% cum cum%
1155.78ms 60.63% 60.63% 1155.78ms 60.63% time.Now
375.28ms 19.69% 80.32% 375.28ms 19.69% runtime.wakeNetPoller
0 0% 80.32% 1155.79ms 60.63% main.main.func3
0 0% 80.32% 1155.78ms 60.63% main.spin
0 0% 80.32% 375.28ms 19.69% runtime.(*timer).maybeAdd
0 0% 80.32% 375.28ms 19.69% runtime.(*timer).modify
0 0% 80.32% 375.28ms 19.69% runtime.(*timer).reset
0 0% 80.32% 375.28ms 19.69% runtime.(*traceAdvancerState).start.func120 个 goroutine 在一个 P 上排队,程序自己量出来的排队时间是 4690 ms,而 -pprof=sched 的总量只有 1906 ms(另外几次是 804、1353 ms)。为什么偏小又不稳定,我没有查清。把它当作“哪个栈等得多”的相对排序用,不要当作精确的总时间。
go tool trace -d=parsed 总共 485 行事件;与标注相关的 9 行,前 8 行:
M=8304148352 P=8 G=1 TaskBegin Time=395507253352320 ID=1 Parent=18446744073709551615 Type="请求"
M=8304148352 P=8 G=1 RegionBegin Time=395507253353280 Task=1 Type="解析"
M=6094778368 P=8 G=1 RegionEnd Time=395507265370048 Task=1 Type="解析"
M=6094778368 P=8 G=1 RegionBegin Time=395507265371072 Task=1 Type="查询"
M=6094778368 P=9 G=1 RegionEnd Time=395507277410496 Task=1 Type="查询"
M=6094778368 P=9 G=1 RegionBegin Time=395507277411584 Task=1 Type="渲染"
M=8304148352 P=9 G=1 RegionEnd Time=395507289457280 Task=1 Type="渲染"
M=8304148352 P=9 G=1 Log Time=395507289460800 Task=1 Category="category" Message="done"
区域 解析:12.02 ms(代码里是 time.Sleep(10ms))
区域 查询:12.04 ms(代码里是 time.Sleep(10ms))
区域 渲染:12.05 ms(代码里是 time.Sleep(10ms))trace.NewTask / trace.WithRegion 把你关心的阶段写进 trace,go tool trace -d=parsed 里能直接读到 Begin/End 的纳秒时间戳。三个各睡 10 ms 的步骤读出来是 12.03、12.03、12.01 ms,和之前量到的 Sleep 多睡约 2 ms 一致。
plain :耗时 最小 0.040 s / 中位 0.041 s / 最大 0.042 s traced :耗时 最小 0.048 s / 中位 0.050 s / 最大 0.050 s;trace 文件 0.9–0.9 MB
一个 200 个 goroutine、每个分配 400 次的小程序,开 trace 后中位耗时从 0.041 s 到 0.050 s,约慢 22%,生成 0.9 MB,折合每秒约 18 MB。真实服务的开销取决于事件密度,我只测了这一个例子。
execution tracer. # Tracing runtime activities The execution trace captures a wide range of execution events such as goroutine creation/blocking/unblocking, syscall enter/exit/block, GC-related events, changes of heap size, processor start/stop, etc. When CPU profiling is active, the execution tracer makes an effort to include those samples as well. A precise nanosecond-precision timestamp and a stack trace is captured for most events. The generated trace can be interpreted using `go tool trace`. - net: network blocking profile - sync: synchronization blocking profile - syscall: syscall blocking profile - sched: scheduler latency profile
-pprof= 支持 net、sync、syscall、sched 四种。本文只实验了 sync 与 sched;net 与 syscall 没有试。网页界面(火焰图式的时间线)需要浏览器,这里没有使用。