Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

core: fix incorrect max level filter calculation #908

Merged
merged 11 commits into from
Aug 10, 2020
Merged

core: fix incorrect max level filter calculation #908

merged 11 commits into from
Aug 10, 2020

Conversation

hawkw
Copy link
Member

@hawkw hawkw commented Aug 8, 2020

Motivation

Currently, when rebuilding the interest cache, the max level is
calculated by tracking a max level, and comparing it with each active
Subscriber's max level hint, and setting the max value to the hint if
the hint is higher than the current value.

This is correct. However, the max level in this calculation starts at
TRACE. This means that regardless of what any subscriber returns for
its hint, after rebuilding the interest cache, the max level will
always be TRACE. This is wrong — it means that the fast path will
not be taken in may cases where it should be.

The max level calculation was started at TRACE rather than OFF,
because when this code was written with it starting at OFF, all the
tests broke, because the test subscribers don't provide hints. This was
the incorrect solution to that problem, however. This caused the tests
to break because we were ignoring all None hints, and not changing
the current max value when a subscriber returns None. This means that
if all subscribers returned None for their max level hint, the max
would remain OFF. However, what we should have done is assume that
if a subscriber doesn't provide a hint, it won't be filtering based on
levels, and assume that the max level is TRACE for that subscriber.

Whoopsie!

Solution

Now, the max level should be calculated correctly for subscribers that
do provide hints, and should still be TRACE if a subscriber does not
have a hint.

I've also added new tests to ensure that the global max level filter is
used when provided, by asserting that enabled is not called with spans
that would be excluded by the max level. These tests fail on master, but
pass after this change.

Additionally, note that fixing this bug revealed a separate issue in
tracing-subscriber's implementation of max_level_hint for
EnvFilter. When the EnvFilter includes directives that filter on
span field values, it will enable all spans with fields with that name,
so that events within the span can be enabled up to the filtering
directive's level. This may not be the ideal behavior, but it's what
we're doing currently, and we have tests for it. Therefore, it was
necessary to change the max_level_hint implementation to take this
into account by always returning TRACE when there are field value
filters.

That means that this branch requires #907 order for the
tracing-subscriber tests to pass.

Fixes: #906

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

@hawkw
tracing: add tests for max level hints
631d424 
Signed-off-by: Eliza Weisman <eliza@buoyant.io>
@hawkw
tracing: add tests for max level hints
c28105e 
Signed-off-by: Eliza Weisman <eliza@buoyant.io>
@hawkw
core: fix incorrect max level calculation
bc344a7 
Currently, when rebuilding the interest cache, the max level is
calculated by tracking a max level, and comparing it with each active
`Subscriber`'s max level hint, and setting the max value to the hint if
the hint is higher than the current value.

This is correct. However, the max level in this calculation starts at
`TRACE`. This means that regardless of what any subscriber returns for
its hint, after rebuilding the interest cache, the max level will
*always* be `TRACE`. This is wrong.

The max level calculation was started at `TRACE` rather than `OFF`,
because when this code was written with it starting at `OFF`, all the
tests broke, because the test subscribers don't provide hints. This was
the incorrect solution to that problem, however. This caused the tests
to break because we were *ignoring* all `None` hints, and not changing
the current max value when a subscriber returns `None`. This means that
if all subscribers returned `None` for their max level hint, the max
would remain `OFF`. However, what we *should* have done is assume that
if a subscriber doesn't provide a hint, it won't be filtering based on
levels, and assume that the max level is `TRACE` for that subscriber.

Now, the max level should be calculated correctly for subscribers that
*do* provide hints, and should still be `TRACE` if a subscriber does not
have a hint.

Whoopsie!

Signed-off-by: Eliza Weisman <eliza@buoyant.io>
@hawkw
fix wrong test
c9d39f9 
Signed-off-by: Eliza Weisman <eliza@buoyant.io>
@hawkw
subscriber: fix level hint not considering value filters
e1c8642 
This fixes an issue with `EnvFilter`'s `max_level_hint` not considering
that span field value filters may enable *any* span, regardless of the
level enabled inside that span. This is because the field value must be
recorded to be known.

We may wish to change this behavior to only check spans up to the
selected level, but this isn't what it does currently. This branch fixes
the wrong max level hint.

This bug was not caught due to an issue where hinting was too
permissive, but fixing that bug uncovers this issue.

Signed-off-by: Eliza Weisman <eliza@buoyant.io>
@hawkw
Merge branch 'eliza/fix-field-filter-hints' into eliza/fix-max-level
0fc7946
@hawkw
subscriber: fix level hint not considering value filters
a88b955 
This fixes an issue with `EnvFilter`'s `max_level_hint` not considering
that span field value filters may enable *any* span, regardless of the
level enabled inside that span. This is because the field value must be
recorded to be known.

We may wish to change this behavior to only check spans up to the
selected level, but this isn't what it does currently. This branch fixes
the wrong max level hint.

This bug was not caught due to an issue where hinting was too
permissive, but fixing that bug uncovers this issue.

Signed-off-by: Eliza Weisman <eliza@buoyant.io>
@hawkw
Merge branch 'eliza/fix-field-filter-hints' into eliza/fix-max-level
258e042 
Signed-off-by: Eliza Weisman <eliza@buoyant.io>
@hawkw hawkw requested a review from a team as a code owner August 8, 2020 20:07
@hawkw hawkw self-assigned this Aug 8, 2020
@hawkw hawkw added crate/core Related to the `tracing-core` crate kind/bug Something isn't working labels Aug 8, 2020
@hawkw
fix tests that require std
5d23a66 
Signed-off-by: Eliza Weisman <eliza@buoyant.io>
yaahc
yaahc approved these changes Aug 10, 2020
View reviewed changes
Copy link
Collaborator

