多个工作区同时跑测试,测试库被互相删掉的排查记录
2739 字约 10 分钟
摘要论坛项目的测试连真实的 PostgreSQL,同时开着好几个工作区跑测试时总会随机失败。一是测试库按同一个前缀命名,启动时会把别人正在用的也强制删掉,二是连接数不够,三是 WSL 的系统时钟每半分钟就往回跳一次。
我的论坛项目有一套连真实 PostgreSQL 的测试,不 mock 数据库。写这个项目时我习惯同时开着好几个 AI 助手会话,各自在独立的 git worktree 里做事,每个 worktree 有自己的数据库和端口,改完都要跑一遍 pnpm check。
最近几天,测试开始随机失败。重跑一遍又全过了,所以我一直把它当成偶发问题。直到有一天,我决定认真看看它到底是什么原因。
先当成偶发问题
最早的一次失败发生在测试的准备阶段,PostgreSQL 的 dropdb 报了错,测试本身都没跑。助手单独重跑测试全部通过,再完整跑一遍也过了,于是得出一个当时觉得合理的判断,测试库当时被别的连接占着,偶发的。
后来又遇到过几种症状,有一次是一个准备步骤超时 10 秒,还有几次是接口意外返回了 500,状态码对不上。每次重跑都能通过,每次都被归为“偶发”。
管道会吞掉失败的退出码这一段里还有一个我自己没发现的坑。助手有几次用
pnpm check 2>&1 | grep ... | head -3 && git commit这样的命令,边跑检查边提交。管道的退出码是最后一个命令的,head总是成功,所以检查失败了,提交照样发生。有一个 PR 就是在本地测试其实失败的情况下发出去的,只是 CI 刚好是绿的。之后它改成先把输出重定向到文件,再单独看退出码,这样失败不会被吞掉。
两个同时在跑的测试
测试库的设计是这样的。开始时,全局准备会迁移一个模板库,叫 mousehole_test。每个测试文件开始前,从这个模板复制出一个属于自己的库,所以测试文件之间可以并行。结束的时候,把所有这些库删掉。
问题出在“删掉所有这些库”的写法。它用名字前缀去匹配,再逐个强制删除。
SELECT datname FROM pg_database WHERE datname LIKE 'mousehole_test%';
DROP DATABASE "<上面查到的每一个>" WITH (FORCE);这在只有一个人跑测试时没有问题。但这个前缀对所有 worktree 都一样,只要有两次测试同时在跑,后启动的那次一开始就会把先启动的那次的模板库和所有副本库一并强制删除,正在跑的测试突然发现自己连接的库没了。先结束的那次收尾时又会再删一次。
WITH (FORCE) 是什么意思正常情况下,PostgreSQL 不允许删除一个还有连接的数据库,会报错说它正被别人使用。加上
WITH (FORCE)之后,数据库会先断开所有连接,再删除。它让测试收尾更干净,也让它能删掉别人正在用的库。
通俗比喻:两个人共用一间仓库两个清洁工都有一条规矩,开工前先把仓库里所有贴着“测试”标签的箱子扔掉。一个人干到一半,另一个人来了,把他手边还没用完的箱子也扔了。
只要两人不同时来,这条规矩一点问题也没有。
读到这里,原因已经写在代码里了,我没有再去复现旧行为。它也能解释最早那次 dropdb 的报错,后来又有一次本地检查失败,报的是收尾时要删的测试库已经不存在,库被别的测试先一步删掉了,和最早那次是同一类问题。
模板库名字跟着数据库走
修复的思路很直接。每个 worktree 本来就有自己的数据库,只要让测试库的名字也跟着它走,就不会撞车。
- 模板库改叫
<DATABASE_URL 里的库名>_test。主检出还是mousehole_test,用脚本建出来的 worktree 是mousehole_<分支名>_test。 - 删库不再按前缀匹配,只删这个确切的模板,以及后面接着 12 位十六进制的副本。
- 副本名的随机后缀从 32 位缩到 12 位。PostgreSQL 的标识符最长 63 个字符,worktree 的库名本来就更长,后缀太长会超出。
还有一个小插曲。我原本想让每个测试进程重新从环境变量算出模板名,结果发现,测试进程里看到的 DATABASE_URL 已经被测试文件的准备步骤改写成了某个副本库的地址,再算一遍得到的是错的名字。所以改用 Vitest 提供的 provide 和 inject,在全局准备阶段把模板名直接传给各个测试进程。
修好之后又冒出两个问题
删库问题修好后,我同时跑两套完整测试,立刻又遇到“too many clients already”。PostgreSQL 默认最多 100 个连接,一次完整测试最多要用 50 个左右,开发服务器平时还占着 30 多个,两套测试一起跑就超了。我在 compose 配置里把 max_connections 调到 300,并给本机正在跑的容器也调了,确认当时没有测试在跑之后重启过一次,开发服务器自己重连了。
另一个是测试文件 indexes.test.ts 的准备步骤,要灌一整年的数据,单独跑约 5 秒,机器一忙就超过默认的 10 秒时限。把它放宽到 60 秒。
还剩下的偶发失败,是时钟的问题
两个问题解决后,同时跑的测试大部分稳定通过了,但偶尔还有一两条失败,而且很有规律,都是比较先后顺序的断言。比如按最后阅读时间排序的列表,期望是 6、7,拿到的却是 7、6。
这些测试依赖数据库写入时记下的时间来排序。如果时间会倒退,先写的反而排在后面。我先对照了宿主机的时钟和 Postgres 的时钟,两者基本一致。接着在两套测试同时跑的 15 秒里,用一个循环反复读取 Postgres 的 clock_timestamp(),看有没有出现比上一次更早的值。
结果是出现了 2 次,最多往回跳了 1.4 秒。当时我猜是 WSL2 虚拟机在高负载下校准时间,但没有证据,只能先把这几条偶发失败放着,重跑就好。
三天以后,另一条测试又撞上了同样的问题,周榜统计的测试偶尔会漏掉最后几个赞。这次助手没有再猜,而是认真量了一遍。
系统时钟每半分钟就往回跳一次
它写了个很小的脚本,每 100 毫秒对比一次墙上时钟和单调时钟,两者的差一变就记下来。单调时钟只会匀速往前走,不受校时影响,正好用来当尺子。
采样的几分钟里,墙上时钟每隔约 29 秒就往回拨一次,每次 0.6 到 0.7 秒。再换成每毫秒读一次,90 秒里往回跳了 6 次,每次往回跳的同一瞬间,单调时钟只走了一毫秒多,也就是说,这是系统时钟被直接改写,而不是慢慢漂移。
接下来看谁在改。timedatectl timesync-status 的输出里,systemd-timesyncd 每 32 秒向 ntp.ubuntu.com 对一次时,每次都得出偏差 -683 毫秒,也就是它认为本机时钟快了,于是往回拨。而同一次查询的网络往返延迟高达 645 毫秒,一个延迟这么大的测量,本身就算不准这个偏差。随后 Hyper-V 的时间同步又把时钟拉回 Windows 的时间,两边就这样来回拉扯。timesyncd 从 10 月 17 日这台机器开机起,已经对时 8900 多次。
通俗比喻:两个人轮流拨同一块钟房间里有两个人,每人手里有一份不太一样的标准时间。一个每半分钟走过来,把墙上的钟往回拨一点,另一个随后走过来,又把它拨回去。钟在两个人之间来回晃,大多数时候看不出来,只有恰好在“拨回去”的那一刻看钟,才会发现时间倒退了。
测试里“刚写进去的数据”和“按现在时间统计”之间只隔了几毫秒,正好会撞上这一刻。
Docker 就跑在这个 WSL 里,两边读的是同一个时钟,所以数据库的 now() 和 Node 的 Date.now() 会一起跳。之前助手还曾判断“数据库和测试进程的时钟有几十毫秒的偏差”,这个判断是错的,它在后来更正了。
周榜统计测试的写法是,先写入几个赞,紧接着统计“截止到现在”的一周。如果这中间时钟往回跳了一下,刚写入的那几个赞就晚于“现在”,没被算进去。CI 上的时钟是正常的,所以从来没出过问题。
修法是把统计窗口的结尾放到一小时以后,这和同目录周报邮件测试的写法一样。为了验证,助手写了个临时实验,在 70 秒里反复执行“插入一个赞,立刻统计”,共 2581 次,按原来的写法漏掉 92 次,按新写法一次也没漏。
要从根本上解决,可以关掉 systemd-timesyncd,WSL 本来就靠 Hyper-V 同步时间。这需要 sudo,属于改系统设置,所以助手把命令留给了我自己决定。
这类断言的通用提醒如果测试靠“后写入的时间比先写入的时间晚”来断言顺序,或者统计一个截止到“现在”的窗口,在虚拟机或容器里就有被时钟回拨打败的可能。把窗口的结尾放远一点,或者给排序再加一个单调递增的编号做兜底,都比假设时钟永远向前更稳妥。
验证和遗留
验证的办法是,用两个检出各自完整跑一遍测试,同时跑了五六轮。跑的过程中列出 pg_database,能看到两套名字各自独立,互不干扰,跑完也没有留下遗留的测试库。剩下的失败只有时钟引起的断言。
还有三件小事要留意。同一个检出里同时跑两次测试,仍然共用同一个模板库,照样会撞上。有一次助手留在后台的测试循环在“已完成”的通知之后其实还在跑,和前台的测试抢同一个库,报出的又是库不存在,后来是按进程号才把它停掉。另外,没有合并新代码的旧 worktree,跑测试时仍然会按旧规则删掉所有 mousehole_test 开头的库,包括主检出里正在跑的,所以要先把它们都更新到最新。最后,浏览器端到端测试用的库名也是写死的,两个 worktree 同时跑也会冲突,需要的话可以照同样的思路改。