How can I get/store span duration with Rust tracing?

Question

I want to capture the duration of execution of a span in rust tracing and send that as metric.

I have found that fmt() helps in printing that as mentioned here:How can I log span duration with Rust tracing?

I have also tried this example about creating layer and implementing on_new_span() and on_event(). I added on_close() as well to check what metadata do we get here. The code for that I wrote is:

use tracing::{info, info_span};
use tracing_subscriber::prelude::*;
mod custom_layer;
use custom_layer::CustomLayer;

fn main() {

    tracing_subscriber::registry()
        .with(CustomLayer)
        .init();

    let outer_span = info_span!("Outer", level = 0, other_field = tracing::field::Empty);
    let _outer_entered = outer_span.enter();

    outer_span.record("other_field", &7);

    let inner_span = info_span!("inner", level = 1);
    let _inner_entered = inner_span.enter();

    info!(a_bool = true, answer = 42, message = "first example");

}

custom_layer.rs:

use std::collections::BTreeMap;
use tracing_subscriber::Layer;

pub struct CustomLayer;

impl<S> Layer<S> for CustomLayer
where
    S: tracing::Subscriber,
    S: for<'lookup> tracing_subscriber::registry::LookupSpan<'lookup>,
{
    fn on_new_span(
        &self,
        attrs: &tracing::span::Attributes<'_>,
        id: &tracing::span::Id,
        ctx: tracing_subscriber::layer::Context<'_, S>,
    ) {
        let span = ctx.span(id).unwrap();
        let mut fields = BTreeMap::new();
        let mut visitor = JsonVisitor(&mut fields);
        attrs.record(&mut visitor);
        let storage = CustomFieldStorage(fields);
        let mut extensions = span.extensions_mut();
        extensions.insert(storage);
    }

    fn on_record(
        &self,
        id: &tracing::span::Id,
        values: &tracing::span::Record<'_>,
        ctx: tracing_subscriber::layer::Context<'_, S>,
    ) {
        // Get the span whose data is being recorded
        let span = ctx.span(id).unwrap();

        // Get a mutable reference to the data we created in new_span
        let mut extensions_mut = span.extensions_mut();
        let custom_field_storage: &mut CustomFieldStorage =
        extensions_mut.get_mut::<CustomFieldStorage>().unwrap();
        let json_data: &mut BTreeMap<String, serde_json::Value> = &mut custom_field_storage.0;

        // And add to using our old friend the visitor!
        let mut visitor = JsonVisitor(json_data);
        values.record(&mut visitor);
    }

    fn on_event(&self, event: &tracing::Event<'_>, ctx: tracing_subscriber::layer::Context<'_, S>) {
        // All of the span context
        let scope = ctx.event_scope(event).unwrap();
        let mut spans = vec![];
        for span in scope.from_root() {
            let extensions = span.extensions();
            let storage = extensions.get::<CustomFieldStorage>().unwrap();
            let field_data: &BTreeMap<String, serde_json::Value> = &storage.0;
            spans.push(serde_json::json!({
                "target": span.metadata().target(),
                "name": span.name(),
                "level": format!("{:?}", span.metadata().level()),
                "fields": field_data,
            }));
        }

        // The fields of the event
        let mut fields = BTreeMap::new();
        let mut visitor = JsonVisitor(&mut fields);
        event.record(&mut visitor);

        // And create our output
        let output = serde_json::json!({
            "target": event.metadata().target(),
            "name": event.metadata().name(),
            "level": format!("{:?}", event.metadata().level()),
            "fields": fields,
            "spans": spans,
        });
        println!("{}", serde_json::to_string_pretty(&output).unwrap());
    }

    fn on_close(
        &self,
        id: tracing::span::Id,
        ctx: tracing_subscriber::layer::Context<'_, S>,
    ) {
        // Get the span whose data is being recorded
        let span = ctx.span(&id).unwrap();
    
        let output = serde_json::json!({
            "target": span.metadata().target(),
            "name": span.name(),
            "level": format!("{:?}", span.metadata().level()),
            "fields": format!("{:?}", span.metadata().fields()),
        });
        println!("On_close{}", serde_json::to_string_pretty(&output).unwrap());

    }
}

struct JsonVisitor<'a>(&'a mut BTreeMap<String, serde_json::Value>);

