如何在Rust tracing中获取与存储Span执行时长？

核心思路 #

tracing的Layer本身不直接提供Span的时长数据，但可以通过在Span创建时记录开始时间，在Span关闭时计算时间差来实现。借助tracing_core的SpanId作为唯一标识，关联每个Span的创建时间，再在on_close回调中计算时长并导出为指标。

具体实现步骤 #

1. 定义自定义Layer结构体 #

用线程安全的哈希表存储每个Span的开始时间，同时集成需要导出的指标（以Prometheus直方图为例，可根据实际监控系统替换）：

use std::collections::HashMap;
use std::sync::{Arc, Mutex};
use std::time::Instant;
use tracing_core::{span, SpanId};
use tracing_subscriber::layer::{Context, Layer};

struct SpanDurationLayer {
    start_times: Arc<Mutex<HashMap<SpanId, Instant>>>,
    span_duration_histogram: prometheus::Histogram,
}

2. 实现Layer的关键方法 #

• on_new_span：Span创建时记录当前时间
• on_close：Span销毁时取出开始时间，计算时长并更新指标

impl<S> Layer<S> for SpanDurationLayer
where
    S: tracing_core::Subscriber,
{
    fn on_new_span(&self, _attrs: &span::Attributes<'_>, id: &SpanId, _ctx: Context<'_, S>) {
        let now = Instant::now();
        self.start_times.lock().unwrap().insert(*id, now);
    }

    fn on_close(&self, id: SpanId, _ctx: Context<'_, S>) {
        let mut start_times = self.start_times.lock().unwrap();
        if let Some(start_time) = start_times.remove(&id) {
            let duration_secs = start_time.elapsed().as_secs_f64();
            
            // 更新监控指标
            self.span_duration_histogram.observe(duration_secs);
            
            // 可选：直接打印时长
            println!("Span {} executed in {:.3}s", id, duration_secs);
        }
    }
}

3. 初始化并注册Layer到tracing订阅器 #

use prometheus::{HistogramOpts, Registry};
use tracing_subscriber::Registry as TracingRegistry;

fn main() {
    // 初始化Prometheus指标
    let opts = HistogramOpts::new("span_duration_seconds", "Duration of tracing spans in seconds");
    let span_duration_histogram = prometheus::Histogram::with_opts(opts).unwrap();
    let registry = Registry::new();
    registry.register(Box::new(span_duration_histogram.clone())).unwrap();

    // 创建自定义Layer
    let duration_layer = SpanDurationLayer {
        start_times: Arc::new(Mutex::new(HashMap::new())),
        span_duration_histogram,
    };

    // 注册Layer到全局订阅器
    let subscriber = TracingRegistry::default().with(duration_layer);
    tracing::subscriber::set_global_default(subscriber).unwrap();

    // 测试Span时长捕获
    let root_span = tracing::info_span!("database_query");
    let _enter = root_span.enter();
    std::thread::sleep(std::time::Duration::from_secs(1));
    
    {
        let child_span = tracing::debug_span!("row_fetch");
        let _enter_child = child_span.enter();
        std::thread::sleep(std::time::Duration::from_millis(300));
    }
}

注意事项 #

• 多线程环境下必须用Arc<Mutex<HashMap>>保证线程安全，避免数据竞争
• 可以通过Span的元数据（名称、标签、target）扩展指标维度，比如按Span名称拆分直方图
• 若不需要监控指标，可直接在on_close中将时长写入日志系统

内容的提问来源于stack exchange，提问作者Sameer Shinde