From 3657acea97ce432476853679472fbb24b4768ea2 Mon Sep 17 00:00:00 2001 From: Oli Scherer Date: Tue, 5 Oct 2021 09:59:34 +0000 Subject: [PATCH] Document tracing awesomeness --- src/tracing.md | 83 +++++++++++++++++++++++++++++++++++++++++++------- 1 file changed, 72 insertions(+), 11 deletions(-) diff --git a/src/tracing.md b/src/tracing.md index a676aaad..88c28868 100644 --- a/src/tracing.md +++ b/src/tracing.md @@ -1,4 +1,8 @@ -The compiler has a lot of [`debug!`] calls, which print out logging information +# Using tracing to debug the compiler + + + +The compiler has a lot of [`debug!`] (or `trace!`) 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. @@ -6,7 +10,62 @@ 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 +log filter. + +## Function level filters + +Lots of functions in rustc are annotated with + +``` +#[instrument(level = "debug", skip(self))] +fn foo(&self, bar: Type) {} +``` + +which allows you to use + +``` +RUSTC_LOG=[foo] +``` + +to do the following all at once + +* log all function calls to `foo` +* log the arguments (except for those in the `skip` list) +* log everything (from anywhere else in the compiler) until the function returns + +### I don't want everything + +Depending on the scope of the function, you may not want to log everything in its body. +As an example: the `do_mir_borrowck` function will dump hundreds of lines even for trivial +code being borrowchecked. + +Since you can combine all filters, you can add a crate/module path, e.g. + +``` +RUSTC_LOG=rustc_borrowck[do_mir_borrowck] +``` + +### I don't want all calls + +If you are compiling libcore, you likely don't want *all* borrowck dumps, but only one +for a specific function. You can filter function calls by their arguments by regexing them. + +``` +RUSTC_LOG=[do_mir_borrowck{id=\.\*from_utf8_unchecked\.\*}] +``` + +will only give you the logs of borrowchecking `from_utf8_unchecked`. Note that you will +still get a short message per ignored `do_mir_borrowck`, but none of the things inside those +calls. This helps you in looking through the calls that are happening and helps you adjust +your regex if you mistyped it. + +## Broad module level filters + +You can also use filters similar to the `log` crate's filters, which will enable +everything within a specific module. This is often too verbose and too unstructured, +so it is recommended to use function level filters. + +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 @@ -69,7 +128,7 @@ $ RUSTDOC_LOG=info rustdoc +stage1 my-file.rs $ RUSTDOC_LOG=rustdoc=debug rustdoc +stage1 my-file.rs ``` -### Log colors +## 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, @@ -94,7 +153,7 @@ 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 +## 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 @@ -104,7 +163,7 @@ 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 +## 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 @@ -112,17 +171,19 @@ 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. +It may be preferrable to use `trace!` over `debug!` for very noisy logs. + +A loosely followed convention is to use `#[instrument(level = "debug")]` in +favour of `debug!("foo(...)")` at the start of a function `foo`. +Within functions, prefer `debug!(?variable.field)` over `debug!("xyz = {:?}", variable.field)` +and `debug!(bar = ?var.method(arg))` over `debug!("bar = {:?}", var.method(arg))`. 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)); +debug!(x = ?random_operation(tcx)); ``` Then if someone runs a debug `rustc` with `RUSTC_LOG=rustc::bar`, then @@ -130,4 +191,4 @@ Then if someone runs a debug `rustc` with `RUSTC_LOG=rustc::bar`, then 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 +No-one will know it until someone tries to use logging to find *another* bug.