Eliza Weisman
197f88f3bc
## Motivation
The `Span::enter` function previously required an `&mut` reference to
enter a span. This is a relic of an earlier design where span closure
logic was determined by dropping an inner span component, and is no
longer strictly necessary.
Requiring `&mut self` to enter a span leads to awkward patterns in cases
when a user wishes to enter a span and then call methods on the span
(such as recording field values). For example, we cannot say
```rust
let mut span = span!("foo", bar);
span.enter(|| {
span.record("bar" &false);
});
```
since the span is mutably borrowed by `enter`. Instead, we must clone
the span, like so:
```rust
let mut span = span!("foo", bar);
span.clone().enter(|| {
span.record("bar" &false);
});
```
Having to clone the span is somewhat less ergonomic, and it has
performance disadvantages as well: cloning a `Span` will clone the
span's `Dispatch` handle, requiring an `Arc` bump, as well as calling
the `Subscriber`'s `clone_span` and `drop_span` functions. If we can
enter spans without a mutable borrow, we don't have to update any of
these ref counts.
The other reason we may wish to require mutable borrows to enter a span
is if we want to disallow entering a span multiple times before exiting
it. However, it is trivially possible to re-enter a span on the same
thread regardless, by cloning the span and entering it twice. Besides,
there may be a valuable semantic meaning in entering a span from inside
itself, such as when a function is called recursively, so disallowing
this is not a goal.
## Solution
This branch rewrites the `Span::enter`, `Span::record`, and
`Span::record_all` functions to no longer require mutable borrows.
In the case of `record` and `record_all`, this was trivial, as borrowing
mutably was not actually *necessary* for those functions. For `enter`,
the `Entered` guard type was reworked to consist of an `&'a Inner`
rather than an `Inner`, so it is no longer necessary to `take` the
span's `Inner`.
## Notes
In addition to allowing spans to be entered without mutable borrows,
`Entered` was changed to exit the span automatically when the guard is
dropped, so we may now observe correct span exits even when unwinding.
Furthermore, this allows us to simplify the `enter` function a bit,
leading to a minor performance improvement when entering spans.
Before:
```
test enter_span ... bench: 13 ns/iter (+/- 1)
```
...and after:
```
test enter_span ... bench: 3 ns/iter (+/- 1)
```
Note that this branch also contains a change to make the
`subscriber::enter_span` benchmark more accurate. Previously, this
benchmark constructed a new span inside of `b.iter(|| {...})`. This
means that the benchmark was measuring not only the time taken to enter
a span, but the time taken to construct a `Span` handle as well.
However, we already have benchmarks for span construction, and the
intention of this particular benchmark was to measure the overhead of
constructing a span.
I've updated the benchmark by moving the span construction out of the
`iter` closure. Now, the span is constructed a single time and entered
on every iteration. This allows us to measure only the overhead of
actually entering a span. The "before" benchmark numbers above were
recorded after backporting this change to master, so they are "fair" to
the previous implementation. Prior to this change the benchmark took
approximately 53 ns.
Signed-off-by: Eliza Weisman <[email protected]>
tokio-trace
A scoped, structured logging and diagnostics system.
Overview
tokio-trace is a framework for instrumenting Rust programs to collect
structured, event-based diagnostic information.
In asynchronous systems like Tokio, interpreting traditional log messages can
often be quite challenging. Since individual tasks are multiplexed on the same
thread, associated events and log lines are intermixed making it difficult to
trace the logic flow. tokio-trace expands upon logging-style diagnostics by
allowing libraries and applications to record structured events with additional
information about temporality and causality — unlike a log message, a span
in tokio-trace has a beginning and end time, may be entered and exited by the
flow of execution, and may exist within a nested tree of similar spans. In
addition, tokio-trace spans are structured, with the ability to record typed
data as well as textual messages.
The tokio-trace crate provides the APIs necessary for instrumenting libraries
and applications to emit trace data.
Usage
First, add this to your Cargo.toml:
[dependencies]
tokio-trace = { git = "https://github.com/tokio-rs/tokio" }
Next, add this to your crate:
#[macro_use]
extern crate tokio_trace;
This crate provides macros for creating Spans and Events, which represent
periods of time and momentary events within the execution of a program,
respectively.
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). In contrast, events should be used to represent points in time within a span — a request returned with a given status code, n new items were taken from a queue, and so on.
Spans are constructed using the span! macro, and then entered
to indicate that some code takes place within the context of that Span:
// Construct a new span named "my span".
let mut span = span!("my span");
span.enter(|| {
// Any trace events in this closure or code called by it will occur within
// the span.
});
// Dropping the span will close it, indicating that it has ended.
The Event type represent an event that occurs instantaneously, and is
essentially a Span that cannot be entered. They are created using the event!
macro:
use tokio_trace::Level;
event!(Level::INFO, "something has happened!");
Users of the log crate should note that tokio-trace exposes a set of macros for
creating Events (trace!, debug!, info!, warn!, and error!) which may
be invoked with the same syntax as the similarly-named macros from the log
crate. Often, the process of converting a project to use tokio-trace can begin
with a simple drop-in replacement.
Let's consider the log crate's yak-shaving example:
#[macro_use]
extern crate tokio_trace;
use tokio_trace::field;
pub fn shave_the_yak(yak: &mut Yak) {
// Create a new span for this invocation of `shave_the_yak`, annotated
// with the yak being shaved as a *field* on the span.
span!("shave_the_yak", yak = field::debug(&yak)).enter(|| {
// Since the span is annotated with the yak, it is part of the context
// for everything happening inside the span. Therefore, we don't need
// to add it to the message for this event, as the `log` crate does.
info!(target: "yak_events", "Commencing yak shaving");
loop {
match find_a_razor() {
Ok(razor) => {
// We can add the razor as a field rather than formatting it
// as part of the message, allowing subscribers to consume it
// in a more structured manner:
info!({ razor = field::display(razor) }, "Razor located");
yak.shave(razor);
break;
}
Err(err) => {
// However, we can also create events with formatted messages,
// just as we would for log records.
warn!("Unable to locate a razor: {}, retrying", err);
}
}
}
})
}
You can find examples showing how to use this crate in the examples directory.
In libraries
Libraries should link only to the tokio-trace crate, and use the provided
macros to record whatever information will be useful to downstream consumers.
In executables
In order to record trace events, executables have to use a Subscriber
implementation compatible with tokio-trace. A Subscriber implements a way of
collecting trace data, such as by logging it to standard output.
Unlike the log crate, tokio-trace does not use a global Subscriber which
is initialized once. Instead, it follows the tokio pattern of executing code
in a context. For example:
#[macro_use]
extern crate tokio_trace;
let my_subscriber = FooSubscriber::new();
tokio_trace::subscriber::with_default(subscriber, || {
// Any trace events generated in this closure or by functions it calls
// will be collected by `my_subscriber`.
})
This approach allows trace data to be collected by multiple subscribers within
different contexts in the program. Alternatively, a single subscriber may be
constructed by the main function and all subsequent code executed with that
subscriber as the default. Any trace events generated outside the context of a
subscriber will not be collected.
The executable itself may use the tokio-trace crate to instrument itself as
well.
The tokio-trace-nursery repository contains less stable crates designed to
be used with the tokio-trace ecosystem. It includes a collection of
Subscriber implementations, as well as utility and adapter crates.
License
This project is licensed under the MIT license.
Contribution
Unless you explicitly state otherwise, any contribution intentionally submitted for inclusion in Tokio by you, shall be licensed as MIT, without any additional terms or conditions.