rusttrace

How can I filter trace spans by duration?


Using tracing_subscriber, How can I log span duration with Rust tracing? explains how to trace span durations. But I have a lot, and I only want to see slow ones.

I have tried this but I'm not sure how to get the span duration from metadata:


fn set_up_tracing() -> Box<dyn std::any::Any> {
    // keep ten days of logs in daily files up to 1MB
    let file_appender = rolling_file::BasicRollingFileAppender::new(
        "./mubbles.log",
        rolling_file::RollingConditionBasic::new()
            .daily()
            .max_size(1024 * 1024 * 10),
        3,
    )
    .expect("Couldn't open log file");
    let (non_blocking, _guard) = tracing_appender::non_blocking(file_appender);

    let my_filter = FilterFn::new(|metadata| {
        metadata.
    });

    let console_layer = tracing_subscriber::fmt::Layer::new()
        .pretty()
        .with_writer(std::io::stdout.with_max_level(tracing::Level::WARN))
        .with_filter(EnvFilter::from_default_env());
    let file_layer = tracing_subscriber::fmt::Layer::new()
        .with_writer(non_blocking)
        .with_ansi(false)
        .with_span_events(tracing_subscriber::fmt::format::FmtSpan::CLOSE)
        .with_filter(my_filter)
        //.without_time()
        .with_filter(EnvFilter::from_default_env());
    // use RUST_LOG="warn,mubbles=trace" to see app tracing
    tracing::subscriber::set_global_default(
        tracing_subscriber::registry()
            .with(console_layer)
            .with(file_layer),
    )
    .expect("Couldn't set up tracing");

    Box::new(_guard)
}

I read the tracing_subscriber docs and found FilterFn; I was expecting to be able to extract is_span and event type and then the duration from the metadata.

How can I get/store span duration with Rust tracing? explains how to add a layer, but I'm not sure how to extend that into a filter.


Solution

  • You can't do it using only the metadata, since the metadata by definition only contains the static data about a span.

    Furthermore, you cannot filter by duration, because to know the duration the span needs to close, but by then the event has already been emitted.

    Therefore, you will have to handle the printing yourself. The general way will be to implement Layer, add an extension into the span containing the time when the span is opened, and calculating the duration and if needed printing it when it is closed.