Rust in Everything
基于 tokio-metrics 0.5.2

在本站中实测

主线位置:两条主线的使用端。任务主线量具体的工作(一次重建、一类请求),运行时主线量整个运行时,这一页把两者放进一个真实服务里对照着看。

本页的框架链接都指向提交 ceffc19,行号以这个提交为准。实验代码只加在一个本地分支上,不合并,下面贴出的是它的主要改动(省略了 Cargo.toml、模块声明和一个把字段原样打日志的函数)。

那个提交的 Cargo.lock 锁的是 tokio 1.52.3(第 8089 行),满足 tokio-metrics 0.5.2 的 >= 1.45.1;加上依赖后 cargo 只新增了 tokio-metrics 一个包,tokio 仍是 1.52.3。本页的实测跑在 1.52.3 上,而不是本卷其他页的 1.54.1;只用到任务指标和稳定的运行时字段。

flowchart TB
  client["压测:SSR、API、静态文件"] --> hyper["主运行时 12 个 worker:连接、中间件"]
  hyper --> mw["实验中间件:按路径三个 TaskMonitor"]
  mw --> ssr["SSR 渲染、server fn"]
  ssr --> pool["dioxus 的 LocalPool:12 个线程"]
  pool -->|oneshot 唤醒| hyper
  tick["每 20 秒一次重建"] --> re["REINDEX monitor"]
  re --> worker["占住主运行时的一个 worker"]
  worker --> tv["tantivy:读盘、写索引、等合并"]
  rm["RuntimeMonitor:只用稳定字段"] -.-> hyper

环境与做法

  • 机器:M2 Max 笔记本(12 核)、macOS、rustc 1.99.0。服务端用 cargo build --release -p app --no-default-features --features server,payments,papers 构建,直接运行二进制,不走 dx serve;页面能渲染,只是没有客户端 wasm 的交互,对服务端的测量没有影响。
  • 数据:本地 Postgres 容器;内容目录和线上同一份,索引约 1 700 篇(文章、文档、案例、课程、论坛主题、论文)。
  • 改动:搜索重建的周期从 600 秒改成 20 秒,采样周期从规划的 10 秒改成 1 秒(重建只持续一两秒,10 秒的区间会把它摊平);关掉了 /api 限流和支付对账任务,免得压测被 429 截断、对账去连外网。
  • 压测:ApacheBench,三路同时跑 80 到 100 秒:SSR 首页 / 并发 6(不复用连接;首页是分块传输的流式响应,ab -k 处理不了)、POST /api/search/query 并发 1、一个 CSS 文件并发 1。压测期间删掉索引目录里的 manifest.json 一到两次,让下一次「增量」重建把约 1 700 篇全部重写一遍,放大效应。
  • 样本:12 个 worker(默认,等于核数)跑 2 轮有效压测(另有 1 轮的 SSR 压测因为用了 -k 没跑起来,只用了它的重建数据),TOKIO_WORKER_THREADS=2 跑 1 轮,模拟小机器;另有 1 轮不压测的空闲对照;每轮启动时的第一次重建也发生在压测开始之前。一共 26 次重建,其中 6 次是全量重写,1 次是空目录上的首次构建。

改了什么

按路径分三个 TaskMonitor

在 dioxus::server::router(App) 组装好的路由最外层,紧挨着 安全响应头中间件 再套一层 from_fn。路径以 /api/ 开头的算服务端函数,最后一段带扩展名的算静态资源,其余算 SSR 页面:

use std::sync::LazyLock;
use std::time::Duration;

use axum::extract::Request;
use axum::middleware::Next;
use axum::response::Response;
use tokio_metrics::{RuntimeMonitor, TaskMetrics, TaskMonitor};

pub static SSR: LazyLock<TaskMonitor> = LazyLock::new(TaskMonitor::new);
pub static API: LazyLock<TaskMonitor> = LazyLock::new(TaskMonitor::new);
pub static STATIC: LazyLock<TaskMonitor> = LazyLock::new(TaskMonitor::new);
/// 重建任务:慢 poll 阈值设成 10ms,正好是判定线。
pub static REINDEX: LazyLock<TaskMonitor> =
  LazyLock::new(|| TaskMonitor::with_slow_poll_threshold(Duration::from_millis(10)));

