linux - 如何调试 tokio 任务挂起的位置？

Question

我在调试轮询代码中的随机挂起时遇到了恰好 11 毫秒的问题。这种情况发生在多个服务器上，具有不同的硬件配置和操作系统(并且相关代码没有共享资源)，因此我倾向于相信它在我的代码中。

本质上，我有一堆正在进行的 TCP 请求，我将它们作为列表中的 future 。我的轮询功能正在检查它们并通过 channel 发送结果。大部分时间都工作正常，但偶尔会暂停 11 毫秒，然后继续。

通常，Waker 由底层 TCP 连接以及将请求插入队列的 channel 进行调度。但出于调试目的，我添加了一个忙碌循环，它总是立即调度 Waker。

使用繁忙循环，我期望有持续的 poll() 调用流，通常情况就是这样。然而，当其中一个问题发生时，我看到线程似乎被暂停/抢占，然后在 11 毫秒后重新启动。

一些我没想到会发生暂停的地方的例子:

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");
... snipped...
            }
            warn!("done (not ready!) future");

可以看到它成功地轮询了底层的 future，并且在对轮询结果执行简单的 if-let 时，暂停了 11 毫秒。我希望立即执行 future 就绪或完成(未准备好!) future 。

另一个例子是:

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 指针，这不会花费任何时间。

这种情况发生的频率足够高，很容易重现(轻负载下每隔几秒一次)，但这种情况很少发生，以至于 strace 会生成大量难以筛选的数据。这也是在一个更大的应用程序中，我没有运气制作一个小的可重复的案例。

运行轮询循环的线程是这样启动的:

    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 使用率、充足的内核)...

如何调试线程暂停的原因，以及为什么即使在不同的服务器上，其总是 11 毫秒？

编辑:添加一些 strace 数据...

[pid 4056498] 20:34:14.995277 write(1, "\33[2m2023-09-27T00:34:14.995272Z\33"..., 1402023-09-27T00:34:14.995272Z  WARN database::backends: poll future... Pending
 <unfinished ...>
[pid 4056497] 20:34:14.995283 write(11, "{\"id\":[snipped]"..., 192 <unfinished ...>
[pid 4056498] 20:34:14.995289 <... write resumed>) = 140 <0.000007>
[pid 4056497] 20:34:14.995293 <... write resumed>) = 192 <0.000006>
[pid 4056498] 20:34:14.995298 write(1, "\33[2m2023-09-27T00:34:14.995294Z\33"..., 1422023-09-27T00:34:14.995294Z  WARN database::backends: done (not ready!) future
 <unfinished ...>
[pid 4056501] 20:34:14.995304 <... epoll_wait resumed>[{events=EPOLLOUT, data={u32=2752585088, u64=2699992046976}}], 1024, 3) = 1 <0.000574>
[pid 4056497] 20:34:14.995309 epoll_wait(20,  <unfinished ...>
[pid 4056501] 20:34:14.995315 epoll_wait(3,  <unfinished ...>
[pid 4056498] 20:34:15.006650 <... write resumed>) = 142 <0.000016>
[pid 4056501] 20:34:15.006668 <... epoll_wait resumed>[{events=EPOLLIN|EPOLLOUT, data={u32=2752585088, u64=2699992046976}}], 1024, 2) = 1 <0.011350>
[pid 4056501] 20:34:15.006689 write(22, "\1\0\0\0\0\0\0\0", 8 <unfinished ...>
[pid 4056498] 20:34:15.006696 write(1, "\33[2m2023-09-27T00:34:15.006681Z\33"..., 135 <unfinished ...>
2023-09-27T00:34:15.006681Z  WARN database::backends: poll loop finished

可以看到与上面相同的行(done(未准备好!) future )，其后的下一行就在循环结束的另一侧，伪代码:

loop {
  log("poll future");
  if (ready) {
    ...
  } else {
    log("done (not ready!) future");
  }
}
log("poll loop finished");

因此，在 else 日志和循环日志结束之间，strace 执行了两个 epoll_wait()，并暂停了 11 毫秒。

编辑:当 epoll_wait() 发生时，它专门等待 anon_inode:[eventpoll] 例如:

[pid 4057391] 20:53:44.862936 epoll_wait(19<anon_inode:[eventpoll]>,  <unfinished ...>
[pid 4057360] 20:53:44.862949 <... epoll_wait resumed>[{events=EPOLLOUT, data={u32=1511071104, u64=2660095827328}}], 1024, 2) = 1 <0.011111>

调试的下一步是什么？

Answer 1

Can see it successfully polled the underlying future, and when doing a simple if-let on the Poll result, gets suspended for 11ms. I would expect future ready or done (not ready!) future to be executed immediately.

if let 极不可能导致此处的延迟，特别是因为您的 warn! 语句已经包含 poll_unpin 返回的结果。因此，延迟可能发生在日志记录语句期间，该语句很可能比其他语句花费更长的时间。

如果您想测试程序在正常执行期间的行为，最好存储一些统计信息。例如，您可以跟踪每次迭代之间的时间并计算迭代时间超过 10 毫秒的次数，然后偶尔输出该计数。此技术可用于确保您当前观察到的问题不是由日志记录语句本身引起的。这看起来并不困难:在繁忙循环中的每次迭代中记录日志都是自找麻烦。这些东西什么时候会被提交到日志中？哪个线程会执行此操作？这个线程在提交这么大量的数据之前是否需要获取锁？

Obviously could be, but 11ms seems like a long time to be off-core. These are (reasonably) beefy boxes, 12-16 core, and this happens plenty often when they're under low load. I'd expect a core to be available at almost all times...

一般来说，如果有其他线程想要在同一核心上运行，11ms 并不算长。请参阅this question 。特别是如果您关心延迟，您可能想了解如何调整调度程序设置，以了解如何尽可能避免非核心时间。

您的服务器可能看起来很空闲，但可能有外部事件触发许多事情同时发生，使其在短时间内更加繁忙。例如，可能有多个请求传入，或者这些请求可能产生多个不同的线程。此外，事实上，转移到不同的核心会带来大量缓存未命中的成本，因此通常会被调度程序延迟。

简而言之，以下是一些不错的后续步骤:

1. 在进行性能跟踪时，请确保性能跟踪不会使负载恶化太多。用一些轻量级的簿记取代繁忙循环中的日志记录。
2. 检查您的调度程序设置，尤其是在您关心延迟的情况下。
3. 调查哪些其他线程正在同一核心上运行，如果可能，请确保它们在不同的核心上运行。