Rust in Everything
基于 tracing 0.1.44

取舍汇总

主线位置:两条主线的总账。前三条决定事件主线上那几道门的形状(门开在哪、每道门读什么、答案缓存在哪),后四条决定 span 主线归谁管(span 的数据存在哪、谁来组合、装在哪里、怎么进出)。
flowchart TB
  d1[核心单独成 crate] --> c1[兼容约束塑造代码]
  d2[元数据在编译期] --> c2[字段名不能动态]
  d3[Interest 与 MAX_LEVEL] --> c3[配置变了要重建]
  c3 --> f3["reload 替你重建"]
  d4[span 数据归 subscriber] --> c4[功能都要 Registry]
  d5[Registry 加 Layer] --> c5[类型长且固定]
  c5 --> f5["reload、Option、Vec"]
  d6[全局默认只设一次] --> c6[测试与框架抢着设]
  c6 --> f6["set_default 线程默认"]
  d7[enter 用守卫] --> c7[跨 await 会错]
  c7 --> f7[Instrument]

每一节的格式和 axum 卷、hyper 卷 的同名页相同:做了什么决定,换来了什么,代价是什么,代价由谁来补。机制都在别的页讲过,这里只给结论和链接;引到的数字都来自那些页的实验,平台都是 M2 Max、rustc 1.99.0。

核心单独成 crate,一直停在 0.1

决定:Metadata、Callsite、Subscriber、Dispatch、字段这些类型,以及全局调用点表 CALLSITES 和全局 dispatcher GLOBAL_DISPATCH,都放在 tracing-core 里;宏、Span 的便利方法、Instrument 放在 tracing 里,用 pub use 把核心类型原样转出去。tracing-core 的文档说它的 API「will change very infrequently」,从 2019 年的 0.1.0 到 0.1.36 一直没有离开 0.1(源码地图)。

换来的:

  • 一个程序里所有打日志的库和 subscriber 共用同一份 static:hyper、tower-http 和你的代码登记进同一张调用点表、交给同一个 dispatcher。Cargo 把不兼容的大版本当成两个 crate,各有一份 static,所以核心必须极少发破坏性版本,这层拆分让门面可以一直加东西而核心不动(源码地图)。
  • 实现 Subscriber 只需要依赖 tracing-core:默认 feature 下的 tracing-subscriber 根本不依赖 tracing,只有开了 env-filter 才拉进来(源码地图 的依赖树)。

代价:

  • 两层 crate,各自发版、各自打 tag。tracing 的 tag tracing-0.1.44 里的 tracing-subscriber 还是 0.3.22,读源码得每个 crate 对着自己的 tag(怎么读这一卷)。
  • 「不能破坏兼容」反过来塑造了代码。几个例子:0.2 分支早就把调用点表换成了侵入式链表,0.1 上照做要给 Callsite trait 加方法,于是 #2083 只能另起一个自带链表节点的 DefaultCallsite,表也就分成「无锁链表 + LOCKED_CALLSITES」两半(Callsite 与 Interest 缓存);Level 的内部数值倒着排、比较全部手写,前提之一是 LevelFilter 必须是 Option<Level>,「历史上就提供了 const fn 转换,改不了」(Metadata、Level 与 LevelFilter);新方法只能带默认实现加进 trait,于是 0.1.28 加的 Box<S> / Arc<S> 的 Subscriber 实现不转发 0.1.30 才有的 on_register_dispatch,编译器也不会提醒(Subscriber trait)。
  • 门面这边同样背着兼容:宏里那行 use $crate::field::{debug, display, Value} 删过两次(#806、#3382),两次都因为下游代码依赖它而撤回,0.1.42 为此被撤下(宏展开 的冷知识)。

谁来补:没有人补,这是有意付的价。tracing 把 tracing::Subscriber 和 tracing_core::Subscriber 做成同一个 trait,用 tracing 写应用的人感觉不到这层拆分。

元数据在编译期:static 的 Metadata 和字段名表

决定:宏在每个调用点放两个互相引用的 static:META 和 __CALLSITE。Metadata 只有一个 const fn new,字段名表 FieldSet 的 names 是 &'static [&'static str](Metadata、Level 与 LevelFilter、字段)。

换来的:

  • 每个 info! 在二进制里对应一份 Metadata 和一份调用点,运行时一次也不构造。调用点有了固定地址,才能在它身上缓存 Interest(下一节);register_callsite 收的是 &'static Metadata<'static>,subscriber 可以按调用点建表。
  • Metadata 的 PartialEq 在 release 构建里只比调用点指针。Field 是「下标 + FieldSet」,subscriber 按名字查一次之后都按下标取。
  • 值不分配:宏构造的 ValueSet 是栈上一排 Option<&dyn Value>。一万条带 6 个字段的事件,tracing 这一侧 0 次分配(字段)。