fn monitor_for(path: &str) -> &'static TaskMonitor {
  if path.starts_with("/api/") {
    &API
  } else if path.rsplit('/').next().is_some_and(|seg| seg.contains('.')) {
    &STATIC
  } else {
    &SSR
  }
}

pub async fn task_metrics_mw(req: Request, next: Next) -> Response {
  let monitor = monitor_for(req.uri().path());
  monitor.instrument(next.run(req)).await
}
    // 实验:最外层按路径分三个 TaskMonitor。
    let router =
      router.layer(axum::middleware::from_fn(crate::server::task_metrics::task_metrics_mw));

用 LazyLock<TaskMonitor> 而不是 static TaskMonitorCore,是因为要用 TaskMonitor::with_slow_poll_threshold;REINDEX 一开始写成 TaskMonitor::builder().with_slow_poll_threshold(..).build(),编译报 E0507。

两点要先说清楚这个中间件量到的是什么:

  • next.run(req) 返回的 future 在响应头准备好时就完成了。SSR 首页是流式响应,响应体由 hyper 在这个 future 之外继续 poll,不在 SSR monitor 的计数里。
  • 这个 Instrumented 嵌套在 hyper 的连接任务里,不是被 tokio 直接调度的那一层。它量到的排队 = 连接任务的排队 + 连接任务这次 poll 走到中间件之前花的时间(包装 waker 的「嵌套的 Instrumented」)。中间件在最外层,前面只有 hyper 自己的几步,第二项很小。

包住搜索增量重建

