查一次系统版本要 14 秒:测试慢在 94 万个 .o 文件上

发 Orca v0.5.14 之前,我在自己的 Mac 上跑了一遍完整的测试。这一步不能省:CI 里没有 macOS 的机器,Seatbelt 沙箱、computer use 驱动这些只在 macOS 上生效的代码,只有本地这一遍能测到。

这一遍跑了很久。nextest 用的是和 CI 一样的配置,两个线程,4632 个测试跑了 4676 秒,将近 78 分钟。看单个测试的耗时更奇怪:前 2170 个测试里,有 1059 个超过 5 秒。最扎眼的是 orca-runtime 里 computer_use 相关的测试,每个 15 到 26 秒,可它们用的是假驱动,按说一眨眼就该跑完。

前两次判断

这不是第一次碰到「macOS 上测试莫名其妙慢」。

10 月 20 日,runtime_host 的一批测试只在重新编译之后的第一次运行时失败,它们在非 Windows 平台上的超时只有 3 秒;TUI 的一个测试也在 2 秒的交接上超时。我当时 sample 了一个卡住的测试,看到它停在 NSProcessInfo.operatingSystemVersion 里,Foundation 正在枚举 bundle 目录。再跑一次,测试又过了。我的结论是「冷启动时 Foundation 的第一次调用慢」,然后让非交互会话不再去探测宿主环境(920c6231)。workspace 的失败从 26 个降到 1 个,TUI 的测试也从 274 秒降到 110 秒。症状确实轻了,我就没有再往下查。

10 月 25 日,完整验证又跑得出奇地慢。这次我在进程列表里找到了三个泄漏的测试进程,是 subagent worker 测试留下的忙循环,最早的一个从 10 月 19 日就开始空转,三个加起来占着 3 个核。我把它们结束掉,这确实是个问题,可测试照样慢。

三次判断:10 月 20 日 runtime_host 的测试只在重新编译后的第一次运行失败,sample 看到 Foundation 在枚举 bundle 目录,判断是冷启动时第一次调用慢,让非交互会话不再探测宿主,失败从 26 个降到 1 个;10 月 25 日完整验证跑得出奇地慢,找到三个泄漏的测试进程占着 3 个核,结束它们之后测试照样慢;10 月 26 日 computer_use 的每个测试 15 到 26 秒,再 sample 一次,229 个样本里 226 个在 readdir,这次去数了那个目录,根因是 target/debug/deps 里的 94.7 万个文件

两次判断都对上了症状,也都做了有用的事,只是都没碰到原因。

这次看完整条栈

10 月 26 日,我挑了一个正在跑的 computer_use 测试,它已经跑了 16 秒,用 sample 采了 3 秒。测试线程的 229 个样本里,228 个在 ComputerUseService::new 调用的 host_supported() 里,其中 226 个停在同一个地方:

一次 sample 看到的调用链:orca_computer_use::apps::host_supported 调用 NSProcessInfo.operatingSystemVersion,经过 _CFCopySystemVersionDictionary、_CFCopyLocalizedVersionKey、CFBundleCopyResourceURL 和 _CFBundleCopyBundleLocalizations,到 _CFBundleCopyLProjDirectoriesForURL 找 .lproj 目录,最后在 readdir 里读 target/debug/deps 的 946,766 个条目;测试二进制是裸的可执行文件,CFBundle 把它所在的目录当成主 bundle;nextest 每个测试一个新进程,每个进程第一次查版本都要把这个目录读一遍

从栈上看,事情是这样的:operatingSystemVersion 要读系统版本的字典,字典里有一项需要本地化;要本地化,CoreFoundation 得先知道主 bundle 支持哪些语言,办法是去主 bundle 里找 .lproj 目录。测试二进制是一个裸的可执行文件,没有 .app 包,CFBundle 就把它所在的目录当作主 bundle,于是去列这个目录。

这个目录是 target/debug/deps,里面有 946,766 个条目。

10 月 20 日那次,我在栈上其实已经看到了「枚举 bundle 目录」,差的只是追问一句:枚举的是哪个目录,里面有多少东西。

只换一个目录

要确认是目录本身的问题,最直接的办法是让同一个程序在不同的目录里跑。我写了一个只做一件事的小程序:

import Foundation
let start = Date()
let v = ProcessInfo.processInfo.operatingSystemVersion
let ms = Date().timeIntervalSince(start) * 1000
print(String(format: "%d.%d.%d %.1f ms", v.majorVersion, v.minorVersion, v.patchVersion, ms))

用 swiftc -O 编出来,复制到几个目录里,每个跑三次。第一次是冷的,取后两次:

同一个程序只换它所在的目录:空目录 2 毫秒,1 万个空文件 13 毫秒,10 万个 100 毫秒,30 万个 290 毫秒,30 万个文件名约 80 字符的文件 580 毫秒,target/debug/deps 的 94.7 万个条目 13,600 毫秒;按 30 万个长名字的结果线性推算,94.7 万个大约 1.8 秒,真实目录要 13.6 秒,剩下的差距没有再追

空目录里 2 毫秒,复制到 target/debug/deps 里 13.6 秒。程序一个字没改。

文件越多越慢,名字越长越慢,大致是线性的。但这只解释了一部分:按 30 万个长名字文件的 580 毫秒推算,94.7 万个大约 1.8 秒,真实的目录要 13.6 秒。剩下的差距我没有再追下去。我猜和这个目录长期反复增删文件有关,没有验证。

94 万个 .o 是哪来的

target/debug/deps 里,940,396 个是 .o,其余是 2,881 个 .d、2,097 个 .rmeta、609 个 .rlib,文件名平均 72 个字符,长这样:live_macos-205419018d0c70e4.72w1v34xz75z5nzmvjs696klh.1t5so90.rcgu.o。

这些是 codegen unit 的目标文件。macOS 上,cargo 的 dev 构建默认给 rustc 传 -C split-debuginfo=unpacked:调试信息不打包进 .dSYM,留在各个 .o 里,调试器要用时去读,所以链接完 .o 不删。我新建了一个空项目确认过,一个 hello world 编完,deps 里就留下 6 个 .rcgu.o。

Orca 的 workspace 有一百来个测试目标,每改一次代码,重编的测试二进制就留下一批新的 .o,旧的那批不会被清掉。几个月下来,就攒到了 94 万个。

至于为什么只有测试慢:nextest 给每个测试起一个新进程,每个走到 host_supported() 的进程,第一次查版本时都要把这个目录读一遍。cargo test 一个测试二进制只起一个进程,只付一次。装到用户机器上的 orca 二进制所在的目录里只有寥寥几个文件,也不受影响。

能做的

我列了三条,到写这篇的时候都还没做:

  • 清掉 target。 cargo clean 之后从零开始,代价是下一次全量重编。之后它还会慢慢涨回去,得定期清。
  • 换掉 dev 构建的 split-debuginfo。 改成 packed,链接时会用 dsymutil 把调试信息打进 .dSYM,代价是链接变慢。这要在 workspace 里统一配置,影响每个人的构建,我还没想好。
  • 查版本不经过 CFBundle。 sysctl -n kern.osproductversion 直接返回 26.6.2,不碰本地化,也就不去列目录。这是代码层面最彻底的改法,测试和正式环境都不用再付这笔开销。

920c6231 让非交互会话不再探测宿主,那个改动本身是对的,它恰好把大部分测试从这条路上挪开了,所以 10 月 20 日之后症状轻了很多。剩下还走这条路的,主要是 computer use 自己的测试,这次每个 15 到 26 秒的就是它们。

参与讨论