Move from log to tracing

[oli-obk]

The only visible change is that we now get timestamps in our logs:

Jul 24 18:41:01.065 TRACE rustc_mir::transform::const_prop: skipping replace of Rvalue::Use(const () because it is already a const
Jul 24 18:41:01.065 TRACE rustc_mir::transform::const_prop: propagated into _2
Jul 24 18:41:01.065 TRACE rustc_mir::transform::const_prop: visit_constant: const ()

This PR was explicitly designed to be as low-impact as possible. We can now move to using the name tracing insteads of log on a crate-by-crate basis and use any of the other tracing features where desirable.

As far as I can tell this will allow tools to seamlessly keep working (since they are using rustc_driver::init_log...).

This is the first half of step 1 of the accepted tracing MCP (rust-lang/compiler-team#331)

[rust-highfive]

r? @Mark-Simulacrum

(rust_highfive has picked a reviewer for you, use r? to override)

[Mark-Simulacrum]

The replacements seem like they could be pretty confusing, so we should try to move off of them pretty quickly, but I agree that for now this is probably the right way to do things, presuming it doesn't cause problems with tracing's own macros expanding to ::tracing::foo and that not resolving.

[oli-obk]

I agree, I'll open an E-easy issue with checkboxes for each of the renames

[hawkw]

Tracing's macros should all use $crate::, so this should be fine.

[Mark-Simulacrum]

Once CI is passing here, could you kick off a perf run? I want to make sure this isn't a performance regression (which would be unexpected, but we should check).

[jyn514]

Looks like rustdoc had a dependency on env_logger but didn't put it in cargo.toml 👀

     Checking rustdoc v0.0.0 (/checkout/src/librustdoc)
error[E0463]: can't find crate for `env_logger`
  --> src/librustdoc/lib.rs:17:1
   |
17 | extern crate env_logger;
   | ^^^^^^^^^^^^^^^^^^^^^^^^ can't find crate
```

[Mark-Simulacrum]

(that is actually good - any tools that have shared dependencies with rustc should ideally not declare them to save time in CI as loading from the sysroot is free, compared to recompiling)

[oli-obk]

@bors try @rust-timer queue

[rust-timer]

Awaiting bors try build completion

[bors]

⌛ Trying commit 2f7afb6d9058b3ebf7a059517ddc231da059ef0d with merge ec225facb960eff32c5290531b2dced3da219bdb...

[rust-log-analyzer]

The job dist-x86_64-linux of your PR failed (pretty log, raw log). Through arcane magic we have determined that the following fragments from the build log may contain information about the problem.

Click to expand the log.

Building stage1 tool error_index_generator (x86_64-unknown-linux-gnu)
   Compiling same-file v1.0.4
   Compiling walkdir v2.2.7
   Compiling error_index_generator v0.0.0 (/checkout/src/tools/error_index_generator)
error[E0463]: can't find crate for `env_logger`
  |
3 | extern crate env_logger;
  | ^^^^^^^^^^^^^^^^^^^^^^^^ can't find crate


error: aborting due to previous error

For more information about this error, try `rustc --explain E0463`.
error: could not compile `error_index_generator`.
To learn more, run the command again with --verbose.
command did not execute successfully: "/checkout/obj/build/x86_64-unknown-linux-gnu/stage0/bin/cargo" "build" "--target" "x86_64-unknown-linux-gnu" "-Zbinary-dep-depinfo" "-j" "16" "--release" "--locked" "--color" "always" "--manifest-path" "/checkout/src/tools/error_index_generator/Cargo.toml" "--message-format" "json-render-diagnostics"
expected success, got: exit code: 101
failed to run: /checkout/obj/build/bootstrap/debug/bootstrap dist --host x86_64-unknown-linux-gnu --target x86_64-unknown-linux-gnu
failed to run: /checkout/obj/build/bootstrap/debug/bootstrap dist --host x86_64-unknown-linux-gnu --target x86_64-unknown-linux-gnu
Build completed unsuccessfully in 0:22:23
== clock drift check ==
  local time: Sat Jul 25 15:11:39 UTC 2020
  network time: Sat, 25 Jul 2020 15:11:40 GMT
== end clock drift check ==
##[error]Process completed with exit code 1.
Terminate orphan process: pid (3404) (python)

I'm a bot! I can only do what humans tell me to, so if this was not helpful or you have suggestions for improvements, please ping or otherwise contact @rust-lang/infra. (Feature Requests)

[bors]

💔 Test failed - checks-actions

[oli-obk]

@bors try @rust-timer queue

this time x.py test ran through cleanly locally and not just the few sub-tests I ran manually

[rust-timer]

Awaiting bors try build completion

[bors]

⌛ Trying commit b9a3fd38bef4e62704cfefda80ccf67a815700d1 with merge 46c33324e985772632898d0f4c1b6d4c246496ec...

[bors]

☀️ Try build successful - checks-actions, checks-azure
Build commit: 46c33324e985772632898d0f4c1b6d4c246496ec (46c33324e985772632898d0f4c1b6d4c246496ec)

[rust-timer]

Queued 46c33324e985772632898d0f4c1b6d4c246496ec with parent 037d8e7, future comparison URL.

[mark-i-m]

Could you also make a PR to update the rustc-dev-guide, specifically with how to turn on and use logging? There is some existing content on how to enable the current logging system.

[rust-timer]

Finished benchmarking try commit (46c33324e985772632898d0f4c1b6d4c246496ec): comparison url.

Benchmarking this pull request likely means that it is perf-sensitive, so we're automatically marking it as not fit for rolling up. Please note that if the perf results are neutral, you should likely undo the rollup=never given below by specifying rollup- to bors.

Importantly, though, if the results of this run are non-neutral do not roll this PR up -- it will mask other regressions or improvements in the roll up.

@bors rollup=never

[oli-obk]

@hawkw any tips on debugging perf regressions due to migrating from log to tracing? I turned on release_max_level_info (we were using this before with log, so some crates enabling this feature should keep turning it on for all crates.

EDIT 1: I believe this is all working correctly, as looking at a const-eval heavy test's perf result (https://perf.rust-lang.org/detailed-query.html?commit=46c33324e985772632898d0f4c1b6d4c246496ec&base_commit=037d8e747de5056f0202f29aa2b0353bdbbf5cfe&benchmark=wf-projection-stress-65510-check&run_name=full) still has a significant number of info! invocations (3 per const eval stack frame, one per statement), which would then require runtime checks for whether they should get emitted. Could these slowdowns be due to the implementation of the env filter?

EDIT 2: I'm doing what you suggested originally now (I think?), and enabling the tracing-log feature of tracing-subscriber, which moves all the changes to just librustc_driver and we can port all the other crates one by one later.

EDIT 3: Oh, that doesn't work with log_enabled!, maybe the regression is due to my span_trace!("").is_none() checks?

EDIT 4: Maybe we're losing perf because we stay compatible to log?

[oli-obk]

@bors try @rust-timer queue

[rust-timer]

Awaiting bors try build completion

[bors]

⌛ Trying commit e301587481705f5dd14df480a9f76c2432e3ad8e with merge 1b5adbdbb4a5be604061874ffc2dade72bf7ede0...

[bors]

☀️ Try build successful - checks-actions, checks-azure
Build commit: 1b5adbdbb4a5be604061874ffc2dade72bf7ede0 (1b5adbdbb4a5be604061874ffc2dade72bf7ede0)

[tesuji]

Should this be var_os?

[oli-obk]

what would be the difference in this case?

[tesuji]

Not checking utf8 validity.

[oli-obk]

hmm true, let's change it

[jyn514]

This broke my logging :( How do I get back the behavior of RUSTDOC_LOG=rustdoc::passes::collect? Right now it gives no output.

[jyn514]

RUSTDOC_LOG=rustdoc also doesn't work so I can't really use logging at all :/ RUSTDOC_LOG=debug has several million lines of output unfiltered.

[jyn514]

hmm, this works for RUSTDOC_LOG=rustc_metadata so maybe it's something specific to tools?

[jyn514]

This fixes it for me:

diff --git a/src/librustdoc/lib.rs b/src/librustdoc/lib.rs
index 002c5f96710..4f08452767a 100644
--- a/src/librustdoc/lib.rs
+++ b/src/librustdoc/lib.rs
@@ -43,7 +43,7 @@ extern crate rustc_trait_selection;
 extern crate rustc_typeck;
 extern crate test as testing;
 #[macro_use]
-extern crate log;
+extern crate tracing as log;
 
 use std::default::Default;
 use std::env;

Other tools might need a similar fix.

[memoryruins]

Other tools might need a similar fix.

@jyn514 ultimately the fix for rustdoc and any other tools may be similar to #74747,
where all mentions of log in the source are replaced by tracing.

[jyn514]

Sure, #74747 is the end goal and if tools want to do that first that's fine. But in the meantime logging is completely broken for rustdoc.

[memoryruins]

👍 #75081 is a reasonable patch until rustdoc is ready for source renaming

[Mark-Simulacrum]

This was a slight performance win, as expected. Huge thanks to @oli-obk and @hawkw for all the work put in here to get us an even faster logging framework. 🎉

[hawkw]

Yay! I'm really glad we were able to get this merged, and the optimizations should benefit other tracing users, as well.

Please feel free to ping me if anyone has additional questions about migrating to tracing!

[hawkw]

When we finish with optimizations, could we get another final try run in that checks the overhead of turning off the compile-time removal of most logging? In particular if we can afford it I'd love to have it on by default -- it's often a real pain to have to recompile with debug assertions on just to get debug logging. Plus, debug assertions are a 25% (just compiler) or 50% (std and compiler) performance hit; I wonder how much of that was from logging...

FWIW, it might be worth trying this again with the latest tracing and tracing-subscriber; we fixed a bug that caused the fast path to not be taken in some cases where it should have been. It might be worth a test.