Commit Graph
8 Commits
Author SHA1 Message Date
Eliza Weismanandcsmoe 847fb59b17 trace-core: Introduce callsite classification in metadata (#1046)
## Motivation

To ease the implementation of `Subscriber::register_callsite`, a field
should be added to `Metadata` to indicate if this callsite is an event or
a span.

## Solution

A new struct, `Kind`, is added to the `metadata` module in
`tokio-trace-core`, and a `Kind` field is added to the `Metadata`
struct. Macros which construct `metadata` now require a `Kind`.

`Kind` is represented as a struct with a private inner enum to allow new
`Kind`s to be added without breaking changes. However, the _addition_ of
the kind field _is_ a breaking change. While this could be done in a
backward-compatible way, it would permit the construction of metadata
with unknown kinds, and since the next `tokio-trace-core` release will
be a breaking change, I opted to make the breaking change instead.

New API tests for the `callsite!` and `metadata!` macros have been added
to guard against future API breakage.

Fixes: #986
Closes: #1008

Co-Authored-By: csmoe <[email protected]>
2019-04-11 11:56:42 -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
Eliza Weisman 44f65afcc6 trace: Allow field names to be separated by .s (#1027)
## Motivation

In order to support conventions that add namespacing to `tokio-trace`
field names, it's necessary to accept at least one type of separator
character. Currently, the `tokio-trace` macros only accept valid Rust
identifiers, so there is no clear separator character for namespaced
conventions. See also #1018.

## Solution

This branch changes the single `ident` fragment matcher for field names
to match *one or more* `ident` fragments separated by `.` characters.

## Notes

The resulting key is still exposed to `tokio-trace-core` as a string
constant created by stringifying the dotted expression. However, if
`tokio-trace-core` were later to adopt a first class notion of
hierarchical field keys, we would be able to track that change in
`tokio-trace` as an implementation detail.

Closes #1018.
Closes #1022.

Signed-off-by: Eliza Weisman <[email protected]>
2019-04-03 14:44:11 -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 d8177f81ac trace: Allow trace instrumentation to emit log records (#992)
## Motivation

`tokio-trace` currently offers a strategy for compatibility with the
`log` crate: its macros can be dropped in as a replacement for `log`'s
macros, and a subscriber can be used that translates trace events to log
records. However, this requires the application to be aware of
`tokio-trace` and manually set up this subscriber.

Many libraries currently emit `log` records, and would like to be able
to emit `tokio-trace` instrumentation instead. The `tokio` runtimes are
one such example. However, with the current log compatibility strategy,
replacing existing logging with trace instrumentation would break
`tokio`'s logs for any downstream user which is using only `log` and not
`tokio-trace`. It is desirable for libraries to have the option to emit
both `log` _and_ `tokio-trace` diagnostics from the same instrumentation
points.

## Solution

This branch adds a `log` feature flag to the `tokio-trace` crate, which
when set, causes `tokio-trace` instrumentation to emit log records as well
as `tokio-trace` instrumentation. 

## Notes

In order to allow spans to log their names when they are entered and 
exited even when the span is disabled, this branch adds an 
`&'static Metadata` to the `Span` type. This was previously stored in
the `Inner` type and was thus only present when the span was enabled.
This makes disabled spans one word longer, but enabled spans remain
the same size.

Fixes: #949

Signed-off-by: Eliza Weisman <[email protected]>
2019-03-26 16:43:05 -07:00
Son 1524ee4b60 trace: Add static level filtering (#987)
## Motivation

`tokio-trace` should have static verbosity level filtering, like the
`log` crate. The static max verbosity level should be controlled at
compile time with a set of features. It should be possible to set a
separate max level for release and debug mode builds.

## Solution

We can do this fairly similarly to how the `log` crate does it:
`tokio-trace` should export a constant whose value is set based on the
static max level feature flags. Then, we add an if statement to the
`span!` and `event!` macros which tests if that event or span's level
is enabled.

Closes #959
2019-03-25 15:19:20 -07:00
Eliza Weisman 4313d65b38 trace: Switch to using local_inner_macros for instrumentation API (#969)
## Motivation

Currently, it isn't possible to import individual macros from
`tokio-trace` using the macros 1.2 syntax:

```rust
use tokio_trace::{debug, info, span};
```

This is because these macros require that `callsite` and `enabled` are
imported as well.

## Solution

This branch resolves the problem by adding the [`local_inner_macros`]
attribute to the instrumentation API's macros. This allows other macros
from within the crate to be used without requiring them to be explicitly
imported. 

However, this also requires duplicating any macros from other sources
(such as std and `tokio-trace-core`) with wrappers due to the behaviour
of `local_inner_macros`. I've added these wrapper macros as well.

Since the macros got even longer as a result of this, I've moved them
to a separate file to make `lib.rs` easier to read. I've also wrapped
some very long lines in the macros, and removed the explicit drop of
the result of evaluating some event macros (it's no longer necessary
as all event macros now evaluate to `()`).

[`local_inner_macros`]: https://doc.rust-lang.org/nightly/edition-guide/rust-2018/macros/macro-changes.html#local-helper-macros

Fixes #968

Signed-off-by: Eliza Weisman <[email protected]>
2019-03-11 14:48:23 -07:00