Introduce `tokio-trace` #827

hawkw · 2019-01-04T01:12:14Z

Motivation

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. Currently, none
of the available logging frameworks or libraries in Rust offer the
ability to trace logical paths through a futures-based program.

There also are complementary goals that can be accomplished with such a
system. For example, metrics / instrumentation can be tracked by
observing emitted events, or trace data can be exported to a distributed
tracing or event processing system.

In addition, it can often be useful to generate this diagnostic data in
a structured manner that can be consumed programmatically. While prior
art for structured logging in Rust exists, it is not currently
standardized, and is not "Tokio-friendly".

Solution

This branch adds a new library to the tokio project, tokio-trace.
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-core crate contains the core primitives for this
system, which are expected to remain stable, while tokio-trace crate
provides a more "batteries-included" API. In particular, it provides
macros which are a superset of the log crate's error!, warn!,
info!, debug!, and trace! macros, allowing users to begin the
process of adopting tokio-trace by performing a drop-in replacement.

Notes

Work on this project had previously been carried out in the
tokio-trace-prototype repository. In addition to the tokio-trace and
tokio-trace-core crates, the tokio-trace-prototype repo also
contains prototypes or sketches of adapter, compatibility, and utility
crates which provide useful functionality for tokio-trace, but these
crates are not yet ready for a release. When this branch is merged, that
repository will be archived, and the remaining unstable crates will be
moved to a new tokio-trace-nursery repository. Remaining issues on the
tokio-trace-prototype repo will be moved to the appropriate new repo.

The crates added in this branch are not identical to the current head
of the tokio-trace-prototype repo, as I did some final clean-up and docs
polish in this branch prior to opening this PR.

Refs: #561

Signed-off-by: Eliza Weisman eliza@buoyant.io

davidbarsky

This looks pretty good; the only comments are around documentation and examples.

(I think I've reviewed this code before, and signed off on it.)

tokio-trace/README.md

seanmonstar

Making a review checkpoint here, just before tokio-trace/src/span.rs.

tokio-trace/LICENSE

tokio-trace/src/dispatcher.rs

tokio-trace/src/field.rs

tokio-trace/src/lib.rs

Addressed all feedback

carllerche

Looks really good 👍 Almost there, so close...

Left thoughts / questions inline. Also:

Should there be a debug_span! macro and a DebugSpan type? When compiled w/o debug_assertions, it would be a unit struct.
The public API of tokio-trace should probably be pruned down to focus on instrumentation (not subscribers). Any API that isn't needed should be removed or marked as #[doc(hidden)].

tokio-trace/tokio-trace-core/src/lib.rs

tokio-trace/tokio-trace-core/src/subscriber.rs

tokio-trace/tokio-trace-core/src/callsite.rs

carllerche · 2019-01-14T22:47:08Z

tokio-trace/src/span.rs

+/// span will silently do nothing. Thus, the handle can be used in the same
+/// manner regardless of whether or not the trace is currently being collected.
+#[derive(Clone, PartialEq, Hash)]
+pub struct Span<'a> {


The lifetime is going to be a bit annoying when storing the span in a future, which will be the common case. Is it necessary to have in this lib?

I had wondered about that when the lifetime was added (hawkw/tokio-trace-prototype#157 (comment)), too, and I'm still not sold on it.

In the tokio-trace-futures lib (in tokio-trace-nursery), IIRC, we just have hardcoded everything as Span<'static>. I thought it might be better to be more flexible here, and have the -futures crate introduce the static requirement. But, it does add more noise. I'd be happy to change this to always be 'static.

tokio-trace/src/span.rs

tokio-trace/src/lib.rs

Signed-off-by: Eliza Weisman <eliza@buoyant.io>

This picks up upstream changes from hawkw/tokio-trace-prototype#168. Signed-off-by: Eliza Weisman <eliza@buoyant.io>

Apparently we were missing this. I wrote a doc example that used it and was surprised when it didn't work. Signed-off-by: Eliza Weisman <eliza@buoyant.io>

Signed-off-by: Eliza Weisman <eliza@buoyant.io>

Looks like this was overlooked in hawkw/tokio-trace-prototype#168. Signed-off-by: Eliza Weisman <eliza@buoyant.io>

Signed-off-by: Eliza Weisman <eliza@buoyant.io>

I didn't want these to be covered only by doctests. Signed-off-by: Eliza Weisman <eliza@buoyant.io>

The new tests revealed these. Signed-off-by: Eliza Weisman <eliza@buoyant.io>

Signed-off-by: Eliza Weisman <eliza@buoyant.io>

This lets us completely skip `Span::new` in this case. This brings the benchmarks for the disabled case back into parity with `log`. Before: ``` Running target/release/deps/no_subscriber-1064195d321c8640 running 5 tests test bench_1_atomic_load ... bench: 0 ns/iter (+/- 0) test bench_costly_field_no_subscriber ... bench: 6 ns/iter (+/- 0) test bench_log_no_logger ... bench: 0 ns/iter (+/- 0) test bench_no_span_no_subscriber ... bench: 0 ns/iter (+/- 0) test bench_span_no_subscriber ... bench: 6 ns/iter (+/- 0) test result: ok. 0 passed; 0 failed; 0 ignored; 5 measured; 0 filtered out Running target/release/deps/subscriber-7319775649c47f41 running 4 tests test span_no_fields ... bench: 37 ns/iter (+/- 10) test span_repeatedly ... bench: 5,626 ns/iter (+/- 812) test span_with_fields ... bench: 101 ns/iter (+/- 20) test span_with_fields_record ... bench: 1,035 ns/iter (+/- 171) test result: ok. 0 passed; 0 failed; 0 ignored; 4 measured; 0 filtered out ``` After: ``` Running target/release/deps/no_subscriber-1064195d321c8640 running 5 tests test bench_1_atomic_load ... bench: 0 ns/iter (+/- 0) test bench_costly_field_no_subscriber ... bench: 0 ns/iter (+/- 0) test bench_log_no_logger ... bench: 0 ns/iter (+/- 0) test bench_no_span_no_subscriber ... bench: 0 ns/iter (+/- 0) test bench_span_no_subscriber ... bench: 0 ns/iter (+/- 0) test result: ok. 0 passed; 0 failed; 0 ignored; 5 measured; 0 filtered out Running target/release/deps/subscriber-7319775649c47f41 running 4 tests test span_no_fields ... bench: 36 ns/iter (+/- 8) test span_repeatedly ... bench: 5,381 ns/iter (+/- 1,075) test span_with_fields ... bench: 110 ns/iter (+/- 19) test span_with_fields_record ... bench: 1,019 ns/iter (+/- 247) test result: ok. 0 passed; 0 failed; 0 ignored; 4 measured; 0 filtered out ``` Signed-off-by: Eliza Weisman <eliza@buoyant.io>

Ugh, code duplication :/

carllerche · 2019-01-25T21:15:40Z

We should set a max number of span fields. 32 is a good start. This ensures we can use stack arrays for passing fields around.

carllerche · 2019-01-25T21:18:47Z

tokio-trace/tokio-trace-core/src/metadata.rs

+        module_path: Option<&'a str>,
+        file: Option<&'a str>,
+        line: Option<u32>,
+        field_names: &'static [&'static str],


field_names should not be exposed as &[&str]. We probably want an opaque type for this.

In theory, I agree. In practice, since we can't use const fns yet, the opaque type would need to have another constructor macro, so it just feels like a bunch of additional complexity to me. I can make that change regardless.

(also, I think FieldSet is essentially the opaque type for this, but it also has a callsite ID. we can't construct that here since we need to create the metadata before the callsite)

KodrAus · 2019-01-26T12:36:48Z

Having some arbitrary limit on the number of fields or the nested depth of complex objects is also, in my opinion, a defensible philosophical decision. It makes you stop and think about what it is you're actually collecting.

This branch reworks `tokio-trace`'s field recording APIs to improve performance in cases where field values are provided in batches. `tokio-trace` supports recording values for span fields either when the span is constructed, or at any point during its lifetime. In order to support this, the current implementation represents each field value recorded with a separate call to a `Subscriber::record_$TYPE` function. This can incur significant overhead --- for example, if the span data is stored behind a mutex, every call to `record` must reacquire the lock. Providing most or all of the fields on a span up-front as it is constructed is likely to be the common case, but in the current design, this use-case has to pay performance costs in order to support the less common case of adding values post-initialization. Even in situations where some field values are unknown, if a majority are recorded at construction-time, each individual value takes a separate trip through the `record` pipeline. This branch rewrites this API so that all field recording is done by a `ValueSet` type, which groups together multiple values. A subscriber may pass an implementation of `Record` to the `ValueSet`'s `record` function, which will record all the provided values with that recorder. When a span is constructed, the `Subscriber::new_span` method is called with a `ValueSet` containing all the fields provided to the `span!` macro, and additional fields may be recorded either individually or in batches. In addition, the previous implementation of `Event`s on top of `Span`s has been removed and replaced with a new `Event` type which goes through a separate `Subscriber::event` function. Events are always known to have all their values at construction time, since the event cannot live long enough to have more values added. Thus, an `Event` also contains a `ValueSet`. I've added new test-support code for expecting certain fields to be recorded by spans and events, and written new tests to cover this behaviour. I've also updated the example code, and my experience doing so suggests that the new API is also somewhat more ergonomic to use. These changes result in significant improvement on the benchmark that simulates recording multiple fields on a span (`bench_span_with_fields_record`). Before: ``` Running target/release/deps/no_subscriber-a6af9f5aa4934184 running 5 tests test bench_1_atomic_load ... bench: 0 ns/iter (+/- 0) test bench_costly_field_no_subscriber ... bench: 0 ns/iter (+/- 0) test bench_log_no_logger ... bench: 0 ns/iter (+/- 0) test bench_no_span_no_subscriber ... bench: 0 ns/iter (+/- 0) test bench_span_no_subscriber ... bench: 0 ns/iter (+/- 0) test result: ok. 0 passed; 0 failed; 0 ignored; 5 measured; 0 filtered out Running target/release/deps/subscriber-ba753dc1d87e480d running 4 tests test span_no_fields ... bench: 41 ns/iter (+/- 5) test span_repeatedly ... bench: 5,418 ns/iter (+/- 658) test span_with_fields ... bench: 110 ns/iter (+/- 42) test span_with_fields_record ... bench: 1,047 ns/iter (+/- 240) test result: ok. 0 passed; 0 failed; 0 ignored; 4 measured; 0 filtered out ``` After: ``` Running target/release/deps/no_subscriber-611d60b262fbbcfb running 5 tests test bench_1_atomic_load ... bench: 0 ns/iter (+/- 0) test bench_costly_field_no_subscriber ... bench: 1 ns/iter (+/- 0) test bench_log_no_logger ... bench: 0 ns/iter (+/- 0) test bench_no_span_no_subscriber ... bench: 0 ns/iter (+/- 0) test bench_span_no_subscriber ... bench: 0 ns/iter (+/- 0) test result: ok. 0 passed; 0 failed; 0 ignored; 5 measured; 0 filtered out Running target/release/deps/subscriber-7a1279c84c0d50ff running 4 tests test span_no_fields ... bench: 37 ns/iter (+/- 9) test span_repeatedly ... bench: 4,502 ns/iter (+/- 712) test span_with_fields ... bench: 54 ns/iter (+/- 17) test span_with_fields_record ... bench: 364 ns/iter (+/- 38) test result: ok. 0 passed; 0 failed; 0 ignored; 4 measured; 0 filtered out ``` Signed-off-by: Eliza Weisman <eliza@buoyant.io>

outdated

Signed-off-by: Eliza Weisman <eliza@buoyant.io>

These have to be in `-core` due to the orphan rules, but seem very handy. Signed-off-by: Eliza Weisman <eliza@buoyant.io>

The `trace_dbg!` macro requires this. Signed-off-by: Eliza Weisman <eliza@buoyant.io>

See also tokio-rs/tracing@5296a4c Signed-off-by: Eliza Weisman <eliza@buoyant.io>

hawkw · 2019-02-11T21:52:12Z

FWIW I believe the AppVeyor CI build for f2c8354 failed due to an unrelated issue.

Trailing commas are optional when fields are included, and when fields are delimited from the format string for the message. Before these would error: ``` event!(tokio_trace::Level::DEBUG, foo = 3, bar = 3,); event!(tokio_trace::Level::DEBUG, { foo = 2, bar = 78, }, "baz"); ``` Now they do not. Tests have been extended. Signed-off-by: Kevin Leimkuhler <kevinl@buoyant.io>

* tokio-trace: Extend `span!` rules Add the ability to define a target and log level for individual spans. `level: ...` must be included since both `$lvl` and `$name` are `expr`. The macro tests and documentation tests have been extended. Signed-off-by: Kevin Leimkuhler <kevinl@buoyant.io> * Add additional `span!` test Change default log level of `span!` to `TRACE` to reflect the default level used in `callsite!`. Signed-off-by: Kevin Leimkuhler <kevinl@buoyant.io>

Signed-off-by: Eliza Weisman <eliza@buoyant.io>

Looks like RLS missed a couple uses Signed-off-by: Eliza Weisman <eliza@buoyant.io>

Signed-off-by: Eliza Weisman <eliza@buoyant.io>

## Motivation 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. Currently, none of the available logging frameworks or libraries in Rust offer the ability to trace logical paths through a futures-based program. There also are complementary goals that can be accomplished with such a system. For example, metrics / instrumentation can be tracked by observing emitted events, or trace data can be exported to a distributed tracing or event processing system. In addition, it can often be useful to generate this diagnostic data in a structured manner that can be consumed programmatically. While prior art for structured logging in Rust exists, it is not currently standardized, and is not "Tokio-friendly". ## Solution This branch adds a new library to the tokio project, `tokio-trace`. `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-core` crate contains the core primitives for this system, which are expected to remain stable, while `tokio-trace` crate provides a more "batteries-included" API. In particular, it provides macros which are a superset of the `log` crate's `error!`, `warn!`, `info!`, `debug!`, and `trace!` macros, allowing users to begin the process of adopting `tokio-trace` by performing a drop-in replacement. ## Notes Work on this project had previously been carried out in the [tokio-trace-prototype] repository. In addition to the `tokio-trace` and `tokio-trace-core` crates, the `tokio-trace-prototype` repo also contains prototypes or sketches of adapter, compatibility, and utility crates which provide useful functionality for `tokio-trace`, but these crates are not yet ready for a release. When this branch is merged, that repository will be archived, and the remaining unstable crates will be moved to a new `tokio-trace-nursery` repository. Remaining issues on the `tokio-trace-prototype` repo will be moved to the appropriate new repo. The crates added in this branch are not _identical_ to the current head of the `tokio-trace-prototype` repo, as I did some final clean-up and docs polish in this branch prior to merging this PR. [tokio-trace-prototype]: https://github.com/hawkw/tokio-trace-prototype Closes: #561 Signed-off-by: Eliza Weisman <eliza@buoyant.io>

hawkw added the tokio-trace label Jan 4, 2019

hawkw self-assigned this Jan 4, 2019

hawkw requested review from carllerche, seanmonstar and davidbarsky January 4, 2019 01:12

hawkw changed the title ~~Eliza/tokio trace~~ Introduce tokio-trace Jan 4, 2019

davidbarsky previously requested changes Jan 4, 2019

View reviewed changes

tokio-trace/README.md Show resolved Hide resolved

tokio-trace/README.md Show resolved Hide resolved

hawkw force-pushed the eliza/tokio-trace branch from c78785d to 2251a90 Compare January 4, 2019 18:23

seanmonstar reviewed Jan 4, 2019

View reviewed changes

Thomasdezeeuw mentioned this pull request Jan 8, 2019

Add support for tracing Thomasdezeeuw/heph#31

Closed

4 tasks

carllerche previously requested changes Jan 14, 2019

View reviewed changes

hawkw added 18 commits January 15, 2019 13:07

Add tokio-trace-core crate

c4cf988

Signed-off-by: Eliza Weisman <eliza@buoyant.io>

Add tokio-trace crate

b60d478

Signed-off-by: Eliza Weisman <eliza@buoyant.io>

Add licenses

c1212f0

Signed-off-by: Eliza Weisman <eliza@buoyant.io>

Add a README to tokio-trace

754d4b6

Signed-off-by: Eliza Weisman <eliza@buoyant.io>

Add more examples and usage information to the tokio-trace readme

8a10214

Signed-off-by: Eliza Weisman <eliza@buoyant.io>

Add a README to the tokio-trace-core crate

00fa609

Signed-off-by: Eliza Weisman <eliza@buoyant.io>

Add new docs/examples from READMEs to RustDoc

36059f6

Signed-off-by: Eliza Weisman <eliza@buoyant.io>

Integrate upstream changes

bab2f40

This picks up upstream changes from hawkw/tokio-trace-prototype#168. Signed-off-by: Eliza Weisman <eliza@buoyant.io>

Support setting targets in log-like event macros

cf3ee71

Apparently we were missing this. I wrote a doc example that used it and was surprised when it didn't work. Signed-off-by: Eliza Weisman <eliza@buoyant.io>

Make doctest examples more compile-y

4720652

Signed-off-by: Eliza Weisman <eliza@buoyant.io>

Disallow bad stuff in tokio-trace-core

5b07f84

Signed-off-by: Eliza Weisman <eliza@buoyant.io>

Add support for no-message event! macro invocations

f226df0

Looks like this was overlooked in hawkw/tokio-trace-prototype#168. Signed-off-by: Eliza Weisman <eliza@buoyant.io>

Fix event macros with more than one field

234ce89

Signed-off-by: Eliza Weisman <eliza@buoyant.io>

Add RustDocs and examples to all event macros

7ea47e3

Signed-off-by: Eliza Weisman <eliza@buoyant.io>

Add real tests for macros

53d8159

I didn't want these to be covered only by doctests. Signed-off-by: Eliza Weisman <eliza@buoyant.io>

Handle missing cases for event! macro

9d1f6d8

The new tests revealed these. Signed-off-by: Eliza Weisman <eliza@buoyant.io>

Stop benchmarks from breaking the build

3db8af9

Signed-off-by: Eliza Weisman <eliza@buoyant.io>

*Actually* fix benchmarks breaking the build

25f7eea

Signed-off-by: Eliza Weisman <eliza@buoyant.io>

hawkw added 2 commits January 18, 2019 11:45

Inline the hottest Span methods

f0170be

hawkw force-pushed the eliza/tokio-trace branch from bdeea40 to d1195ef Compare January 18, 2019 19:52

All event invocations should skip the never case

096b3a7

Ugh, code duplication :/

carllerche reviewed Jan 25, 2019

View reviewed changes

Re-introduce ValueSet length limit

fc2fa65

Signed-off-by: Eliza Weisman <eliza@buoyant.io>

hawkw force-pushed the eliza/tokio-trace branch from 9ca409d to fc2fa65 Compare February 6, 2019 22:42

hawkw added 3 commits February 7, 2019 10:59

Add some utility impls for Record

e56cb74

These have to be in `-core` due to the orphan rules, but seem very handy. Signed-off-by: Eliza Weisman <eliza@buoyant.io>

Fix callsite macro not accepting string field names

7f590f5

The `trace_dbg!` macro requires this. Signed-off-by: Eliza Weisman <eliza@buoyant.io>

Add From<Subscriber> impl for Dispatch

f2c8354

See also tokio-rs/tracing@5296a4c Signed-off-by: Eliza Weisman <eliza@buoyant.io>

kleimkuhler added 2 commits February 11, 2019 16:42

hawkw mentioned this pull request Feb 18, 2019

Add span and event macros that are only enabled in debug mode tokio-rs/tracing#12

Closed

hawkw added 4 commits February 19, 2019 10:38

Don't publish tokio-trace/tokio-trace-core yet

d3e5735

Signed-off-by: Eliza Weisman <eliza@buoyant.io>

Rename Enter to Inner

37c4dcb

Signed-off-by: Eliza Weisman <eliza@buoyant.io>

*Actually* rename Enter to Inner

f07bcc2

Looks like RLS missed a couple uses Signed-off-by: Eliza Weisman <eliza@buoyant.io>

run rustfmt

bf798d9

Signed-off-by: Eliza Weisman <eliza@buoyant.io>

carllerche approved these changes Feb 19, 2019

View reviewed changes

hawkw merged commit c08e73c into master Feb 19, 2019

carllerche deleted the eliza/tokio-trace branch February 23, 2019 23:12

hawkw mentioned this pull request Mar 4, 2019

trace-core: API stability/forward-compat pass #948

Closed

hawkw added this to the tokio-trace-core 0.1 milestone Mar 5, 2019

hawkw modified the milestones: tokio-trace-core 0.1, tokio-trace v0.1 Mar 27, 2019

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Introduce `tokio-trace` #827

Introduce `tokio-trace` #827

hawkw commented Jan 4, 2019

davidbarsky left a comment

seanmonstar left a comment

carllerche left a comment

carllerche Jan 14, 2019

hawkw Jan 14, 2019

carllerche commented Jan 25, 2019

carllerche Jan 25, 2019

hawkw Feb 19, 2019

hawkw Feb 19, 2019

KodrAus commented Jan 26, 2019

hawkw commented Feb 11, 2019

Introduce tokio-trace #827

Introduce tokio-trace #827

Conversation

hawkw commented Jan 4, 2019

Motivation

Solution

Notes

davidbarsky left a comment

Choose a reason for hiding this comment

seanmonstar left a comment

Choose a reason for hiding this comment

carllerche left a comment

Choose a reason for hiding this comment

carllerche Jan 14, 2019

Choose a reason for hiding this comment

hawkw Jan 14, 2019

Choose a reason for hiding this comment

carllerche commented Jan 25, 2019

carllerche Jan 25, 2019

Choose a reason for hiding this comment

hawkw Feb 19, 2019

Choose a reason for hiding this comment

hawkw Feb 19, 2019

Choose a reason for hiding this comment

KodrAus commented Jan 26, 2019

hawkw commented Feb 11, 2019

Introduce `tokio-trace` #827

Introduce `tokio-trace` #827