代价:

  • 字段名必须在宏里写出来:标识符、字符串字面量或 { 常量 }(宏展开),运行时拼出来的名字放不进 &'static [&'static str]。span 的字段也是创建时就定下的,Span::record 一个没声明过的名字会被静默忽略,要后填的得先写成 field::Empty(Span 与 Entered、常见坑:Span::record 没有效果)。
  • 运行时才有的元数据进不来缓存。log 记录的 target、文件、行号都是运行时的值,tracing-log 只好给每个级别造一个固定的假调用点(log_cs! 生成五个),真实的位置塞进 log.* 字段,再由 NormalizeEvent 还原(和 log 互通)。Metadata<'a> 带生命周期也是为它留的(Metadata、Level 与 LevelFilter)。
  • 代码体积:每个调用点一份静态数据加一段展开。一条 info! 在编译期展开 15 次宏;Values::All(#3398)就是为了缩小生成代码加的,PR 的原话是旧写法「must put a Field on the stack for each field--that's 32 bytes per field!」(宏展开、字段)。

谁来补:field::Empty 加 Span::record 给「先占名、后填值」;#[instrument(fields(x))] 只写名字也是得到 field::Empty(参数)。名字本身动态的数据只能放进值里。

Interest 缓存加一个全局 MAX_LEVEL

决定:每个 DefaultCallsite 用一个 AtomicU8 缓存所有 dispatcher 对它的回答(never / sometimes / always),第一次经过时才问;所有 dispatcher 的 max_level_hint 取最大值,存进全局的 MAX_LEVEL(Callsite 与 Interest 缓存、Metadata、Level 与 LevelFilter)。宏把它们和编译期的 STATIC_MAX_LEVEL 用 && 串成几道门,门不通过时字段表达式不求值。

换来的:级别过滤的几道门 用 criterion 量过同一条 debug! 停在各道门的单次耗时:

停在耗时
门一 STATIC_MAX_LEVEL0(编译期删掉,criterion 报「took zero time」)
门二 LevelFilter::current()约 0.33 ns
门三 Interest 为 never约 0.6 ns
门四 enabled 返回 false约 2.4 ns
门五 event_enabled 返回 false约 4.2 ns

被级别和缓存挡住的日志,开销是一两次 Relaxed 原子读,不找 subscriber、不做虚调用、不求值字段。全局 MAX_LEVEL 本身是为 rustc 加的(#853):批处理程序和命令行工具里,第一次建调用点缓存的成本「has a much bigger impact」(Metadata、Level 与 LevelFilter 的冷知识)。

代价:

  • 配置变了要重建,而且要整表重建。 缓存记的是旧答案:调高级别不重建,新放行的日志过不了门二;调低级别不重建,always 的调用点连 enabled 都不问(reload)。rebuild_interest_cache 要对每个调用点把每个 dispatcher 的 register_callsite 问一遍,代价和调用点数量成正比(Callsite 与 Interest 缓存)。
  • 重建的时机不全。 新建 Dispatch 和手动调用时会重建;drop 一个 Dispatch 不会,MAX_LEVEL 和缓存都停在它活着时的值,给 DefaultGuard 的 drop 加重建的 PR #3530 写作时还没合并。只有一个 dispatcher 时走 JustOne 捷径,按当前线程的默认值注册调用点:那个 dispatcher 只是某个线程的局部默认时,别的线程会给调用点缓存上 never,实测 events = 0(#3611,未修)(Callsite 与 Interest 缓存)。
  • 缓存不住的回答每次都要问。 sometimes 的调用点每次经过都要 get_default 加一次虚调用 enabled。EnvFilter 只要有一条动态指令,其余没被静态放行的调用点全是 sometimes:一条 [req]=debug 让所有 target 上被关掉的 debug! 从约 0.3 ns 变成约 7.2 ns(EnvFilter)。两个 dispatcher 意见不同,合并出来也是 sometimes(#927 起,Callsite 与 Interest 缓存)。
  • 门二只是一个数。 它只能按全程序最详细的那一级一刀切;没给 max_level_hint 的 subscriber 按 TRACE 算,门二就什么都挡不住。reload 在 0.3.15 之前就是这样(#2204),不带过滤、不给提示的普通 layer 至今也会这样(reload 的冷知识、过滤:全局与每层)。

谁来补:reload::Handle::modify 改完自动调用 rebuild_interest_cache(reload);能用级别和 register_callsite 表达的过滤就不要放进 enabled / event_enabled(级别过滤的几道门);用线程默认捕获日志时,先设好全局默认或至少多建一个 Dispatch,避开 JustOne。

span 的数据全交给 subscriber

决定:Span 只有 inner: Option<Inner>(一个 Id 加创建它的那份 Dispatch)和 meta。span 的名字、字段值、父子关系、「当前在哪个 span 里」,tracing 一样也不存;Id 由 Subscriber::new_span 发,唯一性、能不能复用全由 subscriber 决定(Subscriber trait、Span 与 Entered)。

换来的:

  • 被过滤掉的 span 是 inner 为 None,对它的所有操作都是空操作,不调 subscriber(Span 与 Entered)。不关心 span 的 subscriber 可以什么都不存,NoSubscriber 给所有 span 发同一个 0xDEAD。
  • Id 是 NonZeroU64,Option<Id> 仍是 8 字节(span 与 Event 的数据)。
  • 存储方式由 subscriber 自己选。Registry 用 sharded-slab 的池,槽清空时原地 Clear、内存复用(Registry)。

代价:

  • 凡是要「知道 span」的事都得问 subscriber。Span::current() 是 current_span 加 clone_span,默认实现返回 Current::unknown(),subscriber 不跟踪当前 span 时拿到的是 Span::none()(Span 与 Entered);Current 父 span 不带 Id,由 subscriber 查自己的当前 span 来解析(span 与 Event 的数据)。
  • tracing-subscriber 里要用 span 数据的功能都绑在 Registry 上:Registry 发 Id、存元数据和父子关系、记每个线程的 span 栈;fmt 把格式化好的字段存进它的 Extensions;Layered::try_close 要先把内层 downcast 成 Registry 拿 CloseGuard;每层过滤的 FilterId 只有 Registry 能分配(Registry、Subscriber trait、过滤:全局与每层)。
  • Id 只是「这一刻在这个 subscriber 里唯一」:Registry 复用槽时代数加一,第二个 span 拿到 2⁵¹ + 1 这样的数,不能当请求 id 用(一条日志穿过 tracing、Registry)。
  • 引用计数也在 subscriber 里:clone_span / try_close 的默认实现不计数,try_close 永远返回 false(Subscriber trait)。

谁来补:tracing-subscriber 的 Registry 把这些公共部分做了一次,Layer 通过 Context → LookupSpan → SpanRef 读(Registry)。自己写 Subscriber 而不是 Layer,这些都要自己实现。

一个 Registry 加多个 Layer,靠类型嵌套

决定:Id 必须有唯一的来源,所以同一时刻一个线程只能有一个 Subscriber;能叠加的观察部分拆成 Layer(Layer 与 Layered)。Layered<L, I> 把一层套在另一层外面,fmt().with_env_filter("info") 搭出来的是 Layered<EnvFilter, Layered<fmt::Layer<Registry>, Registry>>(一条日志穿过 tracing)。

换来的:

  • 存 span、过滤、输出分开写再拼起来。判断方法由外到内问、遇到「不要」就短路;通知方法先内层后本层(Layer 与 Layered)。
  • 组合在类型上,调用是静态分派。fmt::Layer<S, N, E, W> 的字段格式器、事件格式器、writer 都是类型参数,on_event 里调 format_event 可以内联(fmt)。

代价:

  • 类型名长,而且装好以后就固定了。.compact()、.pretty()、.with_writer() 每调一次换一个类型;装上之后换不了格式(fmt)。reload 只能换成同一个类型 L 的值(reload)。
  • 想在运行时决定有几层、是哪种层,就要回到类型擦除:Option<L>、Vec<L>(通常是 Vec<Box<dyn Layer>>),它们各有各的合并规则,过滤器放进 Vec 效果是「或」,而且 Option 和 Vec 不转发 on_register_dispatch(Layer 与 Layered)。reload 包 Box<dyn Layer> 能换任意 layer,但换进来的 layer 没见过已有的 span,读 Extensions 时可能 panic(reload)。
  • 一层的选择影响所有层。.with(filter) 是全局过滤,所有层都看不到被它挡掉的东西;要「文件记 debug、终端记 info」得用每层过滤 with_filter,它最多 64 个,第 65 个 panic「filter IDs may not be greater than 64」,而且只能在全局放行的范围内收窄(过滤:全局与每层、常见坑:过滤器管住了所有层)。不带过滤、不给 max_level_hint 的普通层会让门二失效。
  • 一层没法拦下另一层:on_event 没有返回值,内层的 on_event 跑完 Layered 无条件调外层;要拦只能在 enabled / event_enabled 里(Layer 与 Layered)。

谁来补:reload 换同类型的值;Option / Vec / Box<dyn Layer> 换运行时的灵活性;with_filter 给每层自己的过滤。

全局默认只能设一次

决定:set_global_default 用 GLOBAL_INIT 的一次 compare_exchange 做一次性初始化,成功时用 Arc::into_raw 把 subscriber 有意泄漏成 &'static,第二次调用返回 SetGlobalDefaultError(Dispatch:全局与线程局部)。这和 log 的「The logging system may only be initialized once」是同一个选择(tracing 解决什么问题)。

换来的:

  • 全局默认是 Kind::Global(&'static ..),克隆它只复制一个胖指针,不碰引用计数。
  • get_default 的快路径:进程里没有活着的 DefaultGuard 时,两次原子读就拿到全局默认,不碰线程局部。#2593 换成这种结构时,PR 里的基准是全局默认下 Dispatch::get_ref 快了约 52%、线程默认下 get_clone 慢了约 53%,理由是「a global default dispatcher is the common case for most users」(Dispatch:全局与线程局部 的冷知识)。

代价:

  • 谁先设谁赢。每个测试都 init 会 panic,框架先装了一个,你的 try_init 就只能失败(常见坑:init 两次、常见坑:测试里的日志;本站的情况见 在本站中:subscriber 初始化)。try_init 失败的原因还可能不是 tracing 这边,而是 log 的 logger 已被占用,这时 subscriber 其实已经装上了(fmt、和 log 互通)。
  • 泄漏出来的全局 subscriber 永远不会被释放。
  • 快路径不过 can_enter 检查:全局 subscriber 在自己的 event 里再打 tracing 日志,会一层套一层递归,直到栈溢出;同样的代码装成线程默认时,内层日志被交给 NONE 丢掉(Dispatch:全局与线程局部)。

谁来补:set_default / with_default 给线程局部的默认值,用守卫恢复。它也有价:任何一个线程持有守卫,SCOPED_COUNT 不为 0,所有线程都走慢路径;它只对当前线程有效,let _ = set_default(..) 当场就 drop(Dispatch:全局与线程局部、常见坑:一条日志都没有);要把 dispatcher 带进别的任务用 WithDispatch(Instrument 与异步)。

enter 用守卫,退出在 Drop 里

决定:span.enter() 返回借用 span 的 Entered,span.entered() 返回拥有 span 的 EnteredSpan;exit 在守卫的 Drop 里调用(Span 与 Entered)。

换来的:同步代码里 span 和词法作用域对齐,不会忘了退出;源码注释给的理由是「spans may still be exited when unwinding」,panic 展开时也能退出。

代价:

  • 异步代码里,守卫跨 .await 时作用域退出了、守卫却没 drop,下一个被 poll 的任务继承这个 span。实测:后建的 span 被记成前一个 span 的子 span,没有 span 的旁观任务的日志被挂到两个无关的 span 下(Instrument 与异步)。
  • 编译器只拦一半:EnteredSpan 靠 PhantomNotSend 不是 Send,放进 tokio::spawn 编译不过;Entered 是 Send 的,能编译(Span 与 Entered)。clippy 0.1.99 没有 await_holding_span_guard,要在 clippy.toml 里给 await_holding_invalid_type 列出这两个类型(Instrument 与异步、常见坑:跨 await 持有 enter)。

谁来补:Instrumented<F>:每次 poll 前进入、返回时退出,守卫只活一次 poll,永远不跨 .await(Instrument 与异步)。它也有成本:#[instrument] 加在 async fn 上、span 被关掉时,每次调用仍比不加属性多约 5.7 ns,future 从 16 字节变成 120 字节;同步函数只多约 0.4 ns(展开成什么)。

小结

  • tracing-core 单独成 crate、一直是 0.1,所有库共用同一份全局表;代价是两套版本号,以及「不能破坏兼容」在代码里留下的许多绕路。
  • 元数据和字段名在编译期写死,事件不分配、调用点有固定地址;代价是字段名不能动态,log 记录只能借假调用点进来。
  • 每个调用点缓存一个 Interest、全局缓存一个 MAX_LEVEL,被挡住的日志约 0.3–0.6 ns;代价是配置变了要整表重建,drop 不触发重建,sometimes 每次都要问,一条动态指令就把所有 target 的关掉的 debug! 拉到约 7 ns。
  • span 的数据全归 subscriber,没 subscriber 时 span 什么都不做;代价是「当前 span」、父子关系、计数都要 subscriber 实现,tracing-subscriber 里要用 span 数据的功能都绑在 Registry 上。
  • Registry 加 Layer 靠类型嵌套,静态分派;代价是类型长、装好就固定,运行时的灵活性要靠 reload、Option、Vec、Box<dyn Layer> 换回来。
  • 全局默认只能设一次,换来不碰线程局部的快路径;代价是测试和框架抢着设,全局 subscriber 里打日志会无限递归。
  • enter 用守卫退出,同步代码里正确;跨 .await 就错,靠 Instrument 补。

💬 关联讨论

发起讨论
加载中...