Rewind 新增 time 命令,用确定性 VM 分析程序关键路径
来源标题:Worshipping at the Altar of Brendan Gregg
Rewind 新增 rewind time 命令,可分析录制记录,定位时间消耗并指出如何让运行更快完成。作者用 Rewind 分析构建的关键路径,称缩短关键路径是让程序变快的唯一方式。该功能被视为向 Brendan Gregg 的性能分析工作致敬。
以下正文由 AI 翻译自 Hacker News 最新(原文版权归原站所有),可能存在偏差,重要内容请以原文为准。
得承认,我对 AI 有点上头。当你面对的是一个充满无限可能的问题时,很难把自己限制在有限的功能集里。
一个像 Rewind 这样的确定性 VM 能实现那么多有趣又实用的东西,这让我很惊讶。我一直在用它帮忙找 heisenbug、让 profile-guided optimization 可复现,以及让 Nix 构建做到 bit-reproducible。但最有意思的还是用它来理解性能。
事实证明,性能正是 Rewind 大放异彩的又一个领域。我一直在用它分析构建的关键路径。
关键路径是程序中依赖关系最长的一条链。无论你投入多少资源,这都是程序完成所需的最短时间。想让程序更快,唯一的办法就是缩短关键路径。
如果你在 Brendan Gregg 的祭坛前朝拜,就会知道他花了多年时间把性能分析从一门玄学变成了一门科学。这是献给他的一点小小心意。🤲
我给 Rewind 加了一个新的 rewind time 命令,它会分析一次录制,告诉你时间都花到哪去了,以及做什么能让这次运行更早结束。你可以深入查看答案的任何一个部分,看到对应的源代码行。这就像 Brendan Gregg 的火焰图,但针对关键路径做了强化,而且还挂着一个调试器。¹¹这个命令的所有想法要么受到 Brendan Gregg 工作的启发,要么直接受其影响。跪拜 Zod 吧!
旁注: 刚接触 Rewind?先从那个你只抓到过一次的 flaky build 开始,还有 dafuq 到底什么是确定性 VM?
让我们通过分析一次 libuv 构建与测试运行的关键路径,看看它是怎么工作的。这套构建和测试在 Rewind 里耗时 78 秒,即便用 64 核也仍然要 47 秒。为什么?
通常的答案是看 CPU profile,但在这种情况下,CPU profile 几乎毫无用处。在那 47 秒里,有三分之二的时间,构建所等待的工作根本不在计算:它在睡眠。💤💤💤
每次 rewind time 都以两个数字开头:
$ rewind time 7a29e716
libuv-1.51.0
78.0 s elapsed on the VM's one CPU 47.4 s critical path: the least it can take on any number of CPUs 67% asleep (epoll_pwait 23.1 s, clock_nanosleep 8.53 s, futex 100 ms), 33% computing
第一个数字是这次运行在 VM 的单个虚拟 CPU 上花了多长时间。第二个是关键路径:最长的一条工作链,其中每一步都必须等待前一步完成。
再多的 CPU 也无法让一次运行短于它的关键路径,所以这两个数字之间的差距就是并行能为你带来的全部收益。
两个数字下面那一行运用了 Gregg 的线程状态分析。这里最大的状态是 asleep:在 epoll_pwait 中 23 秒,在 clock_nanosleep 中 8.5 秒。
睡眠中的线程对 CPU profiler 来说是不可见的。Gregg 的答案是 off-CPU 分析:去看线程在哪里阻塞,而不仅仅是它们在哪里计算。
在真实机器上,off-CPU 分析很难做。Linux 可以追踪哪个线程唤醒了哪个线程,Gregg 在此基础上构建了 wakeup 和 off-wake profiling,但你必须在慢速运行发生之前就开始追踪,追踪本身有开销,而且你捕获到的大多数睡眠都是噪声。Rewind 本来就记录每一次上下文切换,因为重放需要它们,而现在它还记录了每一次唤醒以及是谁触发的。所有这些有价值的信息都在每一次录制里。🤤
$ rewind time 7a29e716
libuv-1.51.0
78.0 s elapsed on the VM's one CPU
47.4 s critical path: the least it can take on any number of CPUs
67% asleep (epoll_pwait 23.1 s, clock_nanosleep 8.53 s, futex 100 ms), 33% computing
The critical path by phase
3.54 s configurePhase ██
1.67 s buildPhase █
42.0 s checkPhase █████████████████████
99 ms 5 other phases
The critical path by process
on path pid process, with what it started
47.4 s 34 init › bash -e source-stdenv.sh default-builder.sh
41.9 s 4076 ├─ make -j8 SHELL=bash-5.3p3/bin/bash VERBOSE=y check
36.4 s 4910 │ ├─ make › bash › lt-run-tests
3.38 s 5412 │ │ ├─ lt-run-tests hrtime hrtime asleep in clock_nanosleep 3.38 s
2.00 s 5013 │ │ ├─ lt-run-tests delayed_accept delayed_accept asleep in epoll_pwait 2.00 s
1.62 s 5126 │ │ ├─ lt-run-tests fs_event_watch_dir fs_event_watch_dir asleep in epoll_pwait 1.62 s
1.60 s 5103 │ │ ├─ lt-run-tests fs_event_close_in_callback fs_event_close_in… asleep in epoll_pwait 1.60 s
1.60 s 5508 │ │ ├─ lt-run-tests metrics_idle_time metrics_idle_time asleep in epoll_pwait 1.00 s, computing 600 ms
1.24 s 6095 │ │ ├─ lt-run-tests tcp_write_ready tcp_write_ready
1.14 s 5510 │ │ ├─ lt-run-tests metrics_idle_time_thread metrics_idle_time_t… asleep in epoll_pwait 1.00 s
1.10 s 5132 │ │ ├─ lt-run-tests fs_event_watch_file_current_dir fs_event_wat… asleep in epoll_pwait 1.10 s
22.6 s │ │ └─ 279 more
5.59 s 4077 │ └─ make test/run-tests
2.22 s 4183 │ ├─ gcc -fPIC -fstack-clash-protection -O2 -U_FORTIFY_SOURCE …
2.10 s 4189 │ │ └─ cc1 /build/source/test/test-fs.c
3.35 s │ └─ 20 more
1.99 s 68 ├─ sh ./autogen.sh
1.99 s │ └─ 9 more
1.67 s 2642 ├─ make -j8 SHELL=bash-5.3p3/bin/bash
1.67 s │ └─ 5 more
1.53 s 403 └─ bash ./configure --disable-static --disable-dependency-tracking…
1.47 s └─ 581 more
What would shorten it
sooner pid if this took no time
36.1 s every lt-run-tests, 600 processes
6.66 s every cc1, 283 processes
3.38 s 5412 75 sleeps in clock_nanosleep: lt-run-tests hrtime hrtime
2.00 s 5013 2 sleeps in epoll_pwait: lt-run-tests delayed_accept delayed_accept
1.76 s 4189 cc1 /build/source/test/test-fs.c
1.62 s 5126 30 sleeps in epoll_pwait: lt-run-tests fs_event_watch_dir fs_event_watc…
1.60 s 5103 16 sleeps in epoll_pwait: lt-run-tests fs_event_close_in_callback fs_ev…
1.60 s 5508 lt-run-tests metrics_idle_time metrics_idle_time
1.22 s every perl, 9 processes
1.14 s 5510 lt-run-tests metrics_idle_time_thread metrics_idle_time_thread
Look closer
rewind time 7a29e716 --in PID one process: its threads, sleeps and waits
rewind time 7a29e716 --folded the path for flamegraph.pl or speedscope.app
(原文较长,此处译出前 6000 字,完整内容请点「打开原文」。)
正文由 探How 从来源站点 RSS 同步,内容未经改写;遇到排版缺失或需要图片、视频时请以原文为准。