Move log/tracing instructions to its own file
This commit is contained in:
parent
e0cfc8c17a
commit
1620515e37
|
|
@ -20,6 +20,7 @@
|
||||||
- [Adding new tests](./tests/adding.md)
|
- [Adding new tests](./tests/adding.md)
|
||||||
- [Using `compiletest` commands to control test execution](./compiletest.md)
|
- [Using `compiletest` commands to control test execution](./compiletest.md)
|
||||||
- [Debugging the Compiler](./compiler-debugging.md)
|
- [Debugging the Compiler](./compiler-debugging.md)
|
||||||
|
- [Using the tracing/logging instrumentation](./tracing.md)
|
||||||
- [Profiling the compiler](./profiling.md)
|
- [Profiling the compiler](./profiling.md)
|
||||||
- [with the linux perf tool](./profiling/with_perf.md)
|
- [with the linux perf tool](./profiling/with_perf.md)
|
||||||
- [with Windows Performance Analyzer](./profiling/wpa_profiling.md)
|
- [with Windows Performance Analyzer](./profiling/wpa_profiling.md)
|
||||||
|
|
|
||||||
|
|
@ -159,145 +159,12 @@ stack backtrace:
|
||||||
Cool, now I have a backtrace for the error!
|
Cool, now I have a backtrace for the error!
|
||||||
|
|
||||||
## Getting logging output
|
## Getting logging output
|
||||||
[getting-logging-output]: #getting-logging-output
|
|
||||||
|
|
||||||
The compiler uses the [`tracing`] crate for logging.
|
The compiler uses the [`tracing`] crate for logging.
|
||||||
|
|
||||||
[`tracing`]: https://docs.rs/tracing
|
[`tracing`]: https://docs.rs/tracing
|
||||||
|
|
||||||
The compiler has a lot of [`debug!`] calls, which print out logging information
|
For details see [the guide section on tracing](./tracing.md)
|
||||||
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.
|
|
||||||
|
|
||||||
## Formatting Graphviz output (.dot files)
|
## Formatting Graphviz output (.dot files)
|
||||||
[formatting-graphviz-output]: #formatting-graphviz-output
|
[formatting-graphviz-output]: #formatting-graphviz-output
|
||||||
|
|
|
||||||
|
|
@ -298,10 +298,10 @@ yourself when calling `rustfmt` directly.
|
||||||
|
|
||||||
One last thing: you can use `RUSTC_LOG=XXX` to get debug logging. [Read more
|
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
|
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
|
[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.
|
### Building and Testing `std`/`core`/`alloc`/`test`/`proc_macro`/etc.
|
||||||
|
|
||||||
|
|
|
||||||
|
|
@ -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.
|
||||||
Loading…
Reference in New Issue