取舍汇总
主线位置:两条主线的总账。前三条决定事件主线上那几道门的形状(门开在哪、每道门读什么、答案缓存在哪),后四条决定 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 上照做要给
Callsitetrait 加方法,于是 #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 aFieldon 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_LEVEL | 0(编译期删掉,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补。