core: add faster fast path for level filtering #853

hawkw · 2020-07-27T22:22:42Z

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:
rust-lang/rust#74726 (comment)

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 Subscribers 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!

tracing-core/src/metadata.rs

hawkw · 2020-07-28T21:57:58Z

Definitely seeing a noticeable improvement in our filtering benchmarks:

Note that the tests for enabled events show less change, because actually recording the event takes up a majority of the time in those tests, but it's still visible. Also, the bench environment is probably a bit noisy.

hawkw · 2020-07-28T22:30:44Z

Oh, cool update: looks like the reason the cargo test --all-features CI step is failing is because...the previous version of LevelFilter::OFF in tracing was broken since day 1. It turns out that it compares less than everything, rather than nothing --- the tests should have always been broken with --all-features, since static_max_level_off should always be enabled. Instead, this PR fixes it, and now all the tests are failing.

We should probably either skip these tests when any static_max_level_xxx feature is set, or disable the static max level when cfg(test) is set.

hawkw · 2020-07-29T00:41:31Z

Ugh...changes to the CI config will only actually change anything when merged to master...so we should merge 0ededf6 separately, or else this will never pass CI.

The tests currently only pass with --all-features due to a bug on master and fixing that bug will break the tests with --all-features...

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 <[email protected]>

tracing-core/src/dispatcher.rs

tracing-core/src/metadata.rs

tracing-subscriber/src/layer.rs

tracing/src/macros.rs

hawkw · 2020-07-30T16:32:51Z

tracing/test_static_max_level_features/tests/test.rs

@@ -33,7 +33,7 @@ impl Subscriber for TestSubscriber {
    fn exit(&self, _span: &Id) {}
 }

-#[cfg(test)]
+#[test]


this test was never actually running 🙃

hawkw · 2020-07-30T16:37:05Z

tracing-core/src/metadata.rs

