Rust in Everything
基于 tokio-metrics 0.5.2

它解决什么问题

主线位置:两条主线的动机。本页回答为什么要在任务外面包一层:只有包住任务,才能把一个任务的时间切成 poll、排队、空闲三段,再按任务的种类分开统计。
sequenceDiagram
  participant Q as 运行队列
  participant W as worker 线程
  participant I as Instrumented
  participant X as 外部(IO、定时器、别的线程)
  Q->>W: 取出任务
  W->>I: poll
  Note over I: poll 时长:在 worker 上跑了多久
  I-->>W: Pending
  Note over I,X: 空闲:上次 poll 结束到被唤醒
  X->>I: wake
  I->>Q: 记下唤醒时刻,转给 tokio,任务进队列
  Note over Q,I: 排队:被唤醒到下次被 poll
  Q->>W: 轮到它
  W->>I: poll
  Note over W: 运行时主线:读 tokio 每个 worker 的累计计数器

问题:慢在哪一段

线上一个接口的 p99 变高了。可能的原因有三种,治法完全不同:

慢在哪现象治法
自己 poll 得慢一次 poll 里做了重计算、同步 IO、拿了阻塞锁挪进 spawn_blocking,或者拆小、中间让出
排队排得久自己很快,但被唤醒之后迟迟轮不到;同一个 worker 上有别的任务在做上一种事找出那个慢 poll 的任务;或者加 worker
在等外部数据库、下游服务、定时器本来就慢和异步运行时无关,去看外部

请求级的耗时(日志里的 latency、tracing 的 span 时长)只给出三段的和。tokio 自己的 Handle::metrics() 能给出每个 worker 忙了多久、poll 了多少次,但那是整个运行时的数字:它说不出是哪一类任务慢,也说不出一个任务慢在哪一段。

tokio-metrics 的回答是在任务外面包一层:TaskMonitor::instrument(fut)。包过的 future 每次被 poll 都记下三个时刻,按 monitor 累加:一个路由一个 monitor,就能知道这个路由的任务平均每次 poll 多久、被唤醒后平均等多久、两次 poll 之间平均空闲多久。README 的说法是(README 第 28 行起):同一个 TaskMonitor 包住的任务把指标聚合到一起,要分开看就用不同的 monitor(原文写的是 separate TaskMetrics instances,按上下文指的是 TaskMonitor)。

实验:三种慢各落进一列

三类任务各 10 个,交错 spawn 在单线程运行时上:

  • cpu:一次 poll 忙等 3ms,代表「自己 poll 得慢」。
  • io:sleep(10ms),代表「在等外部」。
  • victim:把一件小事交给阻塞线程池(spawn_blocking),做完立刻从那个线程唤醒自己。它自己几乎不花时间,但和 cpu 挤在同一个线程上。
tokio-metrics = "=0.5.2"
tokio = { version = "=1.54.1", features = ["full"] }
use std::time::{Duration, Instant};
use tokio_metrics::{TaskMetrics, TaskMonitor};

fn spin(d: Duration) {
  let t = Instant::now();
  while t.elapsed() < d {}
}

fn show(name: &str, m: &TaskMetrics, wall: Duration) {
  println!(
    "{name:<5} wall={:>6.1?} poll={:>6.1?} idle={:>6.1?} sched={:>6.1?}  slow_polls={} long_delays={}",
    wall,
    m.total_poll_duration / m.instrumented_count as u32,
    m.total_idle_duration / m.instrumented_count as u32,
    m.total_scheduled_duration / m.instrumented_count as u32,
    m.total_slow_poll_count,
    m.total_long_delay_count,
  );
}

#[tokio::main(flavor = "current_thread")]
async fn main() {
  let cpu = TaskMonitor::new(); // 自己算得慢
  let io = TaskMonitor::new(); // 在等外部(这里用 sleep 代替)
  let victim = TaskMonitor::new(); // 自己很快,但和 cpu 挤在同一个线程上

  let start = Instant::now();
  let mut handles = Vec::new();
  for _ in 0..10 {
    handles.push(tokio::spawn(cpu.instrument(async {
      let t = Instant::now();
      spin(Duration::from_millis(3));
      t.elapsed()
    })));
    handles.push(tokio::spawn(io.instrument(async {
      let t = Instant::now();
      tokio::time::sleep(Duration::from_millis(10)).await;
      t.elapsed()
    })));
    handles.push(tokio::spawn(victim.instrument(async {
      let t = Instant::now();
      // 交给阻塞线程池做一件小事;它做完时从另一个线程唤醒本任务
      tokio::task::spawn_blocking(|| ()).await.unwrap();
      t.elapsed()
    })));
  }
  let mut walls = [Duration::ZERO; 3];
  for (i, h) in handles.into_iter().enumerate() {
    walls[i % 3] += h.await.unwrap();
  }
  println!("total {:?}", start.elapsed());
  show("cpu", &cpu.cumulative(), walls[0] / 10);
  show("io", &io.cumulative(), walls[1] / 10);
  show("victm", &victim.cumulative(), walls[2] / 10);
}