main.rs 第 324 行 起的定时任务,每轮的 reindex_incremental() 包一层,每轮结束取一次 intervals(),正好是这一轮的数字:

    tokio::spawn(async move {
      use crate::server::task_metrics::{log_task, REINDEX};
      let mut ticker = tokio::time::interval(std::time::Duration::from_secs(reindex_secs));
      let mut reindex_iv = REINDEX.intervals();
      let _ = reindex_iv.next();
      loop {
        ticker.tick().await;
        let wall = std::time::Instant::now();
        let res = REINDEX.instrument(module_search::engine::reindex_incremental()).await;
        tracing::info!(target: "exp_metrics", wall_ms = wall.elapsed().as_millis() as u64, "reindex wall");
        if let Some(m) = reindex_iv.next() {
          log_task("reindex", &m);
        }
        match res {
          // ... 原来的日志

TaskMetrics 没有「最长一次 poll」这个字段,所以把慢 poll 阈值设成判定线 10ms:慢 poll 的次数和总时长就回答了「有几次超线、合计多长」。

采样任务

另起一个任务,每秒对三个请求 monitor 各取一次 intervals(),对运行时取一次稳定字段,用 tracing::info! 打一行(log_task 只是把 TaskMetrics 的字段原样打出来):

pub fn spawn_reporter(period: Duration) {
  let runtime = RuntimeMonitor::new(&tokio::runtime::Handle::current());
  tokio::spawn(async move {
    let mut ssr = SSR.intervals();
    let mut api = API.intervals();
    let mut stat = STATIC.intervals();
    let mut rt = runtime.intervals();
    // 任务那边第一次 next() 返回累计值,先空取一次对齐起点
    let _ = (ssr.next(), api.next(), stat.next());
    loop {
      tokio::time::sleep(period).await;
      for (kind, it) in [("ssr", &mut ssr), ("api", &mut api), ("static", &mut stat)] {
        if let Some(m) = it.next() {
          log_task(kind, &m);
        }
      }
      if let Some(r) = rt.next() {
        tracing::info!(
          target: "exp_metrics",
          kind = "runtime",
          workers = r.workers_count,
          busy_ratio = r.busy_ratio(),
          busy_per_worker = r.busy_ratio() / r.workers_count as f64,
          max_busy_ms = r.max_busy_duration.as_millis() as u64,
          total_park = r.total_park_count,
          min_park = r.min_park_count,
          global_queue_depth = r.global_queue_depth,
          elapsed_ms = r.elapsed.as_millis() as u64,
          "runtime interval"
        );
      }
    }
  });
}

一个 monitor 只开一个 intervals(),否则区间最大空闲会被抢走(数字看起来不对)。不接 Prometheus,本站没有。

搜索重建:几乎全部时间都在两次 poll 里

26 次重建按类型归总(slow 指不短于 10ms 的 poll):

类型worker 数次数墙钟时间poll 次数slow 次数slow 合计占墙钟
空目录首次构建(约 1 700 篇)1212 480ms19399.3%
没有改动的增量(只重写 21 篇动态来源),不压测126532–711ms6–10298.5–99.3%
没有改动的增量,压测中129622–1 142ms5–9299.0–99.5%
全量重写(约 1 700 篇),压测中1241 678–2 245ms5–8299.6–99.8%
没有改动的增量(1 次不压测)24947–1 512ms7–11299.4%
全量重写,压测中221 791–1 852ms9299.7%

除首次构建外,每一轮都是 2 次慢 poll 占掉 98.5% 以上的墙钟时间,其余几次 poll 都很短,空闲(等数据库)合计只有 3–9ms,排队均值都在 30µs 以内。两次慢 poll 各多长,TaskMetrics 只给合计,所以只能说最长一次至少是合计的一半:没有改动的增量至少 265ms,全量重写至少 840ms。

为什么是两次,看 reindex_incremental 里 .await 的位置(engine.rs 第 511–540 行):

pub async fn reindex_incremental() -> Result<IncrementalReport, String> {
  // ...
  let file_docs = collect_file_documents();            // 同步:读全部 markdown
  let dyn_docs = collect_dyn_documents().await;        // 等数据库:论坛主题、论文
  // ...
  let diff = diff_for_reindex(&prev, file_docs, dyn_docs);
  // ...
  engine.upsert_documents(&diff.upserts)?;             // 同步:写索引、commit、等合并
  engine.delete_documents(&diff.deletes)?;
  diff.next.save(&engine.dir)?;
  // ...
}

第一次 .await 之前,collect_file_documents 同步读完全部文件;最后一次 .await 之后,upsert_documents 建 writer、写入、commit,再在 commit_and_reload 里 wait_merging_threads() 等后台合并做完。这两段之间的 poll 是数据库查询的往返,都很短。这是按代码结构推断的对应关系,没有逐段计时。「没有改动」也要 0.5 秒以上,是因为文件来源要先读一遍才知道 mtime 有没有变、动态来源每次都全量重写。

所以规划里的第一个问题,答案是:不是一次 poll 做完,但几乎是两次 poll 做完;最长一次远超 10ms。

重建时 SSR 请求被拖慢了吗

把每个 1 秒区间按「和某次重建的时间窗有没有重叠」分成两组。排队均值按排队次数加权,long_delay_ratio 是区间合计的长排队数 ÷ 排队数(阈值默认 50µs):

worker 数轮次分组区间数排队均值每秒最大的排队均值long_delay_ratio每秒最大的 ratio
12第 1 轮重建期间969µs260µs0.1680.418
12第 1 轮其他7152µs391µs0.1390.536
12第 2 轮重建期间1569µs167µs0.1980.403
12第 2 轮其他8571µs373µs0.2160.570
2第 3 轮重建期间12111µs325µs0.2990.575
2第 3 轮其他88116µs1 992µs0.2510.734

ApacheBench 用 -g 记下了每个 SSR 请求的开始时刻和总耗时,同样按秒分组:

worker 数分组请求数p50p90p99最大
12重建期间4 35613ms17ms34ms68ms
12其他38 41013ms18ms33ms136ms
2重建期间5 39713ms17ms26ms96ms
2其他36 98913ms18ms43ms236ms

(第 1 轮用 -g 之前跑的,没有逐请求数据。)三轮的吞吐:SSR 每秒 420–480 个,API 860–1 030 个,静态文件 3 700–4 100 个。

看不出差别。 重建期间的排队均值和长排队比例,有的比其他时段高一点,有的低一点;每秒的最大值反而都出现在没有重建的时候。请求延迟的 p50、p90 完全一样,p99 和最大值也没有偏向重建期间。连只有 2 个 worker、重建时其中一个被占住近 2 秒的那一轮也是如此。50µs 的长排队阈值对这台同时跑着压测程序的笔记本太低,背景的 long_delay_ratio 就有 0.1–0.3,但这不影响两组之间的比较。

为什么没拖慢:渲染不在主运行时上

SSR monitor 的数字本身给了线索:每个 SSR 请求只有 2 次 poll,平均每次 15–20µs。渲染一个 200KB 的首页不可能只要 30µs。原因在 dioxus 0.7.9 的服务端:FullstackState 构造时建了一个 tokio-util 的 LocalPoolHandle,线程数等于核数,每个线程跑自己的单线程运行时;SSR 渲染和服务端函数都 spawn_pinned 到这个池子里(为了支持 !Send 的 future),主运行时上的请求任务只是在等一个 oneshot。

于是:

  • 主运行时上每个请求只做连接、解析、几层中间件和压缩,单次 poll 十几微秒。重建占住一个 worker 时,剩下的 worker 处理这点工作绰绰有余:2 个 worker 那一轮,平时每个 worker 的忙碌比例约 0.27。
  • 渲染完成时,LocalPool 的线程去唤醒主运行时上的请求任务。这是从运行时外面唤醒,任务进注入队列,任何一个空闲的 worker 都能取走(tokio 卷注入队列),不会排在被占住的那个 worker 的本地队列后面。被占住的 worker 本地队列里原有的任务,也会被其他 worker 偷走(窃取与空闲)。
  • /api/search/query 的 tantivy 查询同样跑在 LocalPool 上;重建自己的合并线程是 tantivy 另起的。它们和渲染线程争的是 CPU 核,不是 tokio 的 worker,SSR monitor 量不到,但请求延迟能反映,上表里没有看到。

判定

规划写的判定是「重建任务的最长 poll 超过 10ms,且同期 SSR 的 long_delay_ratio 比空闲时明显升高,就该把重建挪进 spawn_blocking」。前一半成立,后一半不成立,所以在 ceffc19 这个版本下不需要挪:重建在一个 worker 上同步跑 0.5–2.2 秒,每 10 分钟一次,量不出对请求的影响。

这个结论依赖三件当前为真的事:索引约 1 700 篇;dioxus 把渲染和服务端函数放在 LocalPool 上;主运行时上每个请求的工作只有几十微秒。任何一件变了都该重测:

  • 线上日志里 search: incremental reindex applied 那一行的 elapsed_ms 超过 5 000。上表说明它几乎等于两次慢 poll 之和,就是一个 worker 被占住的时长。
  • 索引文档数涨一个数量级(约 17 000 篇)。
  • 升级 dioxus 后,再跑一次本页的中间件:SSR 每个请求的 poll 次数和平均 poll 时长明显变大,说明渲染回到了主运行时上。

真要挪的时候,不能把整个 reindex_incremental 丢进 spawn_blocking(它中间要 .await 数据库)。按上面两次慢 poll 的位置,把 collect_file_documents 和「写索引到存 manifest」这两段分别放进 spawn_blocking 就够了(tokio 卷在 async 里阻塞、阻塞线程池)。

运行时:只用稳定字段能看到什么

12 个 worker 压测时,busy_ratio 稳定在 0.79–0.89,除以 worker 数约 0.07;global_queue_depth 是采样那一刻的注入队列长度,只在 0–3 之间。重建结束的那个 1 秒区间,busy_ratio 跳到 1.1–2.1,max_busy_duration 到了 1 312ms,比区间本身还长,是计数提交滞后的样子:被占住的 worker 在 poll 结束、park 之前才把这段忙碌一次提交(Worker 差分与 poll 时间直方图)。

2 个 worker 那一轮更清楚,一次 1.8 秒的全量重写前后:

13:54:19.946 runtime busy=0.53 per_worker=0.267 max_busy=280ms  park=38265 min_park=18621
13:54:20.948 runtime busy=0.88 per_worker=0.441 max_busy=452ms  park=20075 min_park=103
13:54:21.949 runtime busy=1.77 per_worker=0.885 max_busy=1403ms park=23753 min_park=5230
13:54:22.950 runtime busy=0.53 per_worker=0.266 max_busy=267ms  park=41480 min_park=20523

min_park_count 从近 2 万掉到 103:被占住的那个 worker 几乎没有 park。这是一个不需要 tokio_unstable 就能看到的「有 worker 卡住了」的信号,比 busy_ratio 来得早(busy 要等 poll 结束才提交,park 次数少是当场就少)。它只在所有 worker 都在干活时有用:12 个 worker、负载不高时,总有 worker 整个区间都在睡,min_park_count 一直是 0。

papers 流水线:实测不了的部分和复现

papers_ingest 是独立的 #[tokio::main] 进程,服务器 cron 每天跑一次。按规划包住每天的 run_day 和每篇的 generate_one:

  // 实验:一天一个 future,聚合进同一个 monitor,结束时打一次累计值
  let day_monitor = tokio_metrics::TaskMonitor::new();
  for date in args.dates {
    match day_monitor.instrument(run_day(&db, date, &source, generator.as_ref())).await {
      // ...
    // 实验:每篇一个 future,聚合进同一个 monitor
    let outcome = generate_monitor().instrument(generate_one(db, g, p, &mut usage)).await;

这份改动编译通过,但没有真的跑:一次完整的运行要访问 Hugging Face 的列表接口、arXiv 的全文页面和大模型接口,还会往数据库里写论文和解读,这些在本次实验的条件下都做不了。退而求其次,用框架里真实的两个解析函数(hf::parse_daily、fulltext::parse)加合成的输入,按 run_day 的顺序复现一天:取列表(等 300ms)→ 解析 100 篇的列表 → 入库(等 20ms)→ 生成 3 篇,每篇之间等 ARXIV_INTERVAL 3 秒,下载全文等 500ms、解析全文、英文解读和中文翻译各等 2 秒、写库等 20ms。合成的全文是 LaTeXML 风格的 HTML(节、子节、带 MathML 公式的段落),1MB 和 4MB 两种;真实 arXiv 页面多大没有核实。模型调用按 2 秒算,源码注释里说长论文实测接近 30 秒。

连跑 3 次:

parse 1MB html: 17.226666ms (80 sections, 674748 bytes text)
parse 4MB html: 63.03075ms (320 sections, 2699196 bytes text)
parse_daily: 100 papers, 193681 bytes json, 720.958µs
day: wall=20.04920475s polls=17 slow=4 poll=127.1335ms idle=19.921754835s scheduled=207.874µs

另外两次:解析 1MB 18.9ms、20.2ms,4MB 65.2ms、66.1ms;一天的 poll 合计 122ms、139ms,空闲都是 19.92s。

  • 预期大体成立:20 秒里 poll 只占 0.6%,其余都是空闲。换成真实的 30 秒模型调用、每天 20 篇,这个比例只会更小。
  • 「唯一的同步 IO 是 read_to_string」这条前提不对:fulltext::parse 先用 scraper 把整页解析成 DOM 再遍历,是一段同步计算,合成的 4MB 页面要 60 多毫秒,slow=4 里有 3 次就是它(另一次是 parse_daily 所在的那次 poll,阈值 50µs)。
  • 它现在无害:papers-ingest 是单独的进程,运行时上没有别的任务要等。如果哪天这段代码搬进 app 进程(比如后台加一个「重新生成」按钮),一次解析就会占住主运行时的一个 worker 几十毫秒,那时再用本页的中间件量一次,或者直接放进 spawn_blocking。

打开 tokio_unstable 要付什么

上面四项实测都没用到不稳定字段。规划里需要它的只有 poll 次数、窃取、阻塞池这几类字段,下面把打开它的代价逐项核实,结论放在最后。

怎么传进去。 本站的 .cargo/config.toml 只设了 target-dir,Dockerfile 用 CARGO_TARGET_DIR 覆盖它,没有设 RUSTFLAGS。所以在配置文件里加 rustflags 是可行的;但只要将来哪一步设了 RUSTFLAGS,哪怕是空串,配置文件里的就整个作废(E0609 那一页的表)。

dx 怎么分给服务器和 wasm。 线上镜像用 dx bundle --platform web --release 同时编服务器和 wasm 客户端。dioxus-cli 0.7.9 不是让 cargo 自己去读配置文件,而是自己先算一遍 rustflags:读 RUSTFLAGS 环境变量,再读配置文件里这个目标三元组的 rustflags;然后如果非空,就以 RUSTFLAGS 环境变量传给 cargo。web 客户端那次构建还会额外加上 --cfg getrandom_backend="wasm_js"。用一个最小的 dioxus 全栈程序验证(它按是否带 tokio_unstable 在页面里放两个不同的字符串,构建后在服务器二进制和 wasm 里找),dx build --platform web:

.cargo/config.toml服务器二进制wasm 客户端dx 给 cargo 的 RUSTFLAGS
[target.aarch64-apple-darwin] rustflags = ["--cfg", "tokio_unstable"]ONOFF服务器 --cfg tokio_unstable;wasm 只有 getrandom_backend
[build] rustflags = ["--cfg", "tokio_unstable"]ONONwasm 是 --cfg tokio_unstable --cfg getrandom_backend="wasm_js"

[build] 一节会同时进 wasm:dx 读配置用的 cargo-config2 在没有 [target.<三元组>] 时退回到 [build]。所以要限定在服务器上,必须写在服务器那个三元组的 [target] 下。线上镜像的三元组取决于构建机的架构,本页没有核实;本地验证用的是 aarch64-apple-darwin。只跑了 dx build(debug),没有跑 dx bundle;按源码,bundle 也是经同一个 into_targets 构造 BuildRequest,走同一段 rustflags 逻辑。

全量重编,缓存里多一份。 rustflags 是 cargo 指纹的一部分。cargo 1.99.0 下用本卷常见坑里的小程序(33 个包)试:不带 cfg 编一次,带 cfg 再编,33 个包全部重编;再切回不带 cfg,0 个重编,两套产物在 target 目录里并存。对本站的 Docker 构建,这意味着打开 cfg 后的第一次构建要把整个依赖树重编一遍,并且 rie-target 缓存挂载 里会同时留着新旧两套产物,直到旧的被清掉。那段 Dockerfile 的注释记着,构建缓存曾经把 app 服务器的盘写满。本站完整依赖树多出的一套产物有多大,没有实测。

运行时行为和 semver。 只打开 cfg 不改调度策略,但 tokio 在每次 poll 和 park 时会多记几项计数,具体多做什么见稳定与不稳定两层字段的「打开 tokio_unstable,tokio 每次 poll 多做什么」。更大的代价是从此依赖 tokio 不承诺 semver 的 API:升级 tokio 小版本时,这些方法可能改名或消失,本站和 tokio-metrics 都可能编译不过。

结论:生产不开。 本页四个问题用任务指标和 10 个稳定字段都答上了;真要看窃取次数或 poll 时间直方图,在本地分支上带 cfg 构建一次,量完就丢,和本页的做法一样。

网关 crates/gateway 有自己的 Cargo.lock 和 tokio 版本约束,不在本页范围内。

小结

  • app 一侧的实验代码约 115 行:一个按路径分三个 TaskMonitor 的 from_fn 中间件、一个包住重建的 monitor、一个每秒打日志的采样任务,外加 papers 的两处 instrument。
  • 搜索重建 26 次:除首次构建外每次都是 2 次慢 poll 占 98.5% 以上的墙钟时间,没有改动时 0.5–1.5 秒,全量重写 1.7–2.2 秒,最长一次 poll 至少数百毫秒。
  • 同时段 SSR 的排队均值、长排队比例和请求延迟都看不出变化,12 个和 2 个 worker 都一样:dioxus 把渲染和服务端函数放在自己的 LocalPool 线程上,主运行时上每个请求只有两次十几微秒的 poll。
  • 判定:ceffc19 下不需要 spawn_blocking;elapsed_ms 超过 5 000、文档数到 17 000、或 dioxus 升级后 SSR 的 poll 变长时重测。
  • 稳定字段里,min_park_count 骤降是「有 worker 卡住」的即时信号;busy 要等 poll 结束才提交。
  • papers:用真实解析函数复现,一天里 poll 只占 0.6%;但解析 arXiv 全文是几十毫秒的同步计算,现在因为是独立进程才无害。
  • tokio_unstable:RUSTFLAGS 会覆盖配置文件;dx 只把 [target.<三元组>] 的 rustflags 限定给对应目标,[build] 会进 wasm;打开后全量重编、缓存多一份;生产不开。

💬 关联讨论

发起讨论
加载中...