Module polkadot_node_subsystem::gen::tracing::span

source ·
Expand description

Spans represent periods of time in which a program was executing in a particular context.

A span consists of fields, user-defined key-value pairs of arbitrary data that describe the context the span represents, and a set of fixed attributes that describe all tracing spans and events. Attributes describing spans include:

  • An Id assigned by the subscriber that uniquely identifies it in relation to other spans.
  • The span’s parent in the trace tree.
  • Metadata that describes static characteristics of all spans originating from that callsite, such as its name, source code location, verbosity level, and the names of its fields.

Creating Spans

Spans are created using the span! macro. This macro is invoked with the following arguments, in order:

  • The target and/or parent attributes, if the user wishes to override their default values.
  • The span’s verbosity level
  • A string literal providing the span’s name.
  • Finally, between zero and 32 arbitrary key/value fields.

For example:

use tracing::{span, Level};

/// Construct a new span at the `INFO` level named "my_span", with a single
/// field named answer , with the value `42`.
let my_span = span!(Level::INFO, "my_span", answer = 42);

The documentation for the span! macro provides additional examples of the various options that exist when creating spans.

The trace_span!, debug_span!, info_span!, warn_span!, and error_span! exist as shorthand for constructing spans at various verbosity levels.

Recording Span Creation

The Attributes type contains data associated with a span, and is provided to the Subscriber when a new span is created. It contains the span’s metadata, the ID of the span’s parent if one was explicitly set, and any fields whose values were recorded when the span was constructed. The subscriber, which is responsible for recording tracing data, can then store or record these values.

The Span Lifecycle

Entering a Span

A thread of execution is said to enter a span when it begins executing, and exit the span when it switches to another context. Spans may be entered through the enter, entered, and in_scope methods.

The enter method enters a span, returning a guard that exits the span when dropped

let my_var: u64 = 5;
let my_span = span!(Level::TRACE, "my_span", my_var);

// `my_span` exists but has not been entered.

// Enter `my_span`...
let _enter = my_span.enter();

// Perform some work inside of the context of `my_span`...
// Dropping the `_enter` guard will exit the span.
     Warning: In asynchronous code that uses async/await syntax,
     Span::enter may produce incorrect traces if the returned drop
     guard is held across an await point. See
     the method documentation
     for details.

The entered method is analogous to enter, but moves the span into the returned guard, rather than borrowing it. This allows creating and entering a span in a single expression:

// Create a span and enter it, returning a guard:
let span = span!(Level::INFO, "my_span").entered();

// We are now inside the span! Like `enter()`, the guard returned by
// `entered()` will exit the span when it is dropped...

// ...but, it can also be exited explicitly, returning the `Span`
// struct:
let span = span.exit();

Finally, in_scope takes a closure or function pointer and executes it inside the span:

let my_var: u64 = 5;
let my_span = span!(Level::TRACE, "my_span", my_var = &my_var);

my_span.in_scope(|| {
    // perform some work in the context of `my_span`...
});

// Perform some work outside of the context of `my_span`...

my_span.in_scope(|| {
    // Perform some more work in the context of `my_span`.
});
     Note: Since entering a span takes &self, and
     Spans are Clone, Send, and
     Sync, it is entirely valid for multiple threads to enter the
     same span concurrently.

Span Relationships

Spans form a tree structure — unless it is a root span, all spans have a parent, and may have one or more children. When a new span is created, the current span becomes the new span’s parent. The total execution time of a span consists of the time spent in that span and in the entire subtree represented by its children. Thus, a parent span always lasts for at least as long as the longest-executing span in its subtree.

// this span is considered the "root" of a new trace tree:
span!(Level::INFO, "root").in_scope(|| {
    // since we are now inside "root", this span is considered a child
    // of "root":
    span!(Level::DEBUG, "outer_child").in_scope(|| {
        // this span is a child of "outer_child", which is in turn a
        // child of "root":
        span!(Level::TRACE, "inner_child").in_scope(|| {
            // and so on...
        });
    });
    // another span created here would also be a child of "root".
});

In addition, the parent of a span may be explicitly specified in the span! macro. For example:

// Create, but do not enter, a span called "foo".
let foo = span!(Level::INFO, "foo");

// Create and enter a span called "bar".
let bar = span!(Level::INFO, "bar");
let _enter = bar.enter();

// Although we have currently entered "bar", "baz"'s parent span
// will be "foo".
let baz = span!(parent: &foo, Level::INFO, "baz");

