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.

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

log: compare log record Levels against the max level #1247

Merged
merged 1 commit into from
Feb 18, 2021

Conversation

hawkw
Copy link
Member

@hawkw hawkw commented Feb 18, 2021

This branch adds a check against the current value of the max global
LevelFilter hint in tracing_log's LogTracer::enabled method. This
should prevent log::${LEVEL}_enabled! from always returning true
when tracing is in use, fixing a performance issue when consuming
log records from tracing (see bytecodealliance/wasmtime#2662).

This does, however, mean LogTracer::enabled will always be called if
the max log level is not set. We can't determine whether we can set
log's max level in tracing_log, since we don't know if subscribers
will change (resulting in the current max tracing level filter
changing), or if the current subscriber is set as the global default.
Higher-level code in tracing_subscriber can do this, though, in
init(), because it does know that it's setting a global default.
I'll add that in a follow-up PR.

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

This branch adds a check against the current value of the max global
`LevelFilter` hint in `tracing_log`'s `LogTracer::enabled` method. This
should prevent `log::${LEVEL}_enabled!` from always returning `true`
when `tracing` is in use, fixing a performance issue when consuming
`log` records from tracing (see bytecodealliance/wasmtime#2662).

This does, however, mean `LogTracer::enabled` will always be called if
the max `log` level is not set. We can't determine whether we can set
`log`'s max level in `tracing_log`, since we don't know if subscribers
will change (resulting in the current max `tracing` level filter
changing), or if the current subscriber is set as the global default.
Higher-level code in `tracing_subscriber` can do this, though, in
`init()`, because it _does_ know that it's setting a global default.
I'll add that in a follow-up PR.

Signed-off-by: Eliza Weisman <eliza@buoyant.io>
@hawkw hawkw self-assigned this Feb 18, 2021
@hawkw hawkw requested review from davidbarsky and a team as code owners February 18, 2021 22:05
@hawkw hawkw merged commit 21dfa9d into master Feb 18, 2021
@hawkw hawkw deleted the eliza/check-log-max-level branch February 18, 2021 22:48
hawkw added a commit that referenced this pull request Feb 18, 2021
Depends on #1247.

Since `tracing-subscriber`'s `init` and `try_init` functions set the
global default collector, we can use the collector's max-level hint as
the max level for the log crate, as well. This should significantly
improve performance for skipping `log` records that fall below the
collector's max level, as they will not have to call the
`LogTracer::enabled` method.

This will prevent issues like bytecodealliance/wasmtime#2662
from occurring in the future. See also #1249.

In order to implement this, I also changed the `FmtCollector`'s
`try_init` to just use `util::SubscriberInitExt`'s `try_init` function,
so that the same code isn't duplicated in multiple places. I also
added `AsLog` and `AsTrace` conversions for `LevelFilter`s in
the `tracing-log` crate.

Signed-off-by: Eliza Weisman <eliza@buoyant.io>
hawkw added a commit that referenced this pull request Feb 18, 2021
This branch adds a check against the current value of the max global
`LevelFilter` hint in `tracing_log`'s `LogTracer::enabled` method. This
should prevent `log::${LEVEL}_enabled!` from always returning `true`
when `tracing` is in use, fixing a performance issue when consuming
`log` records from tracing (see bytecodealliance/wasmtime#2662).

This does, however, mean `LogTracer::enabled` will always be called if
the max `log` level is not set. We can't determine whether we can set
`log`'s max level in `tracing_log`, since we don't know if subscribers
will change (resulting in the current max `tracing` level filter
changing), or if the current subscriber is set as the global default.
Higher-level code in `tracing_subscriber` can do this, though, in
`init()`, because it _does_ know that it's setting a global default.
I'll add that in a follow-up PR.

Signed-off-by: Eliza Weisman <eliza@buoyant.io>
hawkw added a commit that referenced this pull request Feb 18, 2021
Depends on #1247.

Since `tracing-subscriber`'s `init` and `try_init` functions set the
global default subscriber, we can use the subscriber's max-level hint as
the max level for the log crate, as well. This should significantly
improve performance for skipping `log` records that fall below the
collector's max level, as they will not have to call the
`LogTracer::enabled` method.

This will prevent issues like bytecodealliance/wasmtime#2662
from occurring in the future. See also #1249.

In order to implement this, I also changed the `FmtSubscriber`'s
`try_init` to just use `util::SubscriberInitExt`'s `try_init` function,
so that the same code isn't duplicated in multiple places. I also
added `AsLog` and `AsTrace` conversions for `LevelFilter`s in
the `tracing-log` crate.

Signed-off-by: Eliza Weisman <eliza@buoyant.io>
hawkw added a commit that referenced this pull request Feb 19, 2021
This branch adds a check against the current value of the max global
`LevelFilter` hint in `tracing_log`'s `LogTracer::enabled` method. This
should prevent `log::${LEVEL}_enabled!` from always returning `true`
when `tracing` is in use, fixing a performance issue when consuming
`log` records from tracing (see bytecodealliance/wasmtime#2662).

This does, however, mean `LogTracer::enabled` will always be called if
the max `log` level is not set. We can't determine whether we can set
`log`'s max level in `tracing_log`, since we don't know if subscribers
will change (resulting in the current max `tracing` level filter
changing), or if the current subscriber is set as the global default.
Higher-level code in `tracing_subscriber` can do this, though, in
`init()`, because it _does_ know that it's setting a global default.
I'll add that in a follow-up PR.

Signed-off-by: Eliza Weisman <eliza@buoyant.io>
hawkw added a commit that referenced this pull request Feb 19, 2021
Depends on #1247.

Since `tracing-subscriber`'s `init` and `try_init` functions set the
global default subscriber, we can use the subscriber's max-level hint as
the max level for the log crate, as well. This should significantly
improve performance for skipping `log` records that fall below the
collector's max level, as they will not have to call the
`LogTracer::enabled` method.

This will prevent issues like bytecodealliance/wasmtime#2662
from occurring in the future. See also #1249.

In order to implement this, I also changed the `FmtSubscriber`'s
`try_init` to just use `util::SubscriberInitExt`'s `try_init` function,
so that the same code isn't duplicated in multiple places. I also
added `AsLog` and `AsTrace` conversions for `LevelFilter`s in
the `tracing-log` crate.

Signed-off-by: Eliza Weisman <eliza@buoyant.io>
hawkw added a commit that referenced this pull request Feb 19, 2021
PRs #1247, #1248, and #1251 improve `tracing`'s behavior for the `log`
crate's `log_enabled!` macro when a max-level hint is set. However, this
*doesn't* get us correct behavior when a particular target is not
enabled but the level is permitted by the max-level filter. In this
case, `log_enabled!` will still return `true` when using `LogTracer`,
because it doesn't currently call `Collect::enabled` on the current
collector in its `Log::enabled` method. Instead, `Collect::enabled` is
only checked when actually recording an event.

This means that when a target is disabled by a target-specific filter
but it's below the max level, `log::log_enabled!` will erroneously
return `true`. This also means that skipping disabled `log` records in
similar cases will construct the `log::Record` struct even when it isn't
necessary to do so.

This PR improves this behavior by adding a call to `Collect::enabled` in
`LogTracer`'s `Log::enabled` method. I've also added to the existing
tests for filtering `log` records to ensure that we also handle the
`log_enabled!` macro correctly.

While I was here, I noticed that the `Log::log` method for `LogTracer`
is somewhat inefficient --- it gets the current dispatcher *three*
times, and checks `enabled` twice. Currently, we check if the event
would be enabled, and then call the`format_trace` function, which *also*
checks if the event is enabled, and then dispatches it if it is. This is
not great. :/ I fixed this by moving the check-and-dispatch inside of a
single `dispatcher::get_default` block, and removing the duplicate
check.

Signed-off-by: Eliza Weisman <eliza@buoyant.io>
hawkw added a commit that referenced this pull request Feb 19, 2021
PRs #1247, #1248, and #1251 improve `tracing`'s behavior for the `log`
crate's `log_enabled!` macro when a max-level hint is set. However, this
*doesn't* get us correct behavior when a particular target is not
enabled but the level is permitted by the max-level filter. In this
case, `log_enabled!` will still return `true` when using `LogTracer`,
because it doesn't currently call `Subscriber::enabled` on the current
subscriber in its `Log::enabled` method. Instead, `Subscriber::enabled`
is only checked when actually recording an event.

This means that when a target is disabled by a target-specific filter
but it's below the max level, `log::log_enabled!` will erroneously
return `true`. This also means that skipping disabled `log` records in
similar cases will construct the `log::Record` struct even when it isn't
necessary to do so.

This PR improves this behavior by adding a call to `Subscriber::enabled`
in `LogTracer`'s `Log::enabled` method. I've also added to the existing
tests for filtering `log` records to ensure that we also handle the
`log_enabled!` macro correctly.

While I was here, I noticed that the `Log::log` method for `LogTracer`
is somewhat inefficient --- it gets the current dispatcher *three*
times, and checks `enabled` twice. Currently, we check if the event
would be enabled, and then call the`format_trace` function, which *also*
checks if the event is enabled, and then dispatches it if it is. This is
not great. :/ I fixed this by moving the check-and-dispatch inside of a
single `dispatcher::get_default` block, and removing the duplicate
check.

Signed-off-by: Eliza Weisman <eliza@buoyant.io>
hawkw added a commit that referenced this pull request Feb 19, 2021
PRs #1247, #1248, and #1251 improve `tracing`'s behavior for the `log`
crate's `log_enabled!` macro when a max-level hint is set. However, this
*doesn't* get us correct behavior when a particular target is not
enabled but the level is permitted by the max-level filter. In this
case, `log_enabled!` will still return `true` when using `LogTracer`,
because it doesn't currently call `Subscriber::enabled` on the current
subscriber in its `Log::enabled` method. Instead, `Subscriber::enabled`
is only checked when actually recording an event.

This means that when a target is disabled by a target-specific filter
but it's below the max level, `log::log_enabled!` will erroneously
return `true`. This also means that skipping disabled `log` records in
similar cases will construct the `log::Record` struct even when it isn't
necessary to do so.

This PR improves this behavior by adding a call to `Subscriber::enabled`
in `LogTracer`'s `Log::enabled` method. I've also added to the existing
tests for filtering `log` records to ensure that we also handle the
`log_enabled!` macro correctly.

While I was here, I noticed that the `Log::log` method for `LogTracer`
is somewhat inefficient --- it gets the current dispatcher *three*
times, and checks `enabled` twice. Currently, we check if the event
would be enabled, and then call the`format_trace` function, which *also*
checks if the event is enabled, and then dispatches it if it is. This is
not great. :/ I fixed this by moving the check-and-dispatch inside of a
single `dispatcher::get_default` block, and removing the duplicate
check.

Signed-off-by: Eliza Weisman <eliza@buoyant.io>
hawkw added a commit that referenced this pull request Feb 19, 2021
PRs #1247, #1248, and #1251 improve `tracing`'s behavior for the `log`
crate's `log_enabled!` macro when a max-level hint is set. However, this
*doesn't* get us correct behavior when a particular target is not
enabled but the level is permitted by the max-level filter. In this
case, `log_enabled!` will still return `true` when using `LogTracer`,
because it doesn't currently call `Subscriber::enabled` on the current
subscriber in its `Log::enabled` method. Instead, `Subscriber::enabled`
is only checked when actually recording an event.

This means that when a target is disabled by a target-specific filter
but it's below the max level, `log::log_enabled!` will erroneously
return `true`. This also means that skipping disabled `log` records in
similar cases will construct the `log::Record` struct even when it isn't
necessary to do so.

This PR improves this behavior by adding a call to `Subscriber::enabled`
in `LogTracer`'s `Log::enabled` method. I've also added to the existing
tests for filtering `log` records to ensure that we also handle the
`log_enabled!` macro correctly.

While I was here, I noticed that the `Log::log` method for `LogTracer`
is somewhat inefficient --- it gets the current dispatcher *three*
times, and checks `enabled` twice. Currently, we check if the event
would be enabled, and then call the`format_trace` function, which *also*
checks if the event is enabled, and then dispatches it if it is. This is
not great. :/ I fixed this by moving the check-and-dispatch inside of a
single `dispatcher::get_default` block, and removing the duplicate
check.

Signed-off-by: Eliza Weisman <eliza@buoyant.io>
hawkw added a commit that referenced this pull request Feb 19, 2021
Added

- Re-export the `log` crate so that users can ensure consistent versions
  ([#602])
- `AsLog` implementation for `tracing::LevelFilter` ([#1248])
- `AsTrace` implementation for `log::LevelFilter` ([#1248])

Fixed

- **log-tracer**: Fixed `Log::enabled` implementation for `LogTracer`
  not calling `Subscriber::enabled` ([#1254])
- **log-tracer**: Fixed `Log::enabled` implementation for `LogTracer`
  not checking the max level hint ([#1247])
- Several documentation fixes ([#483], [#485], [#537], [#595], [#941],
  [#981])

[#483]: https://github.com/tokio-rs/tracing/pulls/483
[#485]: https://github.com/tokio-rs/tracing/pulls/485
[#537]: https://github.com/tokio-rs/tracing/pulls/537
[#595]: https://github.com/tokio-rs/tracing/pulls/595
[#605]: https://github.com/tokio-rs/tracing/pulls/604
[#941]: https://github.com/tokio-rs/tracing/pulls/941
[#1247]: https://github.com/tokio-rs/tracing/pulls/1247
[#1248]: https://github.com/tokio-rs/tracing/pulls/1248
[#1254]: https://github.com/tokio-rs/tracing/pulls/1254

Signed-off-by: Eliza Weisman <eliza@buoyant.io>
hawkw added a commit to linkerd/linkerd2-proxy that referenced this pull request Feb 22, 2021
This picks up tokio-rs/tracing#1247, tokio-rs/tracing#1248,
tokio-rs/tracing#1251, and tokio-rs/tracing#1254. Collectively, these
changes should result in a significant performance improvement when
using `tracing-log`'s compatibility layer for converting legacy `log`
records to `tracing` events.

Since we have some dependencies which use the `log` crate, this should
hopefully reduce the overhead of those dependencies' logging. I'm not
sure how much `log` we have in the hot path by this point, but it's
probably a good idea to pick up the change regardless.

Signed-off-by: Eliza Weisman <eliza@buoyant.io>
olix0r pushed a commit to linkerd/linkerd2-proxy that referenced this pull request Feb 22, 2021
This picks up tokio-rs/tracing#1247, tokio-rs/tracing#1248,
tokio-rs/tracing#1251, and tokio-rs/tracing#1254. Collectively, these
changes should result in a significant performance improvement when
using `tracing-log`'s compatibility layer for converting legacy `log`
records to `tracing` events.

Since we have some dependencies which use the `log` crate, this should
hopefully reduce the overhead of those dependencies' logging. I'm not
sure how much `log` we have in the hot path by this point, but it's
probably a good idea to pick up the change regardless.

Signed-off-by: Eliza Weisman <eliza@buoyant.io>
bors bot referenced this pull request in comit-network/comit-rs Mar 17, 2021
3542: Bump tracing from 0.1.22 to 0.1.25 r=mergify[bot] a=dependabot[bot]

Bumps [tracing](https://github.com/tokio-rs/tracing) from 0.1.22 to 0.1.25.
<details>
<summary>Commits</summary>
<ul>
<li><a href="https://github.com/tokio-rs/tracing/commit/4ad1e62a2dd9f3e97a06ead14285993a9df99ea5"><code>4ad1e62</code></a> tracing: prepare to release v0.1.25</li>
<li><a href="https://github.com/tokio-rs/tracing/commit/c22b62e28121b66522beeff516f8a1528ec8ff36"><code>c22b62e</code></a> tracing: highlight <code>Span::entered</code> in more docs</li>
<li><a href="https://github.com/tokio-rs/tracing/commit/a358728b1ef321751acead4580643b1150863c62"><code>a358728</code></a> tracing: simplify common case of immediately entering the span (<a href="https://github.com/tokio-rs/tracing/issues/1252">#1252</a>)</li>
<li><a href="https://github.com/tokio-rs/tracing/commit/4538d74d228e4a6856c0176ade5f01fc26129b8e"><code>4538d74</code></a> subscriber: prepare to release v0.2.16 (<a href="https://github.com/tokio-rs/tracing/issues/1256">#1256</a>)</li>
<li><a href="https://github.com/tokio-rs/tracing/commit/a0201ba798b86739ba633d15d297ec233b905e4e"><code>a0201ba</code></a> log: prepare to release v0.1.2</li>
<li><a href="https://github.com/tokio-rs/tracing/commit/0cdd5e88ac3478ae91223e9c3b53a1c3598a7893"><code>0cdd5e8</code></a> log: forward <code>LogTracer::enabled</code> to the subscriber  (<a href="https://github.com/tokio-rs/tracing/issues/1254">#1254</a>)</li>
<li><a href="https://github.com/tokio-rs/tracing/commit/8d83326a5fddfdd68dc8865680f8663dad76a2b4"><code>8d83326</code></a> subscriber: fix FmtCollector not forwarding max level  (<a href="https://github.com/tokio-rs/tracing/issues/1251">#1251</a>)</li>
<li><a href="https://github.com/tokio-rs/tracing/commit/31aa6afecc1fb97b1f2d4eb15cefdd456c120142"><code>31aa6af</code></a> subscriber: set the max <code>log</code> <code>LevelFilter</code> in <code>init</code> (<a href="https://github.com/tokio-rs/tracing/issues/1248">#1248</a>)</li>
<li><a href="https://github.com/tokio-rs/tracing/commit/2a9d17f73f8499b7e73cf6e8bee225190aac6990"><code>2a9d17f</code></a> log: compare <code>log</code> record <code>Level</code>s against the max level (<a href="https://github.com/tokio-rs/tracing/issues/1247">#1247</a>)</li>
<li><a href="https://github.com/tokio-rs/tracing/commit/d173c2de9af913e2b4ebb8555e46d65b416ca730"><code>d173c2d</code></a> tracing: prepare to release v0.1.24 (<a href="https://github.com/tokio-rs/tracing/issues/1244">#1244</a>)</li>
<li>Additional commits viewable in <a href="https://github.com/tokio-rs/tracing/compare/tracing-0.1.22...tracing-0.1.25">compare view</a></li>
</ul>
</details>
<br />


[![Dependabot compatibility score](https://dependabot-badges.githubapp.com/badges/compatibility_score?dependency-name=tracing&package-manager=cargo&previous-version=0.1.22&new-version=0.1.25)](https://docs.github.com/en/github/managing-security-vulnerabilities/about-dependabot-security-updates#about-compatibility-scores)

Dependabot will resolve any conflicts with this PR as long as you don't alter it yourself. You can also trigger a rebase manually by commenting `@dependabot rebase`.

[//]: # (dependabot-automerge-start)
[//]: # (dependabot-automerge-end)

---

<details>
<summary>Dependabot commands and options</summary>
<br />

You can trigger Dependabot actions by commenting on this PR:
- `@dependabot rebase` will rebase this PR
- `@dependabot recreate` will recreate this PR, overwriting any edits that have been made to it
- `@dependabot merge` will merge this PR after your CI passes on it
- `@dependabot squash and merge` will squash and merge this PR after your CI passes on it
- `@dependabot cancel merge` will cancel a previously requested merge and block automerging
- `@dependabot reopen` will reopen this PR if it is closed
- `@dependabot close` will close this PR and stop Dependabot recreating it. You can achieve the same result by closing it manually


</details>

Co-authored-by: dependabot[bot] <49699333+dependabot[bot]@users.noreply.github.com>
kaffarell pushed a commit to kaffarell/tracing that referenced this pull request May 22, 2024
Depends on tokio-rs#1247.

Since `tracing-subscriber`'s `init` and `try_init` functions set the
global default subscriber, we can use the subscriber's max-level hint as
the max level for the log crate, as well. This should significantly
improve performance for skipping `log` records that fall below the
collector's max level, as they will not have to call the
`LogTracer::enabled` method.

This will prevent issues like bytecodealliance/wasmtime#2662
from occurring in the future. See also tokio-rs#1249.

In order to implement this, I also changed the `FmtSubscriber`'s
`try_init` to just use `util::SubscriberInitExt`'s `try_init` function,
so that the same code isn't duplicated in multiple places. I also
added `AsLog` and `AsTrace` conversions for `LevelFilter`s in
the `tracing-log` crate.

Signed-off-by: Eliza Weisman <eliza@buoyant.io>
kaffarell pushed a commit to kaffarell/tracing that referenced this pull request May 22, 2024
Added

- Re-export the `log` crate so that users can ensure consistent versions
  ([tokio-rs#602])
- `AsLog` implementation for `tracing::LevelFilter` ([tokio-rs#1248])
- `AsTrace` implementation for `log::LevelFilter` ([tokio-rs#1248])

Fixed

- **log-tracer**: Fixed `Log::enabled` implementation for `LogTracer`
  not calling `Subscriber::enabled` ([tokio-rs#1254])
- **log-tracer**: Fixed `Log::enabled` implementation for `LogTracer`
  not checking the max level hint ([tokio-rs#1247])
- Several documentation fixes ([tokio-rs#483], [tokio-rs#485], [tokio-rs#537], [tokio-rs#595], [tokio-rs#941],
  [tokio-rs#981])

[tokio-rs#483]: https://github.com/tokio-rs/tracing/pulls/483
[tokio-rs#485]: https://github.com/tokio-rs/tracing/pulls/485
[tokio-rs#537]: https://github.com/tokio-rs/tracing/pulls/537
[tokio-rs#595]: https://github.com/tokio-rs/tracing/pulls/595
[tokio-rs#605]: https://github.com/tokio-rs/tracing/pulls/604
[tokio-rs#941]: https://github.com/tokio-rs/tracing/pulls/941
[tokio-rs#1247]: https://github.com/tokio-rs/tracing/pulls/1247
[tokio-rs#1248]: https://github.com/tokio-rs/tracing/pulls/1248
[tokio-rs#1254]: https://github.com/tokio-rs/tracing/pulls/1254

Signed-off-by: Eliza Weisman <eliza@buoyant.io>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

2 participants