wall 是任务自己量的从第一次被 poll 到完成的时间,其余几列是每个任务的平均值。连跑 5 次,各列的毫秒数一致,只有微秒级的数字在变,其中一次:

total 41.407583ms
cpu   wall= 3.0ms poll= 3.0ms idle= 0.0ns sched= 0.0ns  slow_polls=10 long_delays=0
io    wall=16.4ms poll=566.0ns idle=16.4ms sched=954.0ns  slow_polls=0 long_delays=0
victm wall=13.5ms poll= 5.0µs idle=10.7µs sched=13.5ms  slow_polls=0 long_delays=9

三行各有一列独占了 wall:

  • cpu:poll = wall = 3.0ms。10 次 poll 全部超过默认的 50µs 阈值,slow_polls=10。
  • victim:poll 只有几微秒,sched 却是 13.5ms。第 i 个 victim 被阻塞线程池唤醒后,要排在还没跑的 cpu 后面,平均前面还有 4.5 个,4.5 × 3ms = 13.5ms。最后一个 victim 后面没有 cpu,所以 10 次排队里有 9 次超过默认的 50µs,long_delays=9。
  • io:几乎全是 idle。但它睡的是 10ms,idle 是 16.4ms:多出来的 6ms 是定时器到期了却没人处理,单线程一直被 cpu 占着,驱动没机会查时间轮。woke_at 记的是 wake() 被调用的那一刻,这段延误被算进了空闲而不是排队,包装 waker 一页专门讲这种边界。

单看请求耗时,io 和 victim 差不多慢;拆开之后,一个该去查外部依赖,一个该去找同一线程上的 cpu。这就是这个库的用途。

和别的工具的分工

tokio 自带的 Handle::metrics()

tokio 1.54.1 的 RuntimeMetrics 不需要 tokio_unstable 就能读 num_workers、num_alive_tasks、global_queue_depth,以及每个 worker 的忙碌时间、park 次数、park/unpark 次数(这三个包在 cfg_64bit_metrics! 里,要求平台有 64 位原子);poll 次数、窃取次数、本地队列深度等要 tokio_unstable。它们全是从运行时启动开始的累计值,而且都按 worker 或整个运行时统计。

tokio-metrics 和它的关系分两半:

  • 运行时指标:本库不量任何新东西,只是把 tokio 的累计值定期读出来,做差得到「这个区间」的值,再把各 worker 的值求和、求最大最小,这是 02 运行时指标的内容。
  • 任务指标:tokio 不提供按任务分组的数字(1.54.1 有 on_before_task_poll / on_after_task_poll 两个钩子,但都要 tokio_unstable,而且只给你回调,统计要自己写)。本库靠包 future 自己量,不需要 tokio_unstable,在任何运行时上都能用。

tokio-console

README 的 Relation to Tokio Console 一节只有三句:

Currently, Tokio Console is primarily intended for **local** debugging. Tokio
metrics is intended to enable reporting of metrics in production to your
preferred tools. Longer term, it is likely that `tokio-metrics` will merge with
Tokio Console.

即:console 主要用于本地调试,本库用来把指标报给生产环境里你自己的看板工具,长期看两者可能合并。console 要求什么构建条件,见设计取舍的「与 tokio-console 的分工」;它的开销本卷没有测。

dial9

README 的 Relation to dial9 一节(0.5.1 加入):dial9 记录 tokio、操作系统和应用的事件,用来事后排查、找根因;本库把指标报给看板和告警。原话的最后两句是 tokio-metrics can tell you something is wrong. Dial9 can help tell you what is wrong. 本库告诉你出了问题,dial9 帮你找出是什么问题。

工具产出怎么拿到数据典型用法
Handle::metrics()运行时 / worker 级累计值tokio 内部计数器自己读、自己算
tokio-metrics运行时区间值 + 按 monitor 分组的任务指标读 tokio 计数器;包 future生产看板、告警
tokio-console每个任务的实时状态tokio 的 tracing 事件本地调试
dial9事件记录tokio、操作系统、应用事件事后分析

后两行只按两份 README 的描述写,不展开。

小结

  • 一个任务的墙钟时间 = poll + 排队 + 空闲(再加上首次 poll 之前的等待)。请求耗时只给出和,tokio 的运行时指标给不出按任务分组的数字。
  • tokio-metrics 包住任务,按 monitor 累加三段时间;一类任务一个 monitor。
  • 实验里三类任务各被一列独占:忙等的落在 poll,挤在同一线程上的落在排队,等定时器的落在空闲。
  • 空闲和排队的分界是 wake() 被调用的时刻;定时器到期但没人处理的那段时间算空闲。
  • 本库的运行时指标只是把 tokio 的累计值做差;console 用于本地调试,dial9 用于事后找根因,本库用于生产看板。

💬 关联讨论

发起讨论
加载中...