京公网安备11010502063487号CPU profile 靠定时信号采样,只能告诉你 CPU 时间花在哪。这篇用已知占比的三个函数检验它的准确度,看多 goroutine 时样本总量怎么算,验证睡眠不算 CPU 时间,并量采样窗口多短会让结果不可信。
程序自己用 time.Now 量的真实占比:A 60.1% / B 30.0% / C 10.0%
Type: cpu
Duration: 5.20s, Total samples = 4770ms (91.82%)
Showing nodes accounting for 4770ms, 100% of 4770ms total
Showing top 6 nodes out of 7
flat flat% sum% cum cum%
2770ms 58.07% 58.07% 2840ms 59.54% main.workA
1430ms 29.98% 88.05% 1460ms 30.61% main.workB
470ms 9.85% 97.90% 470ms 9.85% main.workC
100ms 2.10% 100% 100ms 2.10% runtime.asyncPreempt
0 0% 100% 4770ms 100% main.cycle
0 0% 100% 4770ms 100% main.main三个函数的真实 CPU 占比是 60.1%、30.0%、10.0%(程序自己用 time.Now 量),5 秒的 profile 给出 58.07%、29.98%、9.85%,另有约 2% 落在 runtime.asyncPreempt(抢占信号打断时的栈)。Total samples 是墙钟时间的 91.82%,即约 91 个样本每秒,而不是 100。
Type: cpu
Duration: 2.20s, Total samples = 6090ms (276.62%)
Showing nodes accounting for 6070ms, 99.67% of 6090ms total
Dropped 12 nodes (cum <= 30.45ms)
flat flat% sum% cum cum%
3360ms 55.17% 55.17% 3660ms 60.10% main.workA
1630ms 26.77% 81.94% 1840ms 30.21% main.workB
550ms 9.03% 90.97% 570ms 9.36% main.workC
530ms 8.70% 99.67% 530ms 8.70% runtime.asyncPreempt
0 0% 99.67% 6080ms 99.84% main.cycle
0 0% 99.67% 6080ms 99.84% main.main.func1CPU profile 统计所有线程的 CPU 时间,所以 4 个 goroutine 并行 2.2 秒得到 276.62% 的 Total samples。我预期接近 400%,实际只有约 69%,原因没查(可能与 macOS 上信号计时的特性有关,没有验证)。
Type: cpu
Duration: 3.14s, Total samples = 1390ms (44.33%)
Showing nodes accounting for 1390ms, 100% of 1390ms total
Showing top 8 nodes out of 21
flat flat% sum% cum cum%
910ms 65.47% 65.47% 910ms 65.47% runtime.kevent
320ms 23.02% 88.49% 430ms 30.94% main.workA
110ms 7.91% 96.40% 110ms 7.91% runtime.asyncPreempt
50ms 3.60% 100% 50ms 3.60% runtime.pthread_cond_wait
0 0% 100% 430ms 30.94% main.main
0 0% 100% 910ms 65.47% runtime.(*timer).maybeAdd
0 0% 100% 910ms 65.47% runtime.(*timer).modify
0 0% 100% 910ms 65.47% runtime.(*timer).reset每轮 Sleep(4ms) 的程序,Total samples 只有墙钟的 44.33%:睡着的时间没有样本。但 time.Sleep 的调用路径里有 runtime.kevent,占了 65.47% 的 flat。所以在 macOS 上看到 kevent 很高,不一定是网络,可能只是定时器在重置。我没有深究这一段 CPU 时间为什么这么大。
窗口 100 ms:C 的估计占比 最小 0.0% / 中位 10.0% / 最大 10.0%(6 次) 窗口 300 ms:C 的估计占比 最小 6.7% / 中位 11.8% / 最大 13.8%(6 次) 窗口 1000 ms:C 的估计占比 最小 8.5% / 中位 10.3% / 最大 13.7%(6 次) 窗口 4000 ms:C 的估计占比 最小 9.5% / 中位 10.3% / 最大 11.2%(6 次)
真实占 10% 的函数,100 ms 的窗口(约 10 个样本)6 次估计在 0.0% 到 10.0%;300 ms 在 6.7% 到 13.8%;4 秒的窗口 6 次都在 9.5% 到 11.2%。所以对占比小的函数,太短的 profile 不能作为结论。
// The runtime routines allow a variable profiling rate, // but in practice operating systems cannot trigger signals // at more than about 500 Hz, and our processing of the // signal is not cheap (mostly getting the stack trace). // 100 Hz is a reasonable choice: it is frequent enough to // produce useful data, rare enough not to bog down the // system, and a nice round number to make it easy to // convert sample counts to seconds. Instead of requiring // each client to specify the frequency, we hard code it. const hz = 100
源码注释:系统最多约 500 Hz,取栈开销不小,100 Hz 足够有用又不拖垮系统,并且一个样本正好是 10 ms,换算方便。这是硬编码的,不是配置项。