rust - 如何使用 Rust 跟踪获取/存储跨度持续时间？

Question

我想捕获 Rust 跟踪中跨度的执行持续时间并将其作为指标发送。

我发现 fmt() 有助于打印此处提到的内容:How can I log span duration with Rust tracing?

我也尝试过this有关创建图层和实现 on_new_span() 和 on_event() 的示例。我还添加了 on_close() 来检查我们在这里获得了哪些元数据。我编写的代码是:

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"

不幸的是，我无法在任何地方获取有关跨度持续时间的数据。你们能帮我确定如何/从哪里获得它吗？

Answer 1

您无法从tracing“获取”跨度持续时间 crate ，因为它不存储它。它仅存储基本元数据，并允许以轻量级方式 Hook 到框架事件。这是 Subscriber 的工作跟踪任何其他数据。

您可以使用tracing-timing如果您只需要周期性直方图，请使用 crate。否则，您无法真正使用可能已经存储计时数据的现有层中的数据，因为它们通常不会公开它。您必须自己跟踪它。

使用tracing-subscriber crate ，您可以创建一个 Layer并使用 Registry 存储附加数据。以下是如何做到这一点的示例:

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(),
        );
    }
}

这只是打印出计算结果，但您可以将结果发送到其他地方，或者将其存储在您认为合适的共享资源中。

一些示例用法:

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

您可能还需要了解 on_enter() 和 on_exit()，它们在使用 async 函数时相关，因为它们的执行可能会暂停并稍后恢复，您可以使用这些功能在发生这种情况时收到通知。根据您要查找的内容，您可能需要添加过滤，以便仅跟踪您感兴趣的范围(按名称或目标或其他方式)。