Rust in Everything
基于 tokio-metrics 0.5.2

数字看起来不对

主线位置:两条主线的读取端。数字本身是对的,是读的人按另一个定义去理解了它。
flowchart TB
  q1["busy_ratio 是 4.00"] --> a1["各 worker 之和 ÷ 墙钟"]
  q2["首次 poll 延迟多 200ms"] --> a2["从 instrument() 算起"]
  q3["slow_poll_ratio 是 NaN"] --> a3["区间里没有 poll:0 ÷ 0"]
  q4["直方图是空的"] --> a4["要 cfg,还要在 Builder 上打开"]
  q5["两个看板最大空闲不同"] --> a5["swap(0):谁先读谁拿走"]
  a1 --> f1["再除以 workers_count"]
  a2 --> f2["在 spawn 那一行 instrument"]
  a3 --> f3["导出前判断分母"]
  a4 --> f4["enable_metrics_poll_time_histogram"]
  a5 --> f5["一个 monitor 只开一个 intervals()"]

四个现象的机制都在前面讲过,这一页把它们放进一个程序里,每个都先跑出现象,再跑出修法。

use std::time::{Duration, Instant};
use tokio_metrics::{RuntimeMonitor, TaskMonitor};

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

#[tokio::main(flavor = "multi_thread", worker_threads = 4)]
async fn main() {
  // 1. busy_ratio 是各 worker 之和 ÷ 墙钟
  let rm = RuntimeMonitor::new(&tokio::runtime::Handle::current());
  let mut ri = rm.intervals();
  let hs: Vec<_> = (0..4).map(|_| tokio::spawn(async { spin(Duration::from_millis(300)) })).collect();
  for h in hs {
    h.await.unwrap();
  }
  let r = ri.next().unwrap();
  println!("1 busy_ratio={:.2} per_worker={:.2}", r.busy_ratio(), r.busy_ratio() / r.workers_count as f64);

  // 2. 首次 poll 延迟从 instrument() 算起
  let late = TaskMonitor::new();
  let fut = late.instrument(async {});
  tokio::time::sleep(Duration::from_millis(200)).await;
  tokio::spawn(fut).await.unwrap();
  let at_spawn = TaskMonitor::new();
  tokio::time::sleep(Duration::from_millis(200)).await;
  tokio::spawn(at_spawn.instrument(async {})).await.unwrap();
  println!(
    "2 first_poll_delay instrument_early={:?} instrument_at_spawn={:?}",
    late.cumulative().mean_first_poll_delay(),
    at_spawn.cumulative().mean_first_poll_delay()
  );

  // 3. 区间里没有 poll:比率是 0/0
  let quiet = TaskMonitor::new();
  let mut qi = quiet.intervals();
  qi.next();
  let q = qi.next().unwrap();
  let ratio = if q.total_poll_count == 0 { 0.0 } else { q.slow_poll_ratio() };
  println!("3 polls={} slow_poll_ratio={} guarded={}", q.total_poll_count, q.slow_poll_ratio(), ratio);

  // 4. 同一个 monitor 开两个 intervals()
  let shared = TaskMonitor::new();
  let mut a = shared.intervals();
  let mut b = shared.intervals();
  a.next();
  b.next();
  let h = tokio::spawn(shared.instrument(async {
    tokio::time::sleep(Duration::from_millis(100)).await;
  }));
  h.await.unwrap();
  let ma = a.next().unwrap();
  let mb = b.next().unwrap();
  println!(
    "4 a: idled={} max_idle={:?}  b: idled={} max_idle={:?}",
    ma.total_idled_count, ma.max_idle_duration, mb.total_idled_count, mb.max_idle_duration
  );

  // 5. 直方图:要 tokio_unstable,还要在 Builder 上打开
  #[cfg(tokio_unstable)]
  {
    let r = ri.next().unwrap();
    println!("5 runtime from #[tokio::main]: polls={} buckets={}", r.total_polls_count, r.poll_time_histogram.buckets().len());
  }
}

不带 cfg 连跑 5 次,其中一次:

1 busy_ratio=4.00 per_worker=1.00
2 first_poll_delay instrument_early=202.030875ms instrument_at_spawn=41.917µs
3 polls=0 slow_poll_ratio=NaN guarded=0
4 a: idled=1 max_idle=100.993709ms  b: idled=1 max_idle=0ns

5 次里第 1、3 行完全相同,第 4 行的 b 每次都是 0ns;instrument_early 在 202.0–203.1ms,instrument_at_spawn 在 15–42µs,a 的 max_idle 在 101.0–103.0ms。带 RUSTFLAGS="--cfg tokio_unstable" 再跑,多出第 5 行:

5 runtime from #[tokio::main]: polls=4 buckets=0

busy_ratio() 返回 4.00

busy_ratio 的分子是所有 worker 忙碌时长之和,分母是一段墙钟时间,范围是 0 到 worker 数。4 个 worker 各忙满 300ms,1.2s ÷ 0.3s = 4.00。要「平均每个 worker 有多忙」的百分比,自己再除以 workers_count。看板上如果把它当 0 到 1 的比率画、设了「大于 0.9 告警」,4 个 worker 的服务在只用了不到四分之一算力时就会报警。

