OpenTelemetry supports a span kind as special metadata to spans. The
span kind defines relationships between spans (e.g. server vs client).
Some distributed tracing providers use this information to enrich their
UIs.
This makes it possible to set the span kind by adding a special
attribute called `otel.kind`, similar to the existing `otel.name`.
## Motivation
The documentation nearly put me off trying to use `tracing` at all. It
looks hard to set up and use, and the two problems I first ran into
(needing to output to stderr, and instrumenting a function with a
non-formattable arg) were not easy to find the right solutions for.
## Solution
This change rearranges the README a little to emphasise solutions,
rather than problems and extra details a first time user probably
doesn't need to care about yet.
* Start with the simple way of setting up a subscriber rather than
diving into the complex ways.
* Show the preferred method of instrumenting async code before
explaining why it is more complex and how it's implemented.
* Remove yak credit. Does anyone care?
* Further tweaks to README contents
Address @hawkw review comments. Opted for clearer wording in passages
joining examples together rather than extra reordering for now.
Co-authored-by: Eliza Weisman <eliza@buoyant.io>
I spent quite a large portion of my talk at Rusty days discussing
logging/structured logging/distributed tracing, covering our usage of `tracing`.
If you think it's relevant I'd be happy to add it to the list 😁
P.S. there were some trailing whitespaces that my VIM setup ruthlessly
eliminated. Let me know if you want me to leave them there.
* Add talk
* Use uniform format
Fixed
- Missing `fmt::Display` impl for `field::DisplayValue` causing a
compilation failure when the "log" feature is enabled (#887)
Thanks to @d-e-s-o for contributing to this release!
I wasn't able to reproduce the exact formatting issues seen on docs.rs
locally, though from some source inspection, this extra `</div>` appears
to be the culprit.
(hopefully) fixes#880
The `tracing-macros` crate uses internal `tracing` APIs that are
unstable. These APIs changed in 0.1.18 (not a breaking change, since
they are explicitly not stable API). `tracing-macros` needed to be
updated to use the new versions of the internal APIs.
As a side note, I'm surprised this wasn't caught before merging the
branch, and only happened on `master`. Are we not checking all crates
for PR builds? If so, we should probably fix that.
Signed-off-by: Eliza Weisman <eliza@buoyant.io>
### Fixed
- Fixed a bug where `LevelFilter::OFF` (and thus also the
`static_max_level_off` feature flag) would enable *all* traces,
rather than *none* (#853)
- **log**: Fixed `tracing` macros and `Span`s not checking
`log::max_level` before emitting `log` records (#870)
### Changed
- **macros**: Macros now check the global max level
(`LevelFilter::current`) before the per-callsite cache when
determining if a span or event is enabled. This significantly improves
performance in some use cases (#853)
- **macros**: Simplified the code generated by macro expansion
significantly, which may improve compile times and/or `rustc`
optimizatation of surrounding code (#869, #869)
- **macros**: Macros now check the static max level before checking any
runtime filtering, improving performance when a span or event is
disabled by a `static_max_level_XXX` feature flag (#868)
- `LevelFilter` is now a re-export of the `tracing_core::LevelFilter`
type, it can now be used interchangably with the versions in
`tracing-core` and `tracing-subscriber` (#853)
- Significant performance improvements when comparing `LevelFilter`s and
`Level`s (#853)
- Updated the minimum `tracing-core` dependency to 0.1.12 (#853)
### Added
- **macros**: Quoted string literals may now be used as field names, to
allow fields whose names are not valid Rust identifiers (#790)
- **docs**: Several documentation improvements (#850, #857, #841)
- `LevelFilter::current()` function, which returns the highest level
that any subscriber will enable (#853)
- `Subscriber::max_level_hint` optional trait method, for setting the
value returned by `LevelFilter::current()` (#853)
Thanks to new contributors @cuviper, @ethanboxx, @ben0x539, @dignati,
@colelawrence, and @rbtcollins for helping out with this release!
Signed-off-by: Eliza Weisman <eliza@buoyant.io>
### Fixed
- **docs**: Incorrect formatting (#862)
### Changed
- **filter**: `LevelFilter` is now a re-export of the
`tracing_core::LevelFilter` type, it can now be used interchangably
with the versions in `tracing` and `tracing-core` (#853)
- **filter**: Significant performance improvements when comparing
`LevelFilter`s and `Level`s (#853)
- Updated the minimum `tracing-core` dependency to 0.1.12 (#853)
### Added
- **filter**: `LevelFilter` and `EnvFilter` now participate in
`tracing-core`'s max level hinting, improving performance
significantly in some use cases where levels are disabled globally
(#853)
Signed-off-by: Eliza Weisman <eliza@buoyant.io>
## Motivation
Currently, every `tracing` macro generates a _new implementation_ of the
`Callsite` trait for a zero-sized struct created for that particular
callsite. This callsite accesses several statics defined in the macro
expansion.
This means that each tracing macro expands to a _lot_ of code — check
out the `cargo expand` output:
```
eliza on butterfly in tracing/examples on master [$?] is v0.0.0 via ⚙️ v1.44.0
:; cargo expand --example all-levels | wc -l
Checking tracing-examples v0.0.0 (/home/eliza/code/tracing/examples)
Finished check [unoptimized + debuginfo] target(s) in 0.20s
463
```
More code in the macro expansion means more code in the function
*invoking* the macro, which may make that function harder for `rustc` to
optimize. This effects the performance of *other* code in the function,
not the `tracing` code, so this isn't necessarily visible in `tracing`'s
microbenchmarks, which only contain `tracing` code.
In `rustc` itself, there is a small but noticeable performance impact
from switching from `log` to `tracing` even after making changes that
should make the filtering overhead equivalent:
https://github.com/rust-lang/rust/pull/74726#issuecomment-665247203.
This appears to be due to more complex generated code impacting
optimizer behavior.
## Solution
This branch moves the callsite generated by each macro out of the macro
expansion and into a single `MacroCallsite` private API type in the
`__macro_support` module. Instead of creating a zero-sized `Callsite`
static and multiple statics for the `Metadata`, the `Once` cell for
registration, and the `Interest` atomic, these are all now fields on the
`Callsite` struct. This shouldn't result in any real change, but makes
the implementation simpler. All the hot filtering functions on
`MacroCallsite` are `#[inline(always)]`, so we shouldn't be adding stack
frames to code that was previously generated in the macro expansion.
After making this change, the expanded output is about half as long
as it was before:
```
eliza on butterfly in tracing/examples on eliza/smaller-macros [$?] is v0.0.0 via ⚙️ v1.44.0
:; cargo expand --example all-levels | wc -l
Checking tracing-examples v0.0.0 (/home/eliza/code/tracing/examples)
Finished check [unoptimized + debuginfo] target(s) in 0.75s
233
```
This change appears to fix most of the remaining `rustc` performance
regressions:
https://github.com/rust-lang/rust/pull/74726#issuecomment-666865545
Additionally, it has some other side benefits. I imagine it probably
improves compile times a bit for crates using `tracing` (although I
haven't tested this), since the compiler is generating fewer callsite
implementations. Reducing the number of branches in the macro expansion
probably helps make the pesky `cognitive_complexity` Clippy lint show up
less often, and improves maintainability for the macros as well.
Signed-off-by: Eliza Weisman <eliza@buoyant.io>
Co-authored-by: David Barsky <me@davidbarsky.com>
### Added
- `LevelFilter` type and `LevelFilter::current()` for returning the
highest level that any subscriber will enable (#853)
- `Subscriber::max_level_hint` optional trait method, for setting the
value returned by `LevelFilter::current()` (#853)
### Fixed
- **docs**: Removed outdated reference to a Tokio API that no longer exists
(#857)
Thanks to new contributor @dignati for contributing to this release!
Signed-off-by: Eliza Weisman <eliza@buoyant.io>
## Motivation
In `tracing/macros.rs` `tracing_log!()` computes whether to log
differently from the log crate.
While the log crate checks for `lvl <= log::STATIC_MAX_LEVEL && lvl <=
log::max_level()`, tracing instead checks for `lvl <=
log::STATIC_MAX_LEVEL` and later the output of `logger.enabled()`. This
causes differences in what is being logged including unexpected log
output.
Since most of our testing has been with `env_logger`, we missed this
issue, since `env_logger` will also return `false` from its `enabled`
method for any records below the max level. However, other loggers may
not. Also, `enabled` is more expensive than checking the max level, so
this should result in better filtering performance for `log` records
emitted by tracing.
## Solution
This commit...fixes that.
Fixes#856
Signed-off-by: Eliza Weisman <eliza@buoyant.io>
This PR removes the `dispatcher::has_been_set` check from the
`level_enabled!` macro. We now check the static max level prior to
checking anything else, which avoids any atomic loads for callsites
disabled by the static max level. Also, checking the value of
`LevelFilter::current` should now be essentially equivalent to the
`dispatcher::has_been_set` check, since the default global max
`LevelFilter` is `OFF` when no dispatcher has been set. This means that
rather than doing *two* memory accesses if a callsite is disabled by the
global max level (one for the dispatcher set flag, and one for the max
level), we only do one memory access.
The `has_been_set` flag is also consumed by the `log` integration, for
determining whether to emit `log` records if "log-always" is not
enabled. We *could* probably replace that with a check if
`LevelFilter::current()` is `OFF`, but I dunno if this is necessary just
to remove that function. Also, we can't remove it from `tracing-core`,
since we want `tracing-core` to be backwards-compatible with previous
versions of `tracing`.
Signed-off-by: Eliza Weisman <eliza@buoyant.io>
## Motivation
Tracing currently stores cached filter evaluations in a per-callsite
cache. Once filters have been evaluated, this allows us to skip disabled
callsites with a single load and compare, which is a nice fast path for
skipping. However, determining the value to store in the callsite cache
is expensive: it requires acquiring a lock to register the callsite, and
asking the subscriber for an `Interest` value to cache.
In long-running applications, such as servers, daemons, and interactive
applications that are used for a long period of time, this cost is not
very visible; it's amortized over the rest of the application's
lifetime. However, in batch-oriented programs and CLI tools that run to
completion, the cost of building the initial cached value has a much
bigger impact. If a given callsite is hit twice over the thirty seconds
that a CLI tool runs for (for example), the cost of the initial
evaluation is _much_ more meaningful than if the same callsite is hit
hundreds of thousands of times by a server that runs for several weeks
before its restarted. Even in a long running application, though, it
could lead to a surprising latency hit if a given callsite is only hit
after a long period of operation.
Per-callsite caching allows high performance for more granular filters,
since it tracks the state of _every_ callsite; we still get a fast path
for skipping a `trace` event in the `foo::bar` module if the `trace`
level is only enabled for the `baz` module. Because of this, we didn't
initially believe that a global maximum level fast path was necessary.
However, in `rustc`, it turns out that the cost of just building the
callsite cache for the first time has a noticeable impact on
performance. See here for details:
https://github.com/rust-lang/rust/pull/74726#issuecomment-664181180
## Solution
This branch adds a faster fast path for skipping callsites whose level
is higher than the highest level enabled for _any_ target/metadata
combination, similar to the `log` crate's `max_level`.
Unlike the `log` crate, which only ever has a single global logger,
`tracing` allows multiple `Subscriber`s to coexist in the same process.
Therefore, our implementation is somewhat different than `log`'s. We
can't simply provide a `set_max_level` function call, because _another_
subscriber may have already set a lower max level, and just overwriting
the max level with ours may result in diagnostics being skipped that
another subscriber wants to collect.
Instead, we've added a `max_level_hint` method to the `Subscriber`
trait, returning an `Option<LevelFilter>`. By default, this returns
`None`, for backwards compatibility. However, if it returns `Some`, the
resulting `LevelFilter` is stored in a global `MAX_LEVEL` atomic. This
method is called by the `register_dispatch` function, which handles the
creation of a new `Dispatch`. This allows us to compare the max level
from a new subscriber with those of all other currently active
subscribers. Similarly, when cached interests are invalidated (such as
by changing a filter, or when a `Subscriber` is dropped), we can
reevaluate the max level.
The path for _checking_ the max level (e.g. in the macros) should be
very efficient. We load the atomic, convert the `usize` value into a
`LevelFilter`, and compare it to the callsite's level. With help from
@eddyb, I was able to implement the conversion such that it should
hopefully be an identity conversion in release mode, rather than
requiring rustc to generate a LUT. The macros have been updated to check
the max level before anything requiring hitting the callsite cache _or_
the subscriber TLS var.
Also, I've updated `tracing` and `tracing-subscriber` to reexport the
`LevelFilter` type from `tracing-core` rather than defining their own.
The API should be a superset of those crates' versions.
Thanks to @oli-obk for uncovering this issue when adding `tracing` to
`rustc`, and for doing a lot of the preliminary analysis of the cause!
So far, there doesn't appear to be a significant change in any of `tracing`'s
internal benchmarks on this branch. However, my guess is that this is
because of `criterion`'s outlier elimination: since the cache is constructed
only on the first iteration, it's pretty likely that `criterion` considers this an
outlier and throws it out entirely, so the benchmark results on master don't
include the cost of evaluating the filter for the initial time.
Incidentally, this PR also fixes a bug in the `tracing` crate's version
of `LevelFilter`, where the `OFF` level actually enabled *everything*,
rather than *nothing*. Oopsie!
Signed-off-by: Eliza Weisman <eliza@buoyant.io>
It turns out that the test run with `--all-features` should never be
able to pass, due to the `static_max_level` features. Setting
`--all-features` will enable `static_max_level_off`, which disables all
tracing. Therefore, all the integration tests will fail.
However, due to a bug in `tracing`'s `LevelFilter::OFF` implementation,
`static_max_level_off` actually _enables_ everything. This makes the
tests pass accidentally. If we fix this bug, though, everything will be
disabled, as it should be, causing the tests to fail. Therefore, we
can't merge a PR that fixes this, like #853, without first resolving the
issues with the tests.
Unfortunately, these are integration tests, so we cannot just put
```rust
#[cfg(not(any(feature = "static_max_level_off", feature = ...))]
```
on the tests to skip them when the feature is set --- features set on
the _crate_ being tested are not visible to integration tests.
Similarly, we cannot use
```rust
#[cfg(test)]
```
to not set the max level when running the tests, because the test cfg is
not set for the crate when running integration tests, only unit tests.
We could change all these tests to be integration tests, I suppose.
However, we are already running a `cargo hack` job that tests every
feature combination for `tracing` _except_ for the `static_max_level`
ones, so I think it's fine to just remove this.
Signed-off-by: Eliza Weisman <eliza@buoyant.io>
## Motivation
Some opentracing systems use fields with : in the names, which are not
legal rust identifiers. We could special case :, but then we have
complicated double-nested patterns (repeated idents separated by : and a
nested repeat separated by .), and this may by a case of always being
one-step-behind as more cases turn up; so this patch instead just gets
in front and lets users put in whatever they want: as they are not rust
identifiers, they miss out on some niceness.
## Solution
This permits : in field names but also potentially anything
stringifiable, which may be overly liberal.
Signed-off-by: Robert Collins <robert.collins@cognite.com>
## Motivation
I'd like to get more feedback on our [`tracing-wasm` crate][1], as well as
improve its discoverability.
[1]: https://crates.io/crates/tracing-wasm
## Solution
Add a link to the crate to the "Related Crates" section of the readme file.
## Motivation
some of the links in the readme don't work or go to the wrong targets
## Solution
* the `closing` link needs another `tracing/` in the path
* the `#[instrument]` link apparently can't have `#[ ]`
* `tracing-core` shouldn't be another link to `tracing`
* avoid duplicate link targets for contained crates
## Motivation
The pull request template link was not pointing to the pull request template.
## Solution
Give the issue template and pull request template links different names.
## Motivation
From the readme
> (if you're the maintainer of a tracing ecosystem crate not in this list, please let us know!)
## Solution
Added link to tide-tracing on readme and doc comment.
### Fixed
- **fmt**: Fixed compilation failure on MSRV when the `chrono` feature
is disabled (#844)
### Added
- **fmt**: Span lookup methods defined by `layer::Context` are now also
provided by `FmtContext` (#834)
## Motivation
The MIT license states:
> The above copyright notice and this permission notice
> shall be included in all copies or substantial portions
> of the Software.
## Solution
Therefore the LICENSE files should be present in each crate directory,
so they are included with `cargo publish`.
The datetime implementation added in 0.2.8 uses `i64::MAX` and
`i32::MAX`, which were added in Rust 1.43.0. This is not compliant with
our current MSRV, 1.39.
This PR fixes this by switching to `std::i64::MAX` and `std::i32::MAX`.
Fixes#840
### Changed
- **log**: Moved verbose span enter/exit log records to
"tracing::span::active" target, allowing them to be filtered
separately (#833)
- **log**: All span lifecycle log records without fields now have the
`Trace` log filter, to guard against `log` users enabling them by
default with blanket level filtering (#833)
### Fixed
- **log**/**macros**: Fixed missing implicit imports of the
`tracing::field::debug` and `tracing::field::display` functions inside
the macros when the "log" feature is enabled (#835)
## Motivation
When the `log` feature is enabled, the expressions provided for field
values are passed into two separate macros: one which prepares the
`tracing` structured value set that is used to construct the `tracing`
event, and another which formats a textual message to send to `log`, if
emitting a `log` record for the event is enabled. The issue is that the
macro that generates the `tracing` value set generates a block
containing an import for `tracing::field::debug` and
`tracing::field::display`, while the block generated by the `log`
message formatting macro does not import those functions. Therefore, the
block where the `log` message is formatted fails to compile, since the
functions are not present in the scope it expands to.
It turns out this is not, in fact, an accidental breaking change in
0.1.16 as was suspected, but a long-standing bug that has existed since
commit 76b5e80405, which predates
`tracing` 0.1.0. This issue existed as far back as when the library was
still called `tokio-trace`!
However, the issue only exists when the `log` feature flag is enabled
--- and it's disabled by default. The bug hadn't caused any issues in
the past, since use of the `log` feature flag was not widespread enough
to be coincident with an instance of someone relying on the
implicitly-imported function names. The breakage happened specifically
because `hyper` 0.13.7 enables `tracing`'s `log` feature by default, so
_everyone_ depending on `hyper` suddenly had that feature enabled ---
now, the set of people enabling the `log` feature is suddenly _much_
larger!
## Solution
This branch adds the missing imports in the `__tracing_mk_format_args!`
helper macro, which generates the `log` format args.
I've also added uses of `debug` and `display` without imports to the
tests for the `log` feature flag, which don't compile prior to the fix.
Fixes#820 (for real, this time!)
## Motivation
Currently, `fmt::FmtContext` _only_ exposes a way to iterate over all
spans in the current context. It doesn't publicly expose any of the
other `layer::Context` methods, although they provide more useful
querying functionality.
The in-crate implementations of the default formatters _do_ use some of
these other methods on `Context`, by accessing the private `Context`
field on `FmtContext`. Not having access to these methods externally
makes many `FormatEvent` implementations in other crates more difficult,
if not impossible.
## Solution
This branch adds forwarding impls of the missing methods.
Signed-off-by: Eliza Weisman <eliza@buoyant.io>
## Motivation
Adding myself to contributors list so I get tagged on tracing-appender PRs
## Solution
Update CODEOWNERS file
Co-authored-by: Zeki Sherif <zekshi@amazon.com>
Co-authored-by: Eliza Weisman <eliza@buoyant.io>
## Motivation
Currently, `tracing`'s `log` feature emits log records for creating,
entering, exiting, and dropping a `Span` at the `log` equivalent of that
span's `tracing` level. If the span has any fields, the span creation
logs are sent to the same target that the span would have, since the
fields provide high-value information that users enabling that target
will probably want to see. However, the other events for entering,
exiting, and dropping a span do not include fields, and are much more
verbose, so they are sent to a special `tracing::span` target. This
allows them to be filtered independently, and only enabled when needed.
However, some `log` users have noted that when using _blanket_ `log`
filters, like setting the level to `info` globally, the more verbose
activity logs will still be enabled for spans whose level matches. This
can be annoying.
## Solution
Therefore, this branch changes the span activity and lifecycle logs to
_always_ have the `Trace` `log` level, even when the span that generated
them has a less-verbose level. When fields are recorded, the emitted log
records are sent to the span's target instead, since users probably want
this information if they have enabled the span's level for its target.
Additionally, I've added a sub-target of `tracing::span` for the
enter/exit logs in particular (`tracing::span::active`). This allows
them to be filtered independently of the less frequent creation/drop
logs.
Signed-off-by: Eliza Weisman <eliza@buoyant.io>
Now that the new https://tokio.rs is live, we can add the new Tracing
logo to the RustDoc!
I also added a couple missing `html_root_url` attributes in published
crates.
Signed-off-by: Eliza Weisman <eliza@buoyant.io>
This reverts commit e3b3a3acb1.
This change was accidentally semver-incompatible, as user code was able
to use the imported `debug` and `display` functions without adding an
import outside the macro. Although this was not documented, downstream
code relied on these names being available, so this resulted in a
breaking change in a point release.
Fixes#820
### Added
- **rolling**: `minutely` rotation schedule to rotate the log file once
every minute (#748)
### Fixed
- Fixed broken links in docs (#718)
- `tracing-appender` now only enables the necessary
`tracing-subscriber`'s feature flags, rather than all of them (#779)
Thanks to new contributors @ericjheinz and @sourcefrog for contributing
to this release!
Signed-off-by: Eliza Weisman <eliza@buoyant.io>
### Changed
- **fmt**: When the `chrono` dependency is enabled, the `SystemTime`
timestamp now emits human-readable timestamps rather than using
`SystemTime`'s fmt::Debug`implementation (`chrono` is still required
for customized timestamp formatting) (#807)
- **ansi**: Updated `ansi_term` dependency to 0.12 (#816)
### Added
- **json**: `with_span_list` method to configure the JSON formatter to
include a list of all spans in the current trace in formatting events
(similarly to the text formatter) (#741)
- **json**: `with_current_span` method to configure the JSON formatter
to include a field for the _current_ span (the leaf of the trace) in
formatted events (#741)
- **fmt**: `with_thread_names` and `with_thread_ids` methods to
configure `fmt::Subscriber`s and `fmt::Layer`s to include the thread
name and/or thread ID of the current thread when formatting events
(#818)
Thanks to new contributors @mockersf, @keetonian, and @Pothulapati for
contributing to this release!
## Motivation
Fixes#809
## Solution
This PR adds two new methods i.e `with_thread_ids` and
`with_thread_names` to the fmt Layer which passed till
the pre-configured Format type, where the check is performed
and these the above values are formatted based on the flags.
The formatting is done by creating to new Types that impl Display
for Id and Name. For Thread Name, we keep track of the max length
of the thread name that occured till now using a thread safe static
type and pad accordingly. For Thread Id, we pad directly with 2
as in most cases we would see a double digit number of threads.
Signed-off-by: Tarun Pothulapati <tarunpothulapati@outlook.com>
## Motivation
This commit fixes name clashes that occurred inside of tracing macros when
values with the names `display`, `Value` and `debug` have been used.
This allows library users to trace variables that have the same name as imported
types inside the `tracing::field` module.
## Solution
Use fully qualified type names for types used inside the `tracing::field`
module.
Fixes#805.