@yaahc yaahc left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM and the explanation is great, a little confused on how the tests are working so I have one question about that but I doubt its a blocker.

tracing/tests/max_level_hint.rs Show resolved Hide resolved
tracing/tests/max_level_hint.rs Show resolved Hide resolved
@hawkw
add comments explaining tests
cabca0d 
Signed-off-by: Eliza Weisman <eliza@buoyant.io>
@hawkw hawkw mentioned this pull request Aug 10, 2020
Merged
@hawkw hawkw merged commit 52254eb into master Aug 10, 2020
@hawkw hawkw deleted the eliza/fix-max-level branch August 10, 2020 20:10
hawkw added a commit that referenced this pull request Aug 10, 2020
@hawkw
core: prepare to release 0.1.14
f47de6e 
Fixed

- Incorrect calculation of global max level filter which could result in
  fast filtering paths not being taken (#908)
@hawkw hawkw mentioned this pull request Aug 10, 2020
Merged
hawkw added a commit that referenced this pull request Aug 10, 2020
@hawkw
core: prepare to release 0.1.14 (#912)
6361e89 
### Fixed

- Incorrect calculation of global max level filter which could result in
  fast filtering paths not being taken (#908)
hawkw added a commit that referenced this pull request Aug 10, 2020
@hawkw
tracing: prepare to release 0.1.19
f9808e3 
Fixed

- Updated `tracing-core` to fix incorrect calculation of the global max
  level filter (#908)

Added

- **attributes**: Support for using `self` in field expressions when
  instrumenting `async-trait` functions (#875)
- Several documentation improvements (#832, #881, #896, #897, #911,
  #913)

Thanks to @anton-dutov, @nightmared, @mystor, and @toshokan for
contributing to  this release!
@hawkw hawkw mentioned this pull request Aug 10, 2020
Merged
hawkw added a commit that referenced this pull request Aug 11, 2020
@hawkw
tracing: prepare to release 0.1.19 (#915)
1b5bfa0 
### Fixed

- Updated `tracing-core` to fix incorrect calculation of the global max
  level filter (#908)

### Added

- **attributes**: Support for using `self` in field expressions when
  instrumenting `async-trait` functions (#875)
- Several documentation improvements (#832, #881, #896, #897, #911,
  #913)

Thanks to @anton-dutov, @nightmared, @mystor, and @toshokan for
contributing to  this release!

Signed-off-by: Eliza Weisman <eliza@buoyant.io>
hawkw added a commit to linkerd/linkerd2-proxy that referenced this pull request Aug 11, 2020
@hawkw
trace: update tracing dependencies
4e40665 
This branch makes the following dependency updates:
```
:; cargo update -p tracing -p tracing-core -p tracing-subscriber -p tokio-trace
    Updating crates.io index
    Updating git repository `https://github.com/hawkw/tokio-trace`
    Updating regex v1.2.1 -> v1.3.9
    Updating regex-syntax v0.6.11 -> v0.6.18
    Updating thread_local v0.3.6 -> v1.0.1
    Updating tracing v0.1.18 -> v0.1.19
    Updating tracing-attributes v0.1.9 -> v0.1.10
    Updating tracing-core v0.1.12 -> v0.1.14
    Updating tracing-subscriber v0.2.10 -> v0.2.11
```

In particular, the `tracing-core` update picks up upstream change
tokio-rs/tracing#908, which fixes a bug where filtering would fail to
take the fastest fast path in many cases. This time, there's a small,
but actually noticeable, latency reduction in the proxy benchmarks.

Signed-off-by: Eliza Weisman <eliza@buoyant.io>
@hawkw hawkw mentioned this pull request Aug 11, 2020
Merged
hawkw added a commit to linkerd/linkerd2-proxy that referenced this pull request Aug 11, 2020
@hawkw
trace: update tracing dependencies (#623)
61932ae 
This branch makes the following dependency updates:
```
:; cargo update -p tracing -p tracing-core -p tracing-subscriber -p tokio-trace
    Updating crates.io index
    Updating git repository `https://github.com/hawkw/tokio-trace`
    Updating regex v1.2.1 -> v1.3.9
    Updating regex-syntax v0.6.11 -> v0.6.18
    Updating thread_local v0.3.6 -> v1.0.1
    Updating tracing v0.1.18 -> v0.1.19
    Updating tracing-attributes v0.1.9 -> v0.1.10
    Updating tracing-core v0.1.12 -> v0.1.14
    Updating tracing-subscriber v0.2.10 -> v0.2.11
```

In particular, the `tracing-core` update picks up upstream change
tokio-rs/tracing#908, which fixes a bug where filtering would fail to
take the fastest fast path in many cases. This time, there's a slight,
but actually noticeable, latency reduction in the proxy benchmarks:

![Screenshot_20200808_183528](https://user-images.githubusercontent.com/2796466/89925622-8cbec780-dbb8-11ea-8a6f-587ab5075240.png)

Signed-off-by: Eliza Weisman <eliza@buoyant.io>
@hawkw hawkw mentioned this pull request Aug 12, 2020
Closed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Reviewers

@yaahc yaahc yaahc approved these changes

Assignees

@hawkw hawkw

Labels
crate/core Related to the `tracing-core` crate kind/bug Something isn't working
Projects
None yet
Milestone
No milestone
Development

Successfully merging this pull request may close these issues.

core: rebuilding interest appears to always set max level to TRACE
2 participants
@hawkw @yaahc