+    /// Returns a `LevelFilter` that matches the most verbose [`Level`] that any
+    /// currently active [`Subscriber`] will enable.
+    #[inline(always)]
+    pub fn max() -> Self {


Interesting fact: log has a LevelFilter::max with the same signature that returns a totally different thing. Maybe we should rename this to avoid confusing users familiar with the log API...

I am not really sure if there's all that much value in having a method for returning the highest possible level filter, when users can just write TRACE...but maybe people are doing that. Also, I would have probably called that function all(), but, whatever...

@davidbarsky @LucioFranco any thoughts on the API naming before I merge this PR?

tracing-core/src/dispatcher.rs

tracing-core/src/metadata.rs

davidbarsky · 2020-07-30T16:57:13Z

tracing-core/src/subscriber.rs

+    /// determine the most verbose level that will be enabled. This will allow
+    /// spans and events which are more verbose than that level to be skipped
+    /// more efficiently. Subscribers which perform filtering are strongly


I never liked "verbosity" when applied to levels, but... I guess that ship sailed. I was always confused by what it meant.

If there's another wording you think is clearer, I'm all ears! If we're going to change it, we should change it throughout the docs.

davidbarsky · 2020-07-30T16:57:38Z

tracing/test_static_max_level_features/tests/test.rs

@@ -33,7 +33,7 @@ impl Subscriber for TestSubscriber {
    fn exit(&self, _span: &Id) {}
 }

-#[cfg(test)]
+#[test]


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

Co-authored-by: bjorn3 <[email protected]>

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

hawkw · 2020-07-30T19:32:39Z

FWIW, it looks like this change results in a pretty significant performance impact for rustc, so I would really like to move forward with getting it merged as soon as practical (cc @tokio-rs/tracing).

LucioFranco

LGTM!

tracing-subscriber/src/layer.rs

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

@dignati

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 <[email protected]>

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 <[email protected]>

@dignati

### 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 <[email protected]>

@cuviper

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 <[email protected]>

### 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 <[email protected]>

@cuviper

### 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 <[email protected]>

This picks up upstream changes tokio-rs/tracing#853, tokio-rs/tracing#868, and tokio-rs/tracing#869 which improve performance in some use cases. The overhead removed by these changes may already be amortized enough in the proxy that it's not a problem, but it seems worth picking up regardless.

This picks up upstream changes tokio-rs/tracing#853, tokio-rs/tracing#868, and tokio-rs/tracing#869 which improve performance in some use cases. The overhead removed by these changes may already be amortized enough in the proxy that it's not a problem, but it seems worth picking up regardless. Signed-off-by: Eliza Weisman <[email protected]>

hawkw requested a review from a team as a code owner July 27, 2020 22:22

hawkw mentioned this pull request Jul 27, 2020

Move from log to tracing rust-lang/rust#74726

Merged

bjorn3 reviewed Jul 28, 2020

View reviewed changes

tracing-core/src/metadata.rs Outdated Show resolved Hide resolved

oli-obk reviewed Jul 28, 2020

View reviewed changes

tracing-core/src/metadata.rs Show resolved Hide resolved

This was referenced Jul 29, 2020

Tracing std::io::err performance #859

Open

chore: remove all-features tests that can't actually pass #863

Merged

hawkw commented Jul 30, 2020

View reviewed changes

tracing-core/src/dispatcher.rs Show resolved Hide resolved

tracing-core/src/dispatcher.rs Show resolved Hide resolved

tracing-core/src/metadata.rs Outdated Show resolved Hide resolved

tracing-subscriber/src/layer.rs Show resolved Hide resolved

tracing/src/macros.rs Show resolved Hide resolved

hawkw commented Jul 30, 2020

View reviewed changes

davidbarsky reviewed Jul 30, 2020

View reviewed changes

hawkw and others added 16 commits July 30, 2020 09:59

core: add LevelFilter and global max level hinting

5e5963f

subscriber: add global level hinting

6b20035

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

tracing: check max level hinting to skip callsites

54b9e75

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

fix backwards cmp

4a794c2

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

add hinting to envfilter

2f27821

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

turns out cmp::max "just does that"

3c3466c

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

allow hints to return Off

65edff3

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

core: optimize Level/LevelFilter comparisons

a8b10dc

fix wrong compare

1ee16e0

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

add tests for level filters

51b24fe

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

Update tracing-core/src/metadata.rs

f0b85fc

Co-authored-by: bjorn3 <[email protected]>

fixy

8da526a

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

fix static max level test...not being a test

58bbe5d

panic safely in debug mode

560da82

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

fix std sometimes not existing

157c326

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

actually that doesn't work

2b78c07

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

Update tracing-core/src/dispatcher.rs

fec251d

hawkw force-pushed the eliza/global-max branch from c01d9c3 to fec251d Compare July 30, 2020 17:01

LucioFranco approved these changes Jul 30, 2020

View reviewed changes

tracing-subscriber/src/layer.rs Show resolved Hide resolved

hawkw added 3 commits July 30, 2020 14:06

update changelogs

196835a

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

update docs

02b2fbe

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

Rename LevelFilter::max -> LevelFilter::current

6cdcf58

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

hawkw merged commit 61b08de into master Jul 30, 2020

hawkw mentioned this pull request Jul 31, 2020

core: prepare to release 0.1.12 #871

Merged

hawkw mentioned this pull request Jul 31, 2020

subscriber: prepare to release 0.2.10 #872

Merged

hawkw mentioned this pull request Jul 31, 2020

tracing: prepare to release 0.1.18 #873

Merged

hawkw mentioned this pull request Jul 31, 2020

trace: roll tracing and tracing-subscriber dependencies linkerd/linkerd2-proxy#615

Merged

mystor mentioned this pull request Aug 20, 2020

RFC: C client API for tracing-core #948

Open

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

core: add faster fast path for level filtering #853

core: add faster fast path for level filtering #853

hawkw commented Jul 27, 2020 •

edited

Loading

hawkw commented Jul 28, 2020

hawkw commented Jul 28, 2020

hawkw commented Jul 29, 2020

hawkw Jul 30, 2020

davidbarsky Jul 30, 2020

hawkw Jul 30, 2020

hawkw Jul 30, 2020

davidbarsky Jul 30, 2020

hawkw Jul 30, 2020

davidbarsky Jul 30, 2020

hawkw commented Jul 30, 2020

LucioFranco left a comment

core: add faster fast path for level filtering #853

core: add faster fast path for level filtering #853

Conversation

hawkw commented Jul 27, 2020 • edited Loading

Motivation

Solution

hawkw commented Jul 28, 2020

hawkw commented Jul 28, 2020

hawkw commented Jul 29, 2020

hawkw Jul 30, 2020

Choose a reason for hiding this comment

davidbarsky Jul 30, 2020

Choose a reason for hiding this comment

hawkw Jul 30, 2020

Choose a reason for hiding this comment

hawkw Jul 30, 2020

Choose a reason for hiding this comment

davidbarsky Jul 30, 2020

Choose a reason for hiding this comment

hawkw Jul 30, 2020

Choose a reason for hiding this comment

davidbarsky Jul 30, 2020

Choose a reason for hiding this comment

hawkw commented Jul 30, 2020

LucioFranco left a comment

Choose a reason for hiding this comment

hawkw commented Jul 27, 2020 •

edited

Loading