Tokio + prctl = 麻烦的Bug
最近,我遇到了一个非常有趣且可爱的Bug,让我立刻知道我要在我的博客上分享它。这个Bug属于那种即使使用Rust也无法完全避免的问题。
事情发生在HyperQueue(HQ)中,这是用Rust编写的一个分布式任务调度器,而我是它的主要开发者之一。尽管HyperQueue是一个相对复杂的分布式应用,并且大多是由两个时间有限的人开发维护,但到目前为止,它的可靠性令人惊讶。不过,在我们发布了版本0.21.0之后,开始接收到一些关于严重问题的报告:由HyperQueue启动的任务在几秒内会被终止,且没有明显的理由。
其中有一个报告特别奇怪:任务运行正常,但最后一个被执行的任务总是失败,无论是什么任务。这种现象对于我们来说是非常不寻常的,因为HyperQueue通常表现很好,而且我们的CI测试集也通过了。那么到底发生了什么呢?让我们深入挖掘吧!
Bug的起源
幸运的是,其中一个用户提供了一个可靠的重现方法,该方法在我本地机器上稳定地重现了这个问题。当HyperQueue启动执行以下简单的Python函数时:
def work():
time.sleep(10)
print("hello world")
任务会在大约十秒后(就在打印之前)失败,并且没有任何输出。更奇怪的是,如果我把sleep的时间改为2秒或5秒,任务都能正常完成;但如果设置为10秒,任务就会失败。这实在让人摸不着头脑。
借助这个重现方法,我使用git bisect run在几分钟内定位到了引入Bug的提交。这个提交实际上是在2024年夏天创建的,当时我在进行博士论文相关的大规模HyperQueue基准测试实验。虽然这个改动很早就存在,但它直到最近才被合并进主分支,因此问题现在才显现出来。
这个提交稍微改变了我们在HyperQueue中启动任务(外部进程)的方式:
- let mut child = command.spawn();
+ let mut child = tokio::task::spawn_blocking(move || command.spawn())
+ .await
+ .expect("Command spawning failed");
看起来只是个小改动!它只是改变了命令在哪里启动(也就是fork/clone/exec系统调用在哪个线程执行),其余部分仍然是相同的。因此,我起初感到困惑为什么这一改动会导致如此奇怪的行为。
之所以我会做出这个改动,是因为在Linux上创建进程的操作并不像看上去那样廉价。HyperQueue需要能够每秒创建数千个进程,而这些操作通常在HPC集群和超级计算机上运行,这些系统可能使用非常老版本的Linux内核和glibc库(C标准库的实现)。因此,仅仅创建进程本身也可能成为性能瓶颈。
为了实现并发,HyperQueue使用了tokio框架,特别是它的单线程运行时。但是,需要注意的是,tokio的Command的spawn方法是阻塞的!这是因为fork并没有异步版本。如果快速启动大量进程,启动开销会累积,可能导致tokio线程被阻塞,其他任务得不到资源。所以,为什么不使用spawn_blocking函数将此操作卸载到其他(工作)线程呢?我尝试了一下,似乎确实提高了HyperQueue的性能。这就是那个提交诞生的原因。
有趣的是,这个提交是在一个极其庞大的PR中加入的,这个PR基本上是我夏季基准测试实验的回退版。这个PR几乎只包含了对基准测试的修改,应该不需要太多审查就能合并。然而,它也包含两个小改动。我在PR描述中写道:
这是对我的博士论文准备的基准测试进行了回退并合并进HQ仓库。几乎所有更改都与基准测试相关,因此无需太多审查。HQ也有少量更改:命令启动优化以及禁用认证以用于基准测试选项。
嗯,结果证明,“命令启动优化”竟然破坏了许多用户的HyperQueue核心功能。这就是提交大型代码改动的风险啊,真是令人叹服。
找出原因
既然我已经知道了哪个提交导致了Bug,接下来只需要找出“为什么”。我无法理解为什么将阻塞操作移动到tokio线程池会产生这样的问题。如果有死锁之类的情况,那还好理解,但任务随机在大约十秒后被终止,这实在太奇怪了。我不太习惯HyperQueue出现这种类型的海森Bug(Heisenbug)。于是,我的第一反应就是责怪tokio(笑)!我认为可能是命令必须在同一线程中启动并轮询完成状态,或者是类似的限制。但在tokio的问题跟踪器中我没有找到任何相关信息。当我试图在HyperQueue之外创建一个独立程序来重现这个问题时,它居然能正常工作:
use tokio::process::Command;
#[tokio::main(flavor = "current_thread")]
async fn main() {
let mut cmd = Command::new("sleep");
cmd.arg("10");
let mut child = tokio::task::spawn_blocking(move || {
cmd.spawn().unwrap()
}).await.unwrap();
let res = child.wait().await.unwrap();
assert_eq!(res.code(), Some(0));
}
让我更加迷惑的是,任务完全没有产生任何输出,也没有退出码。我们原本在HyperQueue中这样检查任务进程的退出码:
let status_to_result = |status: ExitStatus| {
if !status.success() {
let code = status.code().unwrap_or(-1);
Err(tako::Error::GenericError(format!(
"Program terminated with exit code {code}"
)))
} else {
Ok(TaskResult::Finished)
}
};
退出码为-1,这意味着退出码缺失。显然有什么东西在几秒内杀死了我们的任务,且既没有输出也没有退出码。会不会是信号呢?起初,我找不到从ExitStatus获取发送给任务进程信号的方法,但我意识到这可能是操作系统特定的。果然,在Linux上有ExitStatusExt,它提供了一种获取收到信号的方法。
不出所料,记录下来后发现任务确实是被SIGTERM杀死的。但谁(或者什么)发出了这个信号,为什么没有spawn_blocking就不会有这个问题?现在进入有趣的环节。
HyperQueue本质上是一个运行在用户空间的进程管理器。用户空间的部分提供了许多优势,但也引入了局限性。特别地,当启动任务的进程(称为工作者,worker)意外退出时(例如接收到SIGKILL),其派生的任务可能不会被清理。不幸的是,Linux似乎没有在用户空间实现完美的结构化进程管理的方法。也就是说,父进程死亡后,其子进程(甚至孙子进程)仍可能继续运行。一种解决方案是使用PID命名空间,但这需要提升权限,且对HyperQueue来说可能过于笨重。
一段时间前,我发现了一个部分解决方法,可以至少在HQ工作者死亡时清理直接子进程(遗憾的是无法处理孙进程)。这就是PR_SET_DEATHSIG,我们通过prctl系统调用配置它,如下所示:
unsafe {
command.pre_exec(|| {
// 当父进程(工作者)死亡时,向任务发送SIGTERM。
libc::prctl(libc::PR_SET_PDEATHSIG, libc::SIGTERM);
});
}
你可能已经猜到,这里提到PR_SET_DEATHSIG并非偶然,配置发送SIGTERM给任务的行为正是杀死任务的罪魁祸首。没错,当我注释掉prctl调用后,Bug消失了。
但这仍然没有解释清楚问题,因为工作者并没有死亡。那么为什么还会发送SIGTERM给任务呢?让我们看看PR_SET_PDEATHSIG的描述:
将调用进程的父进程死亡信号设置为sig(范围[1, NSIG - 1]内的信号值,或者0清除)。这是父进程死亡时调用进程将接收到的信号。
这听起来合理。当父进程(工作者进程)死亡时,任务接收SIGTERM,这是我想要的结果。或者至少我以为会是这样……
问题是关键词“父进程”。我一直以为它是“父进程”,但再次仔细阅读描述的下一句:
父进程死亡信号会在后续的父线程终止时发送,也会在...
等一下!它说的是“线程”?糟了。突然一切都清晰起来——你明白了吗?
通过将命令启动移动到另一个(tokio工作线程)中,我实际上是告诉内核,当该工作线程而不是父进程(或其主线程)死亡时向派生进程发送SIGTERM。这种情况可能不会单独出现问题,但看起来工作线程在闲置约十秒后会被终止。也许tokio会在后台定期回收没有任务的工作线程?我使用num_threads库计算了重现程序中的活动线程数:
let mut cmd = Command::new("sleep");
cmd.arg("10");
unsafe {
cmd.pre_exec(|| {
libc::prctl(libc::PR_SET_PDEATHSIG, libc::SIGTERM);
Ok(())
});
}
let mut child = tokio::task::spawn_blocking(move || {
cmd.spawn().unwrap()
}).await.unwrap();
eprintln!("Thread count: {}", num_threads::num_threads().unwrap());
let res = child.wait().await.unwrap();
eprintln!("Thread count: {}", num_threads::num_threads().unwrap());
eprintln!("{:?}", res.signal());
不出所料,它打印出:
Thread count: 2
Thread count: 1
Some(15)
所以tokio显然在几秒钟的空闲后终止了工作线程,这导致内核用SIGTERM终止了派生进程。这也是为什么当提交更多任务时它们能成功完成的原因(如#815所示),因为工作线程会收到更多工作(更多命令要启动),tokio需要更长时间才能终止它。只有最后一个任务会失败,因为工作线程没有别的任务要做,因此结束并杀死了最后一个任务。真令人难以置信。
编辑:有人在Reddit给我发了一个链接,指向一个方法,该方法可以覆盖线程保持活动的时间。它的描述清楚地解释了为什么任务会在正好十秒后失败(笑)。我不想修改这个持续时间来“修复”这个Bug。HyperQueue应该尽可能少地消耗资源,空闲线程应尽快被清理。
所以,这个案例告一段落。问题是由于我们在非主线程中启动进程、使用PR_SET_PDEATHSIG以及tokio后台回收空闲线程之间的不幸互动造成的。注意,这里不能怪tokio,回收空闲线程是合理的行为。这只是几种单独正常工作的因素组合在一起却没有很好地协同工作的不幸情况之一。
修复Bug
可能会有点失望,但我“修复”这个Bug的方式仅仅是回滚了那个任务启动优化的提交。我不想放弃PR_SET_PDEATHSIG提供的清理功能,也不知道如何仅在父进程(而非线程)死亡时发送信号,或者如何在用户空间以其他方式实现这种功能。
很遗憾,我们的测试套件没有捕捉到这个Bug;显然没有测试任务运行超过几秒的情况!一般来说,测试类似的东西是很棘手的,但我不想完全不进行回归测试,所以我至少实现了这个测试。测试一个任务是否能运行20秒虽然不是最理想的选择,但总比没有好。
总结
最终,花费不到一个小时就找到了这个Bug、诊断清楚并修复了它,与其他Debugging故事相比,这不算太糟糕。但我认为这个Bug相当美丽,所以还是想分享给大家。
希望你觉得这次调试经历有趣,并可能从中学到了一些新知识。如果有任何评论,请在Reddit告诉我。