A child span should typically be considered part of its parent. For example, if a subscriber is recording the length of time spent in various spans, it should generally include the time spent in a span’s children as part of that span’s duration.

In addition to having zero or one parent, a span may also follow from any number of other spans. This indicates a causal relationship between the span and the spans that it follows from, but a follower is not typically considered part of the duration of the span it follows. Unlike the parent, a span may record that it follows from another span after it is created, using the follows_from method.

As an example, consider a listener task in a server. As the listener accepts incoming connections, it spawns new tasks that handle those connections. We might want to have a span representing the listener, and instrument each spawned handler task with its own span. We would want our instrumentation to record that the handler tasks were spawned as a result of the listener task. However, we might not consider the handler tasks to be part of the time spent in the listener task, so we would not consider those spans children of the listener span. Instead, we would record that the handler tasks follow from the listener, recording the causal relationship but treating the spans as separate durations.

Closing Spans

Execution may enter and exit a span multiple times before that span is closed. Consider, for example, a future which has an associated span and enters that span every time it is polled:

struct MyFuture {
   // data
   span: tracing::Span,
}

impl Future for MyFuture {
    type Output = ();

    fn poll(self: Pin<&mut Self>, _cx: &mut Context<'_>) -> Poll<Self::Output> {
        let _enter = self.span.enter();
        // Do actual future work...
    }
}

If this future was spawned on an executor, it might yield one or more times before poll returns Poll::Ready. If the future were to yield, then the executor would move on to poll the next future, which may also enter an associated span or series of spans. Therefore, it is valid for a span to be entered repeatedly before it completes. Only the time when that span or one of its children was the current span is considered to be time spent in that span. A span which is not executing and has not yet been closed is said to be idle.

Because spans may be entered and exited multiple times before they close, Subscribers have separate trait methods which are called to notify them of span exits and when span handles are dropped. When execution exits a span, exit will always be called with that span’s ID to notify the subscriber that the span has been exited. When span handles are dropped, the drop_span method is called with that span’s ID. The subscriber may use this to determine whether or not the span will be entered again.

If there is only a single handle with the capacity to exit a span, dropping that handle “closes” the span, since the capacity to enter it no longer exists. For example:

{
    span!(Level::TRACE, "my_span").in_scope(|| {
        // perform some work in the context of `my_span`...
    }); // --> Subscriber::exit(my_span)

    // The handle to `my_span` only lives inside of this block; when it is
    // dropped, the subscriber will be informed via `drop_span`.

} // --> Subscriber::drop_span(my_span)

However, if multiple handles exist, the span can still be re-entered even if one or more is dropped. For determining when all handles to a span have been dropped, Subscribers have a clone_span method, which is called every time a span handle is cloned. Combined with drop_span, this may be used to track the number of handles to a given span — if drop_span has been called one more time than the number of calls to clone_span for a given ID, then no more handles to the span with that ID exist. The subscriber may then treat it as closed.

When to use spans

As a rule of thumb, spans should be used to represent discrete units of work (e.g., a given request’s lifetime in a server) or periods of time spent in a given context (e.g., time spent interacting with an instance of an external system, such as a database).

Which scopes in a program correspond to new spans depend somewhat on user intent. For example, consider the case of a loop in a program. Should we construct one span and perform the entire loop inside of that span, like:

let span = span!(Level::TRACE, "my_loop");
let _enter = span.enter();
for i in 0..n {
    // ...
}

Or, should we create a new span for each iteration of the loop, as in:

for i in 0..n {
    let span = span!(Level::TRACE, "my_loop", iteration = i);
    let _enter = span.enter();
    // ...
}

Depending on the circumstances, we might want to do either, or both. For example, if we want to know how long was spent in the loop overall, we would create a single span around the entire loop; whereas if we wanted to know how much time was spent in each individual iteration, we would enter a new span on every iteration.

Structs

  • Attributes
    Attributes provided to a Subscriber describing a new span when it is created.
  • Entered
    A guard representing a span which has been entered and is currently executing.
  • EnteredSpan
    An owned version of Entered, a guard representing a span which has been entered and is currently executing.
  • Id
    Identifies a span within the context of a subscriber.
  • Record
    A set of fields recorded by a span.
  • Span
    A handle representing a span, with the capability to enter the span if it exists.

Traits

  • AsId
    Trait implemented by types which have a span Id.