如何调试Tokio任务出现的固定11ms随机挂起问题？

问题概述 #

调试轮询代码时遇到精确11ms的随机挂起，该问题在不同硬件、操作系统的多台服务器上均出现，无共享资源，倾向于代码层面问题。

将大量在途TCP请求作为futures存入列表，轮询函数检查这些请求并通过通道发送结果，多数情况运行正常，但偶尔会暂停11ms后恢复。正常情况下Waker由底层TCP连接和推送请求的通道调度，为调试添加了始终立即调度Waker的忙循环（本应持续触发poll()调用），但挂起发生时线程仍会被暂停/抢占，11ms后才恢复。

挂起场景示例 #

场景1：轮询后简单判断阶段挂起 #

日志示例：

2023-09-26T23:29:54.354627Z  WARN database::backends: checking pending: 1
2023-09-26T23:29:54.354637Z  WARN database::backends: poll future... Pending
2023-09-26T23:29:54.365740Z  WARN database::backends: done (not ready!) future

对应代码：

let fut_polled = fut.poll_unpin(cx);
warn!("poll future... {:?}", fut_polled);
if let Poll::Ready((x, y, z)) = fut_polled {
  warn!("future ready");
// ... 省略后续代码 ...
}
warn!("done (not ready!) future");

说明：轮询底层future返回Pending后，执行简单的if-let判断时被挂起11ms，本该立即输出future ready或done (not ready!) future。

场景2：指针获取阶段挂起 #

日志示例：

2023-09-26T23:25:07.669470Z  WARN database::backends: poll
2023-09-26T23:25:07.680708Z  WARN database::backends: poll loop!

对应代码：

fn poll(self: Pin<&mut Self>, cx: &mut Context<'_>) -> Poll<Self::Output> {
  warn!("poll");
  let pin = self.get_mut();
  loop {
    warn!("poll loop!");
// ... 省略后续代码 ...

说明：self.get_mut()仅返回底层Pin指针，本不应耗时，但此处仍出现11ms延迟。

线程运行环境 #

启动轮询循环的线程代码：

let _ = std::thread::Builder::new()
  .name("database-thread".to_string())
  .spawn(move || {
    let rt = tokio::runtime::Builder::new_current_thread()
      .enable_all()
      .build()
      .expect("failed to create tokio runtime");

    rt.block_on(async move { handler.await });
  })
  .expect("failed to spawn database thread");

服务器负载状态：内存充足、CPU使用率低、核心富余。

已排查信息 #

• 轻负载下几秒即可复现，但频率不高；strace数据量过大难以筛选，无法构建最小复现案例。
• strace捕获到：挂起发生在done (not ready!) future日志与循环结束日志之间，期间执行了两次epoll_wait()，耗时11ms，且针对anon_inode:[eventpoll]。

下一步调试建议 #

• 排查Tokio Runtime的epoll配置：检查new_current_thread模式下，epoll_wait的默认超时设置是否为11ms相关值；尝试显式修改epoll超时参数，验证是否影响挂起时长。
• 跟踪Waker调度逻辑：在Waker的wake_by_ref方法处添加日志，确认挂起前后Waker是否被正确、及时唤醒，排查是否存在唤醒延迟或丢失的情况。
• 分析future的poll逻辑：逐个排查列表中future的类型，检查是否有自定义poll逻辑间接触发了runtime的park操作，导致线程被挂起。
• 使用perf分析线程状态：通过perf record -p <线程PID>捕获挂起发生时的线程栈，用perf report查看调用栈，定位线程在11ms内的具体状态（内核态epoll_wait还是用户态阻塞）。
• 调整Runtime配置对比测试：尝试禁用enable_all()，只启用TCP、时间等必要功能；或改用多线程Runtime，看问题是否依然存在，判断是否与单线程调度逻辑相关。
• 检查系统定时器精度：通过cat /proc/timer_list查看系统定时器最小周期，确认是否与11ms存在关联（但更可能是代码层面的超时设置）。

内容的提问来源于stack exchange，提问作者theflash