Miri 追踪（Tracing）基础设施与 Perfetto 性能剖析实战指南

Miri 追踪Tracing基础设施与 Perfetto 性能剖析实战指南【免费下载链接】miriAn interpreter for Rusts mid-level intermediate representation项目地址: https://gitcode.com/GitHub_Trending/mi/miri导读Miri 是 Rust 中间层中间表示MIR的解释器其内部包含借用检查器borrow tracker、数据竞争检查器data race checker、布局计算layouting等多个耗时组件。为了量化各组件的时间开销Miri 在仓库中内置了一套完整的 tracing 基础设施见 doc/tracing.md通过一个tracingfeature 与MIRI_TRACING环境变量可以让解释器在运行时把所有事件与 span 写入一份 JSON 格式的 trace 文件再交给 Google 出品的 Perfetto 进行可视化与 SQL 分析。读完本文你将掌握如何编译开启追踪的 Miri、如何生成与解读 trace 文件、如何用 Perfetto 的 SQL 计算各组件耗时占比以及如何在自己的代码路径中插入新的追踪 span。[!WARNING] 需要提前说明截至本文档撰写时Miri 的 tracing 功能因两个上游追踪库的 bug 暂时无法正常工作分别位于 tokio-rs/tracing 的 PR #3392 与 davidbarsky/tracing-tree 的 issue #93Miri 侧跟踪见 rust-lang/miri issue #4752。下文的内容以仓库当前实现为准待上游修复后即可按原样使用。追踪基础设施概览Miri 与rustc_const_eval高度耦合其 trace 数据既来自 Miri 自身的代码也来自rustc_const_eval的代码。所有追踪调用都经过两个入口宏enter_trace_span!()在 Miri 侧定义于 src/helpers.rs它会把调用转发给rustc_const_eval::enter_trace_span!并以MiriMachine作为第一个参数Machinetrait 上的方法enter_trace_span在 src/machine.rs 中实现当tracingfeature 开启时返回span().entered()否则返回()从而让编译器在禁用时把追踪调用整体优化掉。整个追踪链路的输出端是tracingcrate 的Layer机制Miri 使用tracing_chrome层把 span/event 序列化为 Perfetto 可读的 JSON。日志初始化与追踪层装配位于 src/bin/log/setup.rs该文件同时负责处理MIRI_TRACING与MIRI_LOG/RUSTC_LOG环境变量。获取 trace 文件从 Miri 代码库构建所有追踪功能都由tracingfeature 门控见 Cargo.toml确保不需要时零开销。编译时向./miri脚本传入--featurestracing运行时再设置MIRI_TRACING环境变量例如MIRI_TRACING1 ./miri run --featurestracing ./tests/pass/hello.rs这里的./tests/pass/hello.rs是 Miri 自带的通过类测试用例也可以替换为任意其他测试或程序。从 rustc 代码库构建如果你在 rustc 源码树内构建 Miri需要在bootstrap.toml中启用该 featurebuild.tool.miri.features [tracing]然后运行MIRI_TRACING1 ./x.py run miri --stage 1 --args ./src/tools/miri/tests/pass/hello.rs环境变量的底层处理MIRI_TRACING的实际处理位于 src/bin/log/setup.rsinit_logger_once检查该环境变量是否存在若存在但 Miri 未以tracingfeature 编译会直接触发fatal_error!提示必须先以 tracing feature 构建若存在且 feature 已开启则通过ChromeLayerBuilder::new().include_args(true).build()构建tracing_chrome层并经由rustc_driver::init_logger_with_additional_layer注册为全局 logger 的额外层。这意味着 trace 数据与调试日志MIRI_LOG/RUSTC_LOG共用同一条收集管线。trace 文件运行结束后会在当前目录生成一个.json文件其中包含整个执行过程中发生的全部事件events与 span格式遵循 Chrome Trace Format该格式也被 Perfetto 原生支持。需要特别注意的是tracing_chrome层会启动一个后台线程负责写文件若程序非正常退出例如通过std::process::exit直接终止JSON 数组可能缺少结尾的]导致文件损坏。因此 Miri 在 src/bin/log/setup.rs 提供了deinit_loggers()用于在退出前显式 DropTracingGuard以正确收尾文件。用 Perfetto 分析 trace 文件Perfetto 是 Google 出品的 trace 分析器最初来自 Chrome 浏览器项目。打开 Perfetto 在线界面把.json文件拖入窗口即可开始分析。时间线视图工作区左侧会出现 Global Legacy Events 与 Process 1 两个条目点击后时间线展开可缩放查看单个 span彩色盒子与事件瞬间小箭头Process 1包含 Miri 各组件的追踪 span全部挤在同一条时间线上如借用检查器、数据竞争检查器等Global Legacy Events包含两条辅助时间线用于理解任意时刻解释器正在执行什么frame被解释程序当前所处的栈帧step被解释程序 MIR 中正在执行的 statement/terminator。事件之所以存在是因为 rustc 与 Miri 也使用tracingcrate 做调试日志这些日志在 trace 中便呈现为事件。查看 span/event 的详细数据点击任意 span 或事件可查看其携带的参数。例如下面的截图展示了一个layoutingspan 的详情它由 Miri 代码中的这行调用生成let _trace enter_trace_span!(M, layouting::fn_abi_of_instance, ?instance, ?extra_args);SQL 表结构Perfetto 把 span/event 数据库暴露为 SQL 表在顶部搜索栏输入:即可进入 SQL 模式。相关表有两个slices所有 span 与事件。事件与 span 的区别在于dur是否为 0。关键列idPerfetto 为 span 分配的全局唯一主键trace 文件本身不含该列ts/durspan 起始时刻与持续时间单位纳秒namespan 名称parent_id父 span 的 ID无父则为 null由 Perfetto 根据时间关系推断即嵌套 span 互为父子arg_set_id指向参数表的外键一对多。args各 span/event 的参数。关键列arg_set_id与slices表连接的键key参数名统一带有args.前缀display_value参数值。增强时间线显示 span 的 subnameProcess 1 中存在大量同名 span它们其实来自 Miri 中不同的调用点例如数据竞争检查器的多个函数。span 名只体现组件名具体函数名被存进同名参数subname里平时只有点击 span 才能看到。为快速查看 subname可以新增一条时间线选中一个你关心的 span称其名为$NAME点击参数$NAME或args.$NAME旁边高亮的蓝色下拉框选择 Visualize argument values一条新的时间线出现其中只保留原名$NAME的 span但显示名被替换为 subname。下图演示了针对名为data_race的 span 执行上述 4 步后的效果可视化正在执行的 frame / step上述方法对 Process 1 下的 span 有效但对 Global Legacy Events 下的 span 会失效可能是 Perfetto 的 bug。可以改用 SQL 方案在顶部搜索栏输入:进入 SQL 模式执行下面的查询把末尾的SPAN_NAME替换为frame或stepselect slices.id, ts, dur, track_id, category, args.string_value as name, depth, stack_id, parent_stack_id, parent_id, slices.arg_set_id, thread_ts, thread_instruction_count, thread_instruction_delta, cat, slice_id from slices inner join args using (arg_set_id) where args.key args. || name and name SPAN_NAME在底部结果框右上角点击 Show debug track在弹出的窗口中点击 Show一条新 debug track 出现显示各 step 或 frame 的具体名称。该查询的原理是只选出名为SPAN_NAME的 span其余字段保持不变仅把name替换为 subname回想 subname 存在与 span 同名的参数中。快速聚合统计最简单的统计方式沿时间线按住拖拽选中一个时间段然后在底部打开 Current Selection 页签通过 Slices、Pivot Table 或 Slice Flamegraph 查看各 span 的耗时分布。[!NOTE] Slices 与 Pivot Table 展示的数字包含嵌套子 span因此不能直接用来回答X% 的时间花在名为 Y 的 span 上——两个同名 span 可能互相嵌套导致时长被重复计算。这类统计请使用下一节的增强版 SQL。增强版聚合统计下面这条较长但不复杂的 SQL 可按 span 名分组统计耗时。它只统计没有父 span的顶层 span见where parent_id is null例如validate_operand内部调用了layouting并生成子 span那么只有validate_operand的统计会增加。查询同时排除了辅助 spanname ! frame and name ! step。注意该查询默认覆盖整个 trace如需限定时间范围可追加条件例如ts dur MIN_T and ts MAX_T会匹配与区间(MIN_T, MAX_T)相交的 span时间单位为纳秒。select TOTAL PROGRAM DURATION as name, count(*), max(ts dur) as sum(dur), 100.0 as %, null as min(dur), null as max(dur), null as avg(dur), null as stddev(dur) from slices union select TOTAL OVER ALL SPANS (excluding events) as name, count(*), sum(dur), cast(cast(sum(dur) as float) / (select max(ts dur) from slices) * 1000 as int) / 10.0 as %, min(dur), max(dur), cast(avg(dur) as int) as avg(dur), cast(sqrt(avg(dur*dur)-avg(dur)*avg(dur)) as int) as stddev(dur) from slices where parent_id is null and name ! frame and name ! step and dur 0 union select name, count(*), sum(dur), cast(cast(sum(dur) as float) / (select max(ts dur) from slices) * 1000 as int) / 10.0 as %, min(dur), max(dur), cast(avg(dur) as int) as avg(dur), cast(sqrt(avg(dur*dur)-avg(dur)*avg(dur)) as int) as stddev(dur) from slices where parent_id is null and name ! frame and name ! step group by name order by sum(dur) desc, count(*) desc执行后得到类似下表的输出针对某个 span 的 subname 统计把下面的 SQL 中的SPAN_NAME换成目标 span 名即可看到同名 span 各 subname 的统计计数、总时长、最小/最大/平均时长与标准差select args.string_value as name, count(*), sum(dur), min(dur), max(dur), cast(avg(dur) as int) as avg(dur), cast(sqrt(avg(dur*dur)-avg(dur)*avg(dur)) as int) as stddev(dur) from slices inner join args using (arg_set_id) where args.key args. || name and name SPAN_NAME group by args.string_value order by count(*) desc例如下图展示了借用检查器各函数的耗时分布对应 src/borrow_tracker/mod.rs 中borrow_tracker::*系列 span查找长时间无追踪的空白时段下面的 SQL 用于找出耗时最长、但尚未被任何追踪调用覆盖的空白时段从而发现值得新增追踪点的地方。结果表中点击id可快速跳转到对应位置with ordered as ( select s1.*, row_number() over (order by s1.ts) as rn from slices as s1 where s1.parent_id is null and s1.dur 0 and s1.name ! frame and s1.name ! step ) select a.tsa.dur as ts, b.ts-a.ts-a.dur as dur, a.id, a.track_id, a.category, a.depth, a.stack_id, a.parent_stack_id, a.parent_id, a.arg_set_id, a.thread_ts, a.thread_instruction_count, a.thread_instruction_delta, a.cat, a.slice_id, empty as name from ordered as a inner join ordered as b on a.rnb.rn-1 order by b.ts-a.ts-a.dur desc关于保存 Perfetto 预设Perfetto 目前不支持把 UI 状态保存为可复用的 preset因此对多个 trace 做重复分析时需要每次手动点击菜单或重新执行上述 SQL。添加新的追踪调用tracing feature 与Machinetrait 的配合Miri 高度依赖rustc_const_eval因此完整的追踪数据也需要在rustc_const_eval的代码中加入调用。问题是Miri 的代码可以#[cfg(feature tracing)]判断 feature但rustc_const_eval是独立 crate在外部构建时甚至是预编译的.rlib无法感知该 feature。解决方案是在Machinetrait 中增加如下签名的方法fn enter_trace_span(span: impl FnOnce() - tracing::Span) - impl EnteredTraceSpan其中EnteredTraceSpan是一个标记 trait由()与tracing::span::EnteredSpan实现。该方法默认返回()且不调用span闭包只有MiriMachine在开启 tracing 时返回span().entered()。rustc_const_eval需要追踪时调用此方法编译器会理想情况下在 tracing 关闭时把调用整体优化掉。MiriMachine的实现见 src/machine.rs。enter_trace_span!()宏在 Miri 或rustc_const_eval中给某段代码加追踪直接使用enter_trace_span!()宏即可它会自动处理上述 feature 细节。该宏接受与tracing::span!()相同的语法另有少量自定义见下文返回一个已进入entered的 span。返回值是一个 drop guard被 drop 时自动退出 span因此务必把它存进变量以控制作用域let _trace enter_trace_span!(My span);在rustc_const_eval中调用时需要把实现Machinetrait 的类型作为第一个参数传入宏会用其调用Machine::enter_trace_span()。由于rustc_const_eval大部分代码是Machine无关的这个类型通常以M为名可用let _trace enter_trace_span!(My span); // from Miri let _trace enter_trace_span!(M, My span); // from rustc_const_eval宏在 Miri 侧的定义位于 src/helpers.rs它把MiriMachinestatic作为第一个参数注入后转发给rustc_const_eval::enter_trace_span!。仓库中的实际用法遍布 src/machine.rs如emulate_foreign_item、load_mir、data_race::before_memory_read等与 src/borrow_tracker/mod.rs如borrow_tracker::new_allocation、borrow_tracker::on_stack_pop等。tracing::span!()支持的语法enter_trace_span!()沿用tracing::span!()的语法几个容易混淆的写法列举如下// 生成名为 hello 的 span带字段 arg 值为 42仅当 42 实现了 tracing::Value // trait 时可行否则用下面两种方式 let _trace enter_trace_span!(M, hello, arg 42); // 字段名 my_display_var使用 Display 实现记录 let _trace enter_trace_span!(M, hello, %my_display_var); // 字段名 my_debug_var使用 Debug 实现记录 let _trace enter_trace_span!(M, hello, ?my_debug_var);NAME::SUBNAME语法除tracing::span!()的语法外enter_trace_span!()还允许把 span 名写成不带引号的NAME::SUBNAME形式span 名为NAME通常是组件名更具体的SUBNAME通常是函数名会作为名为NAME的字段传给 tracing。这样在 Perfetto 中查看时不会被 subname 干扰需要深入时再按上文增强时间线一节查看 subname// 例如下面第一行展开为第二行 let _trace enter_trace_span!(M, borrow_tracker::on_stack_pop); let _trace enter_trace_span!(M, borrow_tracker, borrow_tracker on_stack_pop);tracing_separate_thread参数Miri 使用tracing_chrome层保存 trace。要让某些 span 在 Perfetto 中落到独立的时间线/线程上可以在宏中传入tracing_separate_thread tracing::field::Empty。这用于把当前 step 或程序帧这类指示性 span 单独分离出来——它们最终显示在 Global Legacy Events 轨道上。使用tracing::field::Empty作为值是为了让其他 layer如日志忽略该字段let _trace enter_trace_span!(M, step::eval_statement, tracing_separate_thread tracing::field::Empty);tracing 关闭时执行其他逻辑EnteredTraceSpantrait 提供or_if_tracing_disabled()方法可在 tracing 关闭时执行替代逻辑例如输出一行日志let _trace enter_trace_span!(M, step::eval_statement) .or_if_tracing_disabled(|| tracing::info!(eval_statement));实现细节代码库中产生的所有事件与 span 先由tracingcrate 收集再分发给写 trace 文件的层tracing_chrome同时在开启日志时也会分发给 logger。为什么选择 tracing crate选择tracing的原因仓库文档原文要点维护非常活跃通过即插即用的Layer支持多种 trace 格式Miri 用tracing_chrome导出 Perfetto 格式span/event 不仅记录名称还附带文件、行号、模块与任意数量的自定义参数它原本就是 Miri 与 rustc 使用的日志框架。但tracing的主要缺点是开销大进入/退出一个 span 大约耗时 100ns而 Miri 许多 span 比这更短导致测量严重失真且程序明显变慢——文档写作时开启 tracing 会让 Miri 慢约 5 倍这已比早期版本好得多见下文时间测量一节。tracing_chrome 层Miri 使用tracing-chrome作为把 span/event 写入 Perfetto 兼容 JSON 的 Layer。虽然该 crate 在 crates.io 上有发布Miri 却不能直接依赖它因为依赖它会引入一份独立的tracingcrate 编译——Miri 不直接依赖tracing而是通过 rustc-private 使用 rustc 自带的版本而 cargo 在涉及 rustc-private 时无法识别出这是同一库。因此解决方案是把 tracing-chrome 唯一的源文件拷贝进 Miri即 src/bin/log/tracing_chrome.rs。拷贝后还顺带做了一些针对性的改动这些改动说明记录在该文件顶部的注释中。从 src/bin/log/mod.rs 可以看到它被声明为mod tracing_chrome;私有模块配合pub mod setup;一起构成日志与追踪子模块。时间测量与时钟源tracing-chrome 使用std::time::Instant计时。在多数现代系统上没问题底层clock_gettime走非常快的硬件计数器如tsc延迟约 16ns。但在部分 x86/x86_64 Linux 系统上tsc被认为不可靠内核会退回其他时钟源如hpet单次约 1.3µs这会让 trace 中大量时间被计时本身消耗严重降低可用性。可以检查系统当前使用的时钟源是否为tsc。[!WARNING] 一个有一定风险的解决办法是在内核启动参数中加入tscreliable clocksourcetsc hpetdisable强制使用tsc但可能造成系统不稳定请自行承担风险。其他有用工具生成火焰图除 trace 之外还可以用 Linux 的perf生成火焰图用于定位未被追踪调用覆盖的热点函数。编译 Miri 后执行perf record --call-graph dwarf -F 999 ./miri/target/debug/miri --edition 2021 --sysroot ~/.cache/miri ./tests/pass/hashmap.rs perf script | inferno-collapse-perf | inferno-flamegraph flamegraph.svg该命令用perf record以 999Hz 采样率记录调用栈perf script导出样本再经inferno-collapse-perf折叠、inferno-flamegraph渲染成 SVG 火焰图。小结Miri 的 tracing 基础设施是一套采集—序列化—可视化的完整链路tracingfeature 控制编译期开关MIRI_TRACING环境变量在运行期激活tracing_chrome层最终产物是 Perfetto 可直接加载的 Chrome Trace JSON。通过enter_trace_span!宏与Machine::enter_trace_span的巧妙配合Miri 和rustc_const_eval两侧都能以近乎零成本的方式埋点再用 Perfetto 的时间线、SQL 统计与火焰图等手段定位解释器各组件借用检查器、数据竞争检查器等的性能热点。相关参考完整追踪文档doc/tracing.md日志与追踪初始化src/bin/log/setup.rsenter_trace_span!宏定义src/helpers.rsMiriMachine::enter_trace_span实现src/machine.rs实际埋点示例src/borrow_tracker/mod.rs、src/machine.rsfeature 声明Cargo.toml【免费下载链接】miriAn interpreter for Rusts mid-level intermediate representation项目地址: https://gitcode.com/GitHub_Trending/mi/miri创作声明：本文部分内容由AI辅助生成（AIGC），仅供参考