From 1620515e37df3c94d1bd458ee4a71028f827c1cd Mon Sep 17 00:00:00 2001 From: Oli Scherer Date: Tue, 5 Oct 2021 09:57:35 +0000 Subject: [PATCH] Move log/tracing instructions to its own file --- src/SUMMARY.md | 1 + src/compiler-debugging.md | 135 +------------------------------------- src/getting-started.md | 4 +- src/tracing.md | 133 +++++++++++++++++++++++++++++++++++++ 4 files changed, 137 insertions(+), 136 deletions(-) create mode 100644 src/tracing.md diff --git a/src/SUMMARY.md b/src/SUMMARY.md index 5e59cf65..b7b6d8bd 100644 --- a/src/SUMMARY.md +++ b/src/SUMMARY.md @@ -20,6 +20,7 @@ - [Adding new tests](./tests/adding.md) - [Using `compiletest` commands to control test execution](./compiletest.md) - [Debugging the Compiler](./compiler-debugging.md) + - [Using the tracing/logging instrumentation](./tracing.md) - [Profiling the compiler](./profiling.md) - [with the linux perf tool](./profiling/with_perf.md) - [with Windows Performance Analyzer](./profiling/wpa_profiling.md) diff --git a/src/compiler-debugging.md b/src/compiler-debugging.md index 34f5e760..8f46e896 100644 --- a/src/compiler-debugging.md +++ b/src/compiler-debugging.md @@ -159,145 +159,12 @@ stack backtrace: Cool, now I have a backtrace for the error! ## Getting logging output -[getting-logging-output]: #getting-logging-output The compiler uses the [`tracing`] crate for logging. [`tracing`]: https://docs.rs/tracing -The compiler has a lot of [`debug!`] calls, which print out logging information -at many points. These are very useful to at least narrow down the location of -a bug if not to find it entirely, or just to orient yourself as to why the -compiler is doing a particular thing. - -[`debug!`]: https://docs.rs/tracing/0.1/tracing/macro.debug.html - -To see the logs, you need to set the `RUSTC_LOG` environment variable to your -log filter. Your log filter can be just `debug` to get all `debug!` output and -higher (e.g., it will also include `info!`), or `path::to::module` to get *all* -output (which will include `trace!`) from a particular module, or -`path::to::module=debug` to get `debug!` output and higher from a particular -module. - -For example, to get the `debug!` output and higher for a specific module, you -can run the compiler with `RUSTC_LOG=path::to::module=debug rustc my-file.rs`. -All `debug!` output will then appear in standard error. - -Note that you can use a partial path and the filter will still work. For -example, if you want to see `info!` output from only -`rustdoc::passes::collect_intra_doc_links`, you could use -`RUSTDOC_LOG=rustdoc::passes::collect_intra_doc_links=info` *or* you could use -`RUSTDOC_LOG=rustdoc::passes::collect_intra=info`. - -If you are developing rustdoc, use `RUSTDOC_LOG` instead. If you are developing -Miri, use `MIRI_LOG` instead. You get the idea :) - -See the [`tracing`] crate's docs, and specifically the docs for [`debug!`] to -see the full syntax you can use. (Note: unlike the compiler, the [`tracing`] -crate and its examples use the `RUST_LOG` environment variable. rustc, rustdoc, -and other tools set custom environment variables.) - -**Note that unless you use a very strict filter, the logger will emit a lot of -output, so use the most specific module(s) you can (comma-separated if -multiple)**. It's typically a good idea to pipe standard error to a file and -look at the log output with a text editor. - -So, to put it together: - -```bash -# This puts the output of all debug calls in `rustc_middle/src/traits` into -# standard error, which might fill your console backscroll. -$ RUSTC_LOG=rustc_middle::traits=debug rustc +stage1 my-file.rs - -# This puts the output of all debug calls in `rustc_middle/src/traits` in -# `traits-log`, so you can then see it with a text editor. -$ RUSTC_LOG=rustc_middle::traits=debug rustc +stage1 my-file.rs 2>traits-log - -# Not recommended! This will show the output of all `debug!` calls -# in the Rust compiler, and there are a *lot* of them, so it will be -# hard to find anything. -$ RUSTC_LOG=debug rustc +stage1 my-file.rs 2>all-log - -# This will show the output of all `info!` calls in `rustc_codegen_ssa`. -# -# There's an `info!` statement in `codegen_instance` that outputs -# every function that is codegen'd. This is useful to find out -# which function triggers an LLVM assertion, and this is an `info!` -# log rather than a `debug!` log so it will work on the official -# compilers. -$ RUSTC_LOG=rustc_codegen_ssa=info rustc +stage1 my-file.rs - -# This will show the output of all `info!` calls made by rustdoc -# or any rustc library it calls. -$ RUSTDOC_LOG=info rustdoc +stage1 my-file.rs - -# This will only show `debug!` calls made by rustdoc directly, -# not any `rustc*` crate. -$ RUSTDOC_LOG=rustdoc=debug rustdoc +stage1 my-file.rs -``` - -### Log colors - -By default, rustc (and other tools, like rustdoc and Miri) will be smart about -when to use ANSI colors in the log output. If they are outputting to a terminal, -they will use colors, and if they are outputting to a file or being piped -somewhere else, they will not. However, it's hard to read log output in your -terminal unless you have a very strict filter, so you may want to pipe the -output to a pager like `less`. But then there won't be any colors, which makes -it hard to pick out what you're looking for! - -You can override whether to have colors in log output with the `RUSTC_LOG_COLOR` -environment variable (or `RUSTDOC_LOG_COLOR` for rustdoc, or `MIRI_LOG_COLOR` -for Miri, etc.). There are three options: `auto` (the default), `always`, and -`never`. So, if you want to enable colors when piping to `less`, use something -similar to this command: - -```bash -# The `-R` switch tells less to print ANSI colors without escaping them. -$ RUSTC_LOG=debug RUSTC_LOG_COLOR=always rustc +stage1 ... | less -R -``` - -Note that `MIRI_LOG_COLOR` will only color logs that come from Miri, not logs -from rustc functions that Miri calls. Use `RUSTC_LOG_COLOR` to color logs from -rustc. - -### How to keep or remove `debug!` and `trace!` calls from the resulting binary - -While calls to `error!`, `warn!` and `info!` are included in every build of the compiler, -calls to `debug!` and `trace!` are only included in the program if -`debug-logging=true` is turned on in config.toml (it is -turned off by default), so if you don't see `DEBUG` logs, especially -if you run the compiler with `RUSTC_LOG=rustc rustc some.rs` and only see -`INFO` logs, make sure that `debug-logging=true` is turned on in your -config.toml. - -### Logging etiquette and conventions - -Because calls to `debug!` are removed by default, in most cases, don't worry -about adding "unnecessary" calls to `debug!` and leaving them in code you -commit - they won't slow down the performance of what we ship, and if they -helped you pinning down a bug, they will probably help someone else with a -different one. - -A loosely followed convention is to use `debug!("foo(...)")` at the _start_ of -a function `foo` and `debug!("foo: ...")` _within_ the function. Another -loosely followed convention is to use the `{:?}` format specifier for debug -logs. - -One thing to be **careful** of is **expensive** operations in logs. - -If in the module `rustc::foo` you have a statement - -```Rust -debug!("{:?}", random_operation(tcx)); -``` - -Then if someone runs a debug `rustc` with `RUSTC_LOG=rustc::bar`, then -`random_operation()` will run. - -This means that you should not put anything too expensive or likely to crash -there - that would annoy anyone who wants to use logging for their own module. -No-one will know it until someone tries to use logging to find *another* bug. +For details see [the guide section on tracing](./tracing.md) ## Formatting Graphviz output (.dot files) [formatting-graphviz-output]: #formatting-graphviz-output diff --git a/src/getting-started.md b/src/getting-started.md index 14225c50..4d77b03d 100644 --- a/src/getting-started.md +++ b/src/getting-started.md @@ -298,10 +298,10 @@ yourself when calling `rustfmt` directly. One last thing: you can use `RUSTC_LOG=XXX` to get debug logging. [Read more here][logging]. Notice the `C` in `RUSTC_LOG`. Other than that, it uses normal -[`env_logger`][envlog] syntax. +[`env_logger`][envlog] or `tracing` syntax. [envlog]: https://crates.io/crates/env_logger -[logging]: ./compiler-debugging.html#getting-logging-output +[logging]: ./tracing.md ### Building and Testing `std`/`core`/`alloc`/`test`/`proc_macro`/etc. diff --git a/src/tracing.md b/src/tracing.md new file mode 100644 index 00000000..a676aaad --- /dev/null +++ b/src/tracing.md @@ -0,0 +1,133 @@ +The compiler has a lot of [`debug!`] calls, which print out logging information +at many points. These are very useful to at least narrow down the location of +a bug if not to find it entirely, or just to orient yourself as to why the +compiler is doing a particular thing. + +[`debug!`]: https://docs.rs/tracing/0.1/tracing/macro.debug.html + +To see the logs, you need to set the `RUSTC_LOG` environment variable to your +log filter. Your log filter can be just `debug` to get all `debug!` output and +higher (e.g., it will also include `info!`), or `path::to::module` to get *all* +output (which will include `trace!`) from a particular module, or +`path::to::module=debug` to get `debug!` output and higher from a particular +module. + +For example, to get the `debug!` output and higher for a specific module, you +can run the compiler with `RUSTC_LOG=path::to::module=debug rustc my-file.rs`. +All `debug!` output will then appear in standard error. + +Note that you can use a partial path and the filter will still work. For +example, if you want to see `info!` output from only +`rustdoc::passes::collect_intra_doc_links`, you could use +`RUSTDOC_LOG=rustdoc::passes::collect_intra_doc_links=info` *or* you could use +`RUSTDOC_LOG=rustdoc::passes::collect_intra=info`. + +If you are developing rustdoc, use `RUSTDOC_LOG` instead. If you are developing +Miri, use `MIRI_LOG` instead. You get the idea :) + +See the [`tracing`] crate's docs, and specifically the docs for [`debug!`] to +see the full syntax you can use. (Note: unlike the compiler, the [`tracing`] +crate and its examples use the `RUST_LOG` environment variable. rustc, rustdoc, +and other tools set custom environment variables.) + +**Note that unless you use a very strict filter, the logger will emit a lot of +output, so use the most specific module(s) you can (comma-separated if +multiple)**. It's typically a good idea to pipe standard error to a file and +look at the log output with a text editor. + +So, to put it together: + +```bash +# This puts the output of all debug calls in `rustc_middle/src/traits` into +# standard error, which might fill your console backscroll. +$ RUSTC_LOG=rustc_middle::traits=debug rustc +stage1 my-file.rs + +# This puts the output of all debug calls in `rustc_middle/src/traits` in +# `traits-log`, so you can then see it with a text editor. +$ RUSTC_LOG=rustc_middle::traits=debug rustc +stage1 my-file.rs 2>traits-log + +# Not recommended! This will show the output of all `debug!` calls +# in the Rust compiler, and there are a *lot* of them, so it will be +# hard to find anything. +$ RUSTC_LOG=debug rustc +stage1 my-file.rs 2>all-log + +# This will show the output of all `info!` calls in `rustc_codegen_ssa`. +# +# There's an `info!` statement in `codegen_instance` that outputs +# every function that is codegen'd. This is useful to find out +# which function triggers an LLVM assertion, and this is an `info!` +# log rather than a `debug!` log so it will work on the official +# compilers. +$ RUSTC_LOG=rustc_codegen_ssa=info rustc +stage1 my-file.rs + +# This will show the output of all `info!` calls made by rustdoc +# or any rustc library it calls. +$ RUSTDOC_LOG=info rustdoc +stage1 my-file.rs + +# This will only show `debug!` calls made by rustdoc directly, +# not any `rustc*` crate. +$ RUSTDOC_LOG=rustdoc=debug rustdoc +stage1 my-file.rs +``` + +### Log colors + +By default, rustc (and other tools, like rustdoc and Miri) will be smart about +when to use ANSI colors in the log output. If they are outputting to a terminal, +they will use colors, and if they are outputting to a file or being piped +somewhere else, they will not. However, it's hard to read log output in your +terminal unless you have a very strict filter, so you may want to pipe the +output to a pager like `less`. But then there won't be any colors, which makes +it hard to pick out what you're looking for! + +You can override whether to have colors in log output with the `RUSTC_LOG_COLOR` +environment variable (or `RUSTDOC_LOG_COLOR` for rustdoc, or `MIRI_LOG_COLOR` +for Miri, etc.). There are three options: `auto` (the default), `always`, and +`never`. So, if you want to enable colors when piping to `less`, use something +similar to this command: + +```bash +# The `-R` switch tells less to print ANSI colors without escaping them. +$ RUSTC_LOG=debug RUSTC_LOG_COLOR=always rustc +stage1 ... | less -R +``` + +Note that `MIRI_LOG_COLOR` will only color logs that come from Miri, not logs +from rustc functions that Miri calls. Use `RUSTC_LOG_COLOR` to color logs from +rustc. + +### How to keep or remove `debug!` and `trace!` calls from the resulting binary + +While calls to `error!`, `warn!` and `info!` are included in every build of the compiler, +calls to `debug!` and `trace!` are only included in the program if +`debug-logging=true` is turned on in config.toml (it is +turned off by default), so if you don't see `DEBUG` logs, especially +if you run the compiler with `RUSTC_LOG=rustc rustc some.rs` and only see +`INFO` logs, make sure that `debug-logging=true` is turned on in your +config.toml. + +### Logging etiquette and conventions + +Because calls to `debug!` are removed by default, in most cases, don't worry +about adding "unnecessary" calls to `debug!` and leaving them in code you +commit - they won't slow down the performance of what we ship, and if they +helped you pinning down a bug, they will probably help someone else with a +different one. + +A loosely followed convention is to use `debug!("foo(...)")` at the _start_ of +a function `foo` and `debug!("foo: ...")` _within_ the function. Another +loosely followed convention is to use the `{:?}` format specifier for debug +logs. + +One thing to be **careful** of is **expensive** operations in logs. + +If in the module `rustc::foo` you have a statement + +```Rust +debug!("{:?}", random_operation(tcx)); +``` + +Then if someone runs a debug `rustc` with `RUSTC_LOG=rustc::bar`, then +`random_operation()` will run. + +This means that you should not put anything too expensive or likely to crash +there - that would annoy anyone who wants to use logging for their own module. +No-one will know it until someone tries to use logging to find *another* bug. \ No newline at end of file