Post #1005

我们考虑一个 c 程序，主线程 epoll_wait 一个空 epfd 超时设置 2ms，循环不干事；另一个线程 nanosleep 17ms 也循环不干事。代码长得像这样 // main thread for (;;) { epoll_wait(epfd, events, 1, 2); } // sub thread struct timespec interval = {0, 17 *1000 * 1000}; for (;;) { nanosleep(&interval, NULL); } 很显然我们应该预期这个进程 cpu 消耗接近 0，毕竟大部分时间都在睡觉，不过睡得好像有点过于频繁，主线程睡 2ms 醒一次，但问题不大，在我笔记本电脑上绑定单 cpu 运行，perf stat 显示只消耗 0.7% 的 cpu，符合预期。 $ perf stat -ddd -p $(pidof a.out) -- sleep 1 6.60 msec task-clock # 0.007 CPUs utilized 正片开始，我们用 go 按照正经生产环境最佳实践移植一版，非常简练。 ticker := time.NewTicker(17 * time.Millisecond) defer ticker.Stop() go func() { for range ticker.C {} }() epfd, _ := unix.EpollCreate1(unix.EPOLL_CLOEXEC) events := make([]unix.EpollEvent, 1) for { unix.EpollWait(epfd, events, 2) } 猜猜看，它跑起来消耗多少 cpu？ 2.7% 的 cpu！是 c 版本的四倍消耗！ 当然 2.7% 是很少的 cpu，但问题是这程序啥都没干啊，光睡觉睡掉了接近 3% 的 cpu，我看到监控的时候惊呆了，我精心射进的架构预期在大部分时间都是接近静默，零消耗，结果这起手就 3% 了，我还没开始正经干活呢。 执行一遍 perf record + perf report，发现 73.51% cpu 时间消耗在 x64_sys_call，锁定在 syscall 调用上，让我们来看每秒钟 syscall 调用统计。 c 版本 $ timeout 1 strace -c -fTttp $(pidof a.out) % time seconds usecs/call calls errors syscall ------ ----------- ----------- --------- --------- ---------------- 56.60 0.008679 152 57 clock_nanosleep 42.51 0.006518 13 476 epoll_wait 0.89 0.000137 137 1 restart_syscall ------ ----------- ----------- --------- --------- ---------------- 100.00 0.015334 28 534 total 大致估算一下 1s / 2ms = 500 次 epoll_wait，1s / 17 ms = 58 次 nanosleep，完全合理。 go 版本 % time seconds usecs/call calls errors syscall ------ ----------- ----------- --------- --------- ---------------- 45.19 0.041057 22 1849 54 futex 28.46 0.025861 228 113 epoll_pwait 20.93 0.019016 41 459 epoll_wait 5.33 0.004845 6 734 nanosleep 0.08 0.000073 5 13 sched_yield 0.00 0.000004 4 1 1 restart_syscall ------ ----------- ----------- --------- --------- ---------------- 100.00 0.090856 28 3169 55 total 太鬼畜了，futex 每秒钟调用近两千次，然后是 nanosleep 从预期的 58 次爆炸到 700+，太坏了。 用 strace -e futex,nanosleep -k -fTttp 检查一下是谁在调用这些 syscall [pid 50060] 00:13:03.796991 futex(0x52d220, FUTEX_WAKE_PRIVATE, 1) = 1 <0.000008> > (runtime.futex.abi0+0x23) [0x6c8a3] > (runtime.notewakeup+0x25) [0xe325] > (runtime.startm+0x209) [0x3bb29] > (runtime.handoffp+0x18d) [0x3bd8d] > (runtime.retake+0x255) [0x43b35] > (runtime.sysmon+0x345) [0x437c5] > (runtime.mstart1+0x93) [0x3a013] > (runtime.mstart0+0x75) [0x39f55] > (runtime.mstart.abi0+0x5) [0x68bc5] [pid 50060] 00:23:57.248078 nanosleep({tv_sec=0, tv_nsec=20000}, NULL) = 0 <0.000377> > (runtime.usleep.abi0+0x37) [0x6c2d7] > (runtime.sysmon+0xa5) [0x43525] > (runtime.mstart1+0x93) [0x3a013] > (runtime.mstart0+0x75) [0x39f55] > (runtime.mstart.abi0+0x5) [0x68bc5] 原来是（以下很可能有事实错误，请 go 语言专家斧正） go runtime 有个 sysmon 线程在监控和调度，但是在 sysmon 线程自身的睡觉节省 cpu 这件事情上 go runtime 试图做得聪明点，有个 adaptive 的 sleep time，如果发现经常被唤醒，就睡短一点，短到 20 us 也就是上面的 nanosleep ({0, 20000})；否则可以睡得长一点进入 deep sleep，不过 deep sleep 的时候如果被 syscall exit 打断，会通过 futex 进行通知。 所以我们的进程虽然只有一个 epoll_wait 的 2ms 一次唤醒 + timer 17ms 一次唤醒，但 runtime sysmon 自己在“睡得长一点还是短一点” 这事情上内耗，造成大量的 futex + nanosleep syscall，吃饱了 cpu。 这，就是 go runtime 的魅力 😀每天都在做奇怪的工程实在太好玩了 😀 😀