细节见 Worker 差分与 poll 时间直方图。那一页还讲了另一个让它「超标」的原因:tokio 只在 worker park 前和每 61 个 tick 提交一次计数,一次很长的 poll 会在结束后的那个区间里一次补上,单个区间的 max_busy_duration 可以大于区间本身的长度。在本站中实测里,2 个 worker 的服务在一次 1.8 秒的搜索重建后,1 秒的区间里 max_busy_duration 是 1403ms。

首次 poll 延迟比预期大几百毫秒

首次 poll 延迟 = 第一次 poll 的时刻 − instrumented_at,而 instrumented_at 是在 instrument() 被调用时记下的,不是 spawn 时。上面第 2 行,先 instrument 再等 200ms 才 spawn,这 200ms 全算进了首次 poll 延迟;同样等 200ms,但在 spawn 那一行才 instrument,延迟只有几十微秒。

常见的写法是先把一批 future 包好放进 Vec,再逐个 spawn,或者把包好的 future 交给一个有界队列、由消费者稍后 spawn。这两种情况下首次 poll 延迟量到的是「排队等着被 spawn」加上「被 spawn 之后等着被 poll」。如果想要的是后一段,就在 tokio::spawn(monitor.instrument(fut)) 这一行包;如果前一段也想要,那它正好量到了。机制见 Instrumented 与 instrument_poll 的「第一段:首次 poll 延迟」。

slow_poll_ratio 是 NaN,poll_time_histogram 是空的

两件事碰巧经常一起出现,原因不同。

NaN:slow_poll_ratio 是慢 poll 数 ÷ poll 总数,long_delay_ratio 是长排队数 ÷ 排队总数,都是浮点除法。intervals() 的某个区间里一次 poll 都没有(任务都在等外部,或者这个路由这段时间没人访问)就是 0.0 ÷ 0.0 = NaN;同一个区间里 8 个 mean_* 却返回 0,因为它们除以 0 时特意返回零(TaskMetrics 与派生指标)。有的看板把 NaN 画成断点,有的导出器拒收,metrics-rs 集成则原样导出 NaN(metrics-rs 与 metrique)。第 3 行的 guarded 是一种处理:分母为 0 时按 0 算;也可以跳过这个区间不导出,看你希望看板上「没有流量」显示成 0 还是空白。

空直方图:poll_time_histogram 要两样东西:编译时带 --cfg tokio_unstable(不带时字段本身不存在,见 E0609),以及建运行时时调 Builder::enable_metrics_poll_time_histogram()。#[tokio::main] 不会替你调,所以第 5 行有 poll 计数、桶数却是 0,不报错。自己建运行时并打开它:

// 只在 --cfg tokio_unstable 下有意义
let mut b = tokio::runtime::Builder::new_multi_thread();
b.worker_threads(2).enable_all();
if enable {
  b.enable_metrics_poll_time_histogram();
}
let rt = b.build().unwrap();
let monitor = RuntimeMonitor::new(rt.handle());
enable_metrics_poll_time_histogram=false polls=10 buckets=0
enable_metrics_poll_time_histogram=true polls=10 buckets=10

默认是 10 个 100µs 宽的线性桶,900µs 以上都落进最后一个,看长尾要换成对数桶,见 Worker 差分与 poll 时间直方图 的「poll 时间直方图」一节。

两个看板的 max_idle_duration 对不上

第 4 行,同一个 monitor 开了两个 intervals():两边都看到了那次 100ms 的空闲(idled=1),但只有先 next() 的 a 拿到了最大空闲,b 是 0。计数和时长是每个迭代器各自记住上一次的读数做差,互不干扰;区间最大值做不了差,只能读一个「区间内」的原子变量再 swap(0) 清零,一个 monitor 只有这一份,谁先读谁拿走。

实际中的样子:一个后台任务每 10 秒 intervals() 打日志,同时 metrics-rs 的 reporter 自己也开了一个 intervals() 每 30 秒导出;或者两个看板各起一个采样任务。修法是一个 monitor 只开一个 intervals(),取到的 TaskMetrics 再分发给各个消费者(它实现了 Clone);或者需要两种周期时,一个用 intervals(),另一个用 cumulative() 自己做差,cumulative() 读的是全局最大值,不会清零。细节见 intervals:迭代器差分。

小结

  • busy_ratio 范围是 0 到 worker 数,要百分比再除以 workers_count;计数提交滞后会让单个区间更「超标」。
  • 首次 poll 延迟从 instrument() 算起,包和 spawn 不在同一行时,中间的时间也算进去。
  • 区间里没有 poll 时两个比率是 NaN,均值是 0;导出前判断分母。
  • poll_time_histogram 要 tokio_unstable 加 enable_metrics_poll_time_histogram(),#[tokio::main] 不会打开它,空着也不报错。
  • 区间最大空闲靠 swap(0),同一个 monitor 的第二个 intervals() 读到 0;一个 monitor 只开一个。

💬 关联讨论

发起讨论
加载中...