impl<'a> tracing::field::Visit for JsonVisitor<'a> {
    fn record_f64(&mut self, field: &tracing::field::Field, value: f64) {
        self.0
        .insert(field.name().to_string(), serde_json::json!(value));
    }

    fn record_i64(&mut self, field: &tracing::field::Field, value: i64) {
        self.0
        .insert(field.name().to_string(), serde_json::json!(value));
    }

    fn record_u64(&mut self, field: &tracing::field::Field, value: u64) {
        self.0
        .insert(field.name().to_string(), serde_json::json!(value));
    }

    fn record_bool(&mut self, field: &tracing::field::Field, value: bool) {
        self.0
        .insert(field.name().to_string(), serde_json::json!(value));
    }

    fn record_str(&mut self, field: &tracing::field::Field, value: &str) {
        self.0
        .insert(field.name().to_string(), serde_json::json!(value));
    }

    fn record_error(
        &mut self,
        field: &tracing::field::Field,
        value: &(dyn std::error::Error + 'static),
    ) {
        self.0.insert(
            field.name().to_string(),
            serde_json::json!(value.to_string()),
        );
    }

    fn record_debug(&mut self, field: &tracing::field::Field, value: &dyn std::fmt::Debug) {
        self.0.insert(
            field.name().to_string(),
            serde_json::json!(format!("{:?}", value)),
        );
    }
}

#[derive(Debug)]
struct CustomFieldStorage(BTreeMap<String, serde_json::Value>);

Cargo.toml

[package]
name = "tracing-custom-logging"
version = "0.1.0"
edition = "2021"

[dependencies]
serde_json = "1"
tracing = "0.1"
tracing-subscriber = "0.3.16"
snafu = "0.7.3"
thiserror = "1.0.31"
tracing-opentelemetry = "0.18.0"

Unfortunately I have not been able to get the data about duration of a span anywhere. Can you guys help me identify how/where can I get it from?

Answer 1

You cannot "get" the span duration from the tracing crate because it doesn't store it. It only stores the basic metadata and allows for hooking into framework events in a lightweight way. It is the job of the Subscriber to keep track of any additional data.

You could use the tracing-timing crate if you only need periodic histograms. Otherwise, you can't really use data from an existing layer which may already store timing data, because they often don't expose it. You'll have to keep track of it yourself.

Using the tracing-subscriber crate, you can create a Layer and store additional data using the Registry. Here's an example of how that can be done:

use std::time::Instant;
use tracing::span::{Attributes, Id};
use tracing::Subscriber;
use tracing_subscriber::layer::{Context, Layer};
use tracing_subscriber::registry::LookupSpan;

struct Timing {
    started_at: Instant,
}

pub struct CustomLayer;

impl<S> Layer<S> for CustomLayer
where
    S: Subscriber,
    S: for<'lookup> LookupSpan<'lookup>,
{
    fn on_new_span(&self, _attrs: &Attributes<'_>, id: &Id, ctx: Context<'_, S>) {
        let span = ctx.span(id).unwrap();

        span.extensions_mut().insert(Timing {
            started_at: Instant::now(),
        });
    }

    fn on_close(&self, id: Id, ctx: Context<'_, S>) {
        let span = ctx.span(&id).unwrap();

        let started_at = span.extensions().get::<Timing>().unwrap().started_at;

        println!(
            "span {} took {}",
            span.metadata().name(),
            (Instant::now() - started_at).as_micros(),
        );
    }
}

This just prints out the results where they are calculated, but you can emit the results elsewhere, or store it in some shared resource as you see fit.

Some example usage:

use std::time::Duration;
use tracing_subscriber::layer::SubscriberExt;
use tracing_subscriber::util::SubscriberInitExt;

#[tracing::instrument]
fn test(n: u64) {
    std::thread::sleep(Duration::from_secs(n));
}

fn main() {
    tracing_subscriber::registry::Registry::default()
        .with(CustomLayer)
        .init();

    test(1);
    test(2);
    test(3);
}

span test took 1000081
span test took 2000106
span test took 3000127

You may also need to be aware of on_enter() and on_exit(), which are relevant when using async functions because their execution may be suspended and resumed later, and you can use those functions to be notified when that happens. Depending on what you're looking for, you may need to add filtering so that you only track the spans you're interested in (by name or target or whatever).