tokio-rs / tracing

Application level tracing for Rust.
https://tracing.rs
MIT License
5.5k stars 722 forks source link

Use qualified function names for span names generated by `#[instrumented]`. #2116

Open jswrenn opened 2 years ago

jswrenn commented 2 years ago

Feature Request

Crates

This feature directly impacts:

The discussed implementation strategies impact:

Motivation

The name metadata on spans generated by #[instrument] includes only the name the name of the annotated function, and thus lacks useful context. Consider the following two motivations:

Motivation: Distinguishing between methods with the same name

Because the name of the Self type is not included in name, it is difficult to distinguish between methods of different types that have the same name. For instance, the two methods in this example (reduced from mini-redis-server) have identical names ("run") and targets ("server"):

pub mod server {
    pub struct Listener;
    pub struct Handler;

    impl Listener {
        #[tracing::instrument]
        async fn run(&self) { … }
    }

    impl Handler {
        #[tracing::instrument]
        async fn run(&self) { … }
    }
}

Since name and target are the primary mechanism for filtering on spans, the spans emitted by each of these functions are incredibly difficult to distinguish from each other. Currently, the most viable recourse is to manually set their name:

pub mod server {
    pub struct Listener;
    pub struct Handler;

    impl Listener {
        #[tracing::instrument(name = "Listener::run")]
        async fn run(&self) { … }
    }

    impl Handler {
        #[tracing::instrument(name = "Handler::run")]
        async fn run(&self) { … }
    }
}

...which is fragile, mistake-prone, and verbose.

Motivation: Distinguishing between distinct instantiations of methods.

Because name does not factor in generic parameters, it is impossible to distinguish between distinct instantiations of generic methods. This is unfortunate, because how generic types are instantiated can have significant impact how methods behave and how they perform. E.g., all tracing spans emitted by lock in the below example will have identical names, regardless of how T is instantiated:

impl<T> Mutex<T> {
    #[tracing::instrument]
    fn lock<T>(&self) -> Guard<'_> {
        ...
    }
}

Proposals

Improving this situation is tricky, because:

  1. Rust lacks a function_name!() macro comparable to module_path!()
  2. Proc-macro method attributes do not have access to the name of the Self type during expansion.

However, it's nonetheless possible to generate names that include the necessary extra context.

A solution using core::any::type_name.

The below code (playground) defines two macros that produce &'static str:

/// Returns an `&'static str` containing the current function/method name,
/// EXCLUDING the instantiated generic parameters (if any).
macro_rules! abstract_fn_name {
    () => {{ 
        struct Here;
        const PREFIX: &str = concat!(module_path!(), "::");
        const SUFFIX: &str = "::Here";
        let here = core::any::type_name::<Here>();
        &here[PREFIX.len()..(here.len() - SUFFIX.len())]
    }}
}

/// Returns an `&'static str` containing the current function/method name,
/// INCLUDING the instantiated generic parameters (if any).
macro_rules! concrete_fn_name {
    () => {{
        fn type_name_of_val<T: ?Sized>(_: &T) -> &'static str {
            core::any::type_name::<T>()
        }
        const PREFIX: &str = concat!(module_path!(), "::");
        const SUFFIX: &str = "::{{closure}}";
        let here = &type_name_of_val(&||{});
        &here[PREFIX.len()..(here.len() - SUFFIX.len())]
    }}
}

struct GenericType<A>(A);

impl<A> GenericType<A> {
    fn generic_method<B>(self, _a: B) {
        dbg!(abstract_fn_name!());
        dbg!(concrete_fn_name!());
    }
}

pub fn main() {
    GenericType(42u8).generic_method(false);
}

The above snippet prints:

[src/main.rs:31] abstract_fn_name!() = "GenericType<_>::generic_method"
[src/main.rs:32] concrete_fn_name!() = "GenericType<u8>::generic_method<bool>"

Unfortunately, neither of the above approaches can be easily be adapted to be runnable in a const context, since core::any::type_name is not a const fn. At minimum, implementing this approach would require revising the expansion of span!. Furthermore, the result of concrete_fn_name!() cannot be cached in a static without indirection, since distinct generic instantiations of functions in Rust currently share their statics.

Implementing either of the above two approaches thus would require changes to tracing. (That said, relaxing the stiff requirements that tracing imposes on Span names (i.e., that they're const evaluable and static), would have other benefits. When I was working on allocating tracing, for instance, I really wanted to be able to dynamically generate event names from the backtrace frames in alloc and free, but could not do so.)

A solution (ab)using proc macros.

Although proc-macro attributes do not have access to the qualified function name of annotated fn items, they do have unstable access to:

...of processed token spans. Using these, the #[instrument] macro could be modified re-parse a full syntax tree from the source-file containing the annotated item, then find the fn item in that three with a matching source location, and then look back up the parse tree to determine whether the fn item is associated with a type.

Alternatives

Aside from the option of taking no action, we could also advocate for any of the following Rust language/library features:

These features would, in the long term, eliminate the implementation drawbacks of the type_name-based approach.

hawkw commented 2 years ago

See also existing issues #1939 and #1123 — this seems like a specific proposal for how to implement the behavior discussed in those issues. I believe the comments on those issues may discuss additional alternative approaches.

One thing I'll add is that we can always use non-const-eval-able code as the span's message for now, which would let us add your proposed approach for getting qualified method names into the current #[instrument]-generated spans, and we could then go back and use them for the span's name later if (say) type_name becomes possible in const contexts.

WesleyAC commented 7 months ago

What's the reason behind the decision to require span names to be const evaluable?

hawkw commented 7 months ago

What's the reason behind the decision to require span names to be const evaluable?

Span names are part of a span's metadata, which is a static struct generated at compile-time. Filtering (determining whether a span or event is enabled) is performed using this static metadata, before any data is recorded. This makes skipping disabled spans or events fast, because none of the data recorded by skipped spans/events must be evaluated in order to disable them.