Commit Graph
6 Commits
Author SHA1 Message Date
Eliza Weisman 4bfa4ffcdf trace-core: Dispatchers unset themselves (#1033)
This branch changes `dispatcher::get_default` to unset the thread's
current dispatcher while the reference to it is held by the closure.
This prevents infinite loops if the subscriber calls code paths which
emit events or construct spans. 

Note that this also means that nested calls to `get_default` inside of a
`get_default` closure will receive a `None` dispatcher rather than the
"actual" dispatcher. However, it was necessary to unset the default in
`get_default` rather than in dispatch methods such as `Dispatch::enter`,
as when those functions are called, the current state has already been
borrowed.

Before:
```
test enter_span              ... bench:           3 ns/iter (+/- 0)
test span_no_fields          ... bench:          51 ns/iter (+/- 12)
test span_repeatedly         ... bench:       5,073 ns/iter (+/- 1,528)
test span_with_fields        ... bench:          56 ns/iter (+/- 49)
test span_with_fields_record ... bench:         363 ns/iter (+/- 61)
```

After:
```
test enter_span              ... bench:           3 ns/iter (+/- 0)
test span_no_fields          ... bench:          35 ns/iter (+/- 12)
test span_repeatedly         ... bench:       4,165 ns/iter (+/- 298)
test span_with_fields        ... bench:          48 ns/iter (+/- 12)
test span_with_fields_record ... bench:         363 ns/iter (+/- 91)
```

Closes #1032 

Signed-off-by: Eliza Weisman <[email protected]>
2019-04-16 15:51:45 -07:00
Jane Lusby b4fe517a16 trace-core: add a function to rebuild cached interest (#1039)
## Motivation

Currently, `tokio-trace-core` permits `Subscriber`s to indicate that
they are "always", "sometimes", or "never" interested in a particular
callsite. When "always" or "never" is returned, then the interest is
cached and the subscriber will not be asked again about that callsite.
This is much more efficient than requiring the filter to be re-evaluated
every time the callsite is hit.

However, if a subscriber wishes to change its filter configuration
dynamically at runtime, it cannot benefit from this caching. Instead, it
must always return `Interest::sometimes`.  Even when filters change very
infrequently, they must still always be re-evaluated every time.

In order to support a use-case where subscribers may change their filter
configuration at runtime (e.g. tokio-rs/tokio-trace-nursery#42),
but do so infrequently, we should introducing a new function to
invalidate the cached interest.

## Solution

This branch adds a new function in the `callsite` module, called
`rebuild_interest_cache`, that will invalidate and rebuild all cached
interest.

## Breaking Change

In order to fix a race condition that could occur when rebuilding
interest caches using `clear_interest` and `add_interest`, these methods
have been replaced by a new `set_interest` method. `set_interest` should
have the semantics of atomically replacing the previous cached interest,
so that the callsite does not enter a temporary state where it has no
interest.

Closes #1038

Co-Authored-By: yaahallo <[email protected]>
2019-04-10 13:51:05 -07:00
Eliza Weisman 197f88f3bc trace: Change Span::enter and record to take &self (#1029)
## 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]>
2019-04-03 15:06:47 -07:00
João Oliveira 597f271c08 trace: Remove default trace level and make levels mandatory on span! macro (#1025)
## Motivation 

Was determined that having the span! macro default to the TRACE level is
probably not ideal (see discussion on #952). 

Closes #1013

## Solution 

Remove default trace level and make log lvl mandatory on span! macro,
and add the respective `trace_span!`, `debug_span!`, `info_span!`,
`warn_span!` and `error_span!` macros that behave as span! macro, but
with defined log levels

## Notes 

I think this is it, also removed some captures that were repeated, and
some testcases that also seemed repeated after adding the mandatory log
level, but please review it, if more tests or examples are needed happy
to provide (tried to find a way to get the generated macros log level,
but didn't find one, if there is a way i can add tests to assert that
the generated macro has the matching log level ). thanks
2019-04-02 11:29:23 -07:00
Eliza Weisman b8f63308d7 trace-core: Pass dispatcher by ref to dispatcher::with_default (#971)
* trace-core: Pass dispatcher by ref to `dispatcher::with_default`

As requested by @carllerche in https://github.com/tokio-rs/tokio/pull/966#discussion_r264380005, this branch changes the
`dispatcher::with_default` function in `tokio-trace-core` to take the
dispatcher by ref and perform the clone internally. This makes this
function more consistant with other `with_default` functions in other
crates.

Signed-off-by: Eliza Weisman <[email protected]>

* trace: Don't set the default dispatcher on entering a span

Setting the default dispatcher on span entry is a relic of when spans
tracked their parent's ID. At that time, it was necessary to ensure that
any spans created inside a span were observed by the same subscriber
that originally provided the entered span with an ID, as otherwise, new
spans would be created with parent IDs that did not originate from that
subscriber.

Now that spans don't track their parent ID, this is no longer necessary.
However, removing this behavior does mean that if a span is entered
outside of the subscriber context it was created in, any subsequent
spans will be observed by the current default subscriber and thus will
not be part of the original span's trace tree. Since subscribers are not
expected to change frequently, and spans are not expected to move
between them, this is likely acceptable.

I've removed the tests for the old behavior.

Note that this change improves the performance of span entry/exit fairly
significantly. Here are the results of running a benchmark that enters
a span, does nothing, and immediately exits it, before this change:

```
test enter_span              ... bench:          93 ns/iter (+/- 14)
```

...and after:

```
test enter_span              ... bench:          51 ns/iter (+/- 9)
```

Signed-off-by: Eliza Weisman <[email protected]>
2019-03-11 15:29:00 -07:00
Eliza Weisman c08e73c8d4 Introduce tokio-trace (#827)
<!-- Thank you for your Pull Request. Please provide a description above
and review the requirements below.

Bug fixes and new features should include tests.

Contributors guide:
https://github.com/tokio-rs/tokio/blob/master/CONTRIBUTING.md -->

## 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 <[email protected]>
2019-02-19 12:15:01 -08:00