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

Allow disabling logging feature #1190

Closed

Conversation

bobrik
Copy link
Contributor

@bobrik bobrik commented Jan 14, 2021

Logging macro if_log_enabled checks both log and always-log crate features to select which macro version to use. Unfortunately, log feature cannot be set by crate consumers in either existing form or if added to Cargo.toml, probably because of a name clash with log crate:

$ git diff Cargo.toml
diff --git a/tracing/Cargo.toml b/tracing/Cargo.toml
index 37bb61f..e030d27 100644
--- a/tracing/Cargo.toml
+++ b/tracing/Cargo.toml
@@ -63,7 +63,7 @@ release_max_level_trace = []
 async-await = []

 std = ["tracing-core/std"]
+log = ["log"]
 log-always = ["log"]
 attributes = ["tracing-attributes"]
Caused by:
  optional dependency `log` is not included in any feature
  Make sure that `dep:log` is included in one of features in the [features] table.

I'm renaming log feature to logging to work around that.

With the following code:

let now = std::time::Instant::now();

eprintln!("before span created us = {}", now.elapsed().as_micros());

let span = tracing::span!(tracing::Level::TRACE, "setup");

eprintln!("after span created us = {}", now.elapsed().as_micros());

let entered = span.enter();

eprintln!("after enter us = {}", now.elapsed().as_micros());

drop(entered);

eprintln!("after entered drop us = {}", now.elapsed().as_micros());

drop(span);

eprintln!("after span drop us = {}", now.elapsed().as_micros());

Typical timings with logging feature enabled (but not logging anything):

before span created us = 0
after span created us = 8
after enter us = 9
after entered drop us = 13
after span drop us = 14

Typical timings with logging disabled (this PR):

before span created us = 0
after span created us = 1
after enter us = 3
after entered drop us = 5
after span drop us = 6

@bobrik bobrik requested review from hawkw and a team as code owners January 14, 2021 01:54
@bobrik bobrik force-pushed the ivan/allow-disabling-logging-feature branch from c2bcb6e to ffce665 Compare January 14, 2021 02:04
bobrik added a commit to bobrik/tracing that referenced this pull request Jan 14, 2021
It was renamed everywhere in tokio-rs#1015, but until tokio-rs#1190 it wasn't possible
to enter this macro branch. Now it fails with the following:

```
   Compiling tracing v0.2.0 (/Users/ivan/projects/tracing/tracing)
error[E0433]: failed to resolve: maybe a missing crate `dispatcher`?
    --> /Users/ivan/projects/tracing/tracing/src/macros.rs:2351:21
     |
2351 |           if !$crate::dispatcher::has_been_set() {
     |                       ^^^^^^^^^^ maybe a missing crate `dispatcher`?
```
@bobrik
Copy link
Contributor Author

bobrik commented Jan 14, 2021

The timings are more different if I run the same traced code twice and measure more precisely, but it's still better.

fn trace_timings() {
    let now = std::time::Instant::now();

    let before_span_created = now.elapsed().as_nanos();

    let span = tracing::span!(tracing::Level::TRACE, "setup");

    let after_span_created = now.elapsed().as_nanos();

    let entered = span.enter();

    let after_span_entered = now.elapsed().as_nanos();

    drop(entered);

    let after_span_entered_dropped = now.elapsed().as_nanos();

    drop(span);

    let after_span_dropped = now.elapsed().as_nanos();

    eprintln!("before span created ns = {:6}", before_span_created);
    eprintln!("after span created ns  = {:6}", after_span_created);
    eprintln!("after enter ns         = {:6}", after_span_entered);
    eprintln!("after entered drop ns  = {:6}", after_span_entered_dropped);
    eprintln!("after span drop ns     = {:6}", after_span_dropped);
}
  • Before (logging feature on, no logs produced):
before span created ns =      0
after span created ns  =   5833
after enter ns         =   6041
after entered drop ns  =  10375
after span drop ns     =  10583
---
before span created ns =      0
after span created ns  =    125
after enter ns         =    166
after entered drop ns  =    250
after span drop ns     =    291
  • After (logging feature off):
before span created ns =      0
after span created ns  =    333
after enter ns         =   1333
after entered drop ns  =   2875
after span drop ns     =   3125
---
before span created ns =      0
after span created ns  =      0
after enter ns         =     41
after entered drop ns  =     83
after span drop ns     =    125

Logging macro `if_log_enabled` checks both `log` and `always-log` crate
features to select which macro version to use. Unfortunately, `log` feature
cannot be set by crate consumers in either existing form or if added
to `Cargo.toml`, probably because of a name clash with `log` crate:

```diff
$ git diff Cargo.toml
diff --git a/tracing/Cargo.toml b/tracing/Cargo.toml
index 37bb61f..e030d27 100644
--- a/tracing/Cargo.toml
+++ b/tracing/Cargo.toml
@@ -63,7 +63,7 @@ release_max_level_trace = []
 async-await = []

 std = ["tracing-core/std"]
+log = ["log"]
 log-always = ["log"]
 attributes = ["tracing-attributes"]
 ```

```
Caused by:
  optional dependency `log` is not included in any feature
  Make sure that `dep:log` is included in one of features in the [features] table.
```

I'm renaming `log` feature to `logging` to work around that.

There's a slight improvement in throughput with logging disabled:

```
global/collector/span_no_fields
                        time:   [7.9682 ns 7.9704 ns 7.9729 ns]
                        change: [-13.902% -13.812% -13.720%] (p = 0.00 < 0.05)
                        Performance has improved.
```
@bobrik bobrik force-pushed the ivan/allow-disabling-logging-feature branch from ffce665 to 2d54456 Compare January 15, 2021 06:37
@bobrik
Copy link
Contributor Author

bobrik commented Jan 15, 2021

Please disregard my ramblings about the timings, these are from a non-release build.

Actual difference from the benchmark:

global/collector/span_no_fields
                        time:   [7.9682 ns 7.9704 ns 7.9729 ns]
                        change: [-13.902% -13.812% -13.720%] (p = 0.00 < 0.05)
                        Performance has improved.

I amended the commit to reflect that.

#1191 should probably be merged before this.

hawkw added a commit that referenced this pull request Jan 27, 2021
It was renamed everywhere in #1015, but until #1190 it wasn't possible
to enter this macro branch. Now it fails with the following:

```
   Compiling tracing v0.2.0 (/Users/ivan/projects/tracing/tracing)
error[E0433]: failed to resolve: maybe a missing crate `dispatcher`?
    --> /Users/ivan/projects/tracing/tracing/src/macros.rs:2351:21
     |
2351 |           if !$crate::dispatcher::has_been_set() {
     |                       ^^^^^^^^^^ maybe a missing crate `dispatcher`?
```

Co-authored-by: Eliza Weisman <eliza@buoyant.io>
@hawkw
Copy link
Member

hawkw commented Jan 27, 2021

Unfortunately, log feature cannot be set by crate consumers in either existing form or if added to Cargo.toml, probably because of a name clash with log crate:

I'm not sure if this is the case. It should be possible to enable or disable the optional dependency as though it were a crate feature, without adding it to the tracing Cargo.toml as a feature flag.

Something like this should work, and I'm pretty sure it's been used successfully in the past.

[dependencies.tracing]
version = "0.1"
features = ["log"]

Does this no longer work?

@bobrik
Copy link
Contributor Author

bobrik commented Jan 29, 2021

Not sure how I messed up my local setup, but it does indeed work as intended.

@bobrik bobrik closed this Jan 29, 2021
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