|
| 1 | +--- |
| 2 | +layout: default |
| 3 | +title: Debugging the Compiler |
| 4 | +--- |
| 5 | + |
| 6 | +# Debugging the compiler |
| 7 | +[debugging]: #debugging |
| 8 | + |
| 9 | +Here are a few tips to debug the compiler: |
| 10 | + |
| 11 | +## Getting a backtrace |
| 12 | +[getting-a-backtrace]: #getting-a-backtrace |
| 13 | + |
| 14 | +When you have an ICE (panic in the compiler), you can set |
| 15 | +`RUST_BACKTRACE=1` to get the stack trace of the `panic!` like in |
| 16 | +normal Rust programs. IIRC backtraces **don't work** on Mac and on MinGW, |
| 17 | +sorry. If you have trouble or the backtraces are full of `unknown`, |
| 18 | +you might want to find some way to use Linux or MSVC on Windows. |
| 19 | + |
| 20 | +In the default configuration, you don't have line numbers enabled, so the backtrace looks like this: |
| 21 | + ``` |
| 22 | +stack backtrace: |
| 23 | + 0: std::sys::imp::backtrace::tracing::imp::unwind_backtrace |
| 24 | + 1: std::sys_common::backtrace::_print |
| 25 | + 2: std::panicking::default_hook::{{closure}} |
| 26 | + 3: std::panicking::default_hook |
| 27 | + 4: std::panicking::rust_panic_with_hook |
| 28 | + 5: std::panicking::begin_panic |
| 29 | + 6: rustc_typeck::check::cast::<impl rustc_typeck::check::FnCtxt<'a, 'gcx, 'tcx>>::pointer_kind |
| 30 | + (~~~~ LINES REMOVED BY ME FOR BREVITY ~~~~) |
| 31 | + 32: rustc_typeck::check_crate |
| 32 | + 33: <std::thread::local::LocalKey<T>>::with |
| 33 | + 34: <std::thread::local::LocalKey<T>>::with |
| 34 | + 35: rustc::ty::context::TyCtxt::create_and_enter |
| 35 | + 36: rustc_driver::driver::compile_input |
| 36 | + 37: rustc_driver::run_compiler |
| 37 | + ``` |
| 38 | + |
| 39 | +If you want line numbers for the stack trace, you can enable `debuginfo-lines=true` or `debuginfo=true` in your config.toml and rebuild the compiler. Then the backtrace will look like this: |
| 40 | +``` |
| 41 | +stack backtrace: |
| 42 | + (~~~~ LINES REMOVED BY ME FOR BREVITY ~~~~) |
| 43 | + 6: rustc_typeck::check::cast::<impl rustc_typeck::check::FnCtxt<'a, 'gcx, 'tcx>>::pointer_kind |
| 44 | + at /home/user/rust/src/librustc_typeck/check/cast.rs:110 |
| 45 | + 7: rustc_typeck::check::cast::CastCheck::check |
| 46 | + at /home/user/rust/src/librustc_typeck/check/cast.rs:572 |
| 47 | + at /home/user/rust/src/librustc_typeck/check/cast.rs:460 |
| 48 | + at /home/user/rust/src/librustc_typeck/check/cast.rs:370 |
| 49 | + (~~~~ LINES REMOVED BY ME FOR BREVITY ~~~~) |
| 50 | + 33: rustc_driver::driver::compile_input |
| 51 | + at /home/user/rust/src/librustc_driver/driver.rs:1010 |
| 52 | + at /home/user/rust/src/librustc_driver/driver.rs:212 |
| 53 | + 34: rustc_driver::run_compiler |
| 54 | + at /home/user/rust/src/librustc_driver/lib.rs:253 |
| 55 | +``` |
| 56 | + |
| 57 | +## Getting a backtrace for errors |
| 58 | +[getting-a-backtrace-for-errors]: #getting-a-backtrace-for-errors |
| 59 | + |
| 60 | +If you want to get a backtrace to the point where the compiler emits |
| 61 | +an error message, you can pass the `-Z treat-err-as-bug`, which |
| 62 | +will make the compiler panic on the first error it sees. |
| 63 | + |
| 64 | +This can also help when debugging `delay_span_bug` calls - it will make |
| 65 | +the first `delay_span_bug` call panic, which will give you a useful backtrace. |
| 66 | + |
| 67 | +For example: |
| 68 | +``` |
| 69 | +$ cat error.rs |
| 70 | +fn main() { |
| 71 | + 1 + (); |
| 72 | +} |
| 73 | +$ ./build/x86_64-unknown-linux-gnu/stage1/bin/rustc error.rs |
| 74 | +error[E0277]: the trait bound `{integer}: std::ops::Add<()>` is not satisfied |
| 75 | + --> error.rs:2:7 |
| 76 | + | |
| 77 | +2 | 1 + (); |
| 78 | + | ^ no implementation for `{integer} + ()` |
| 79 | + | |
| 80 | + = help: the trait `std::ops::Add<()>` is not implemented for `{integer}` |
| 81 | +
|
| 82 | +error: aborting due to previous error |
| 83 | +
|
| 84 | +$ # Now, where does the error above come from? |
| 85 | +$ RUST_BACKTRACE=1 \ |
| 86 | + ./build/x86_64-unknown-linux-gnu/stage1/bin/rustc \ |
| 87 | + error.rs \ |
| 88 | + -Z treat-err-as-bug |
| 89 | +error[E0277]: the trait bound `{integer}: std::ops::Add<()>` is not satisfied |
| 90 | + --> error.rs:2:7 |
| 91 | + | |
| 92 | +2 | 1 + (); |
| 93 | + | ^ no implementation for `{integer} + ()` |
| 94 | + | |
| 95 | + = help: the trait `std::ops::Add<()>` is not implemented for `{integer}` |
| 96 | +
|
| 97 | +error: internal compiler error: unexpected panic |
| 98 | +
|
| 99 | +note: the compiler unexpectedly panicked. this is a bug. |
| 100 | +
|
| 101 | +note: we would appreciate a bug report: https://github.com/rust-lang/rust/blob/master/CONTRIBUTING.md#bug-reports |
| 102 | +
|
| 103 | +note: rustc 1.24.0-dev running on x86_64-unknown-linux-gnu |
| 104 | +
|
| 105 | +note: run with `RUST_BACKTRACE=1` for a backtrace |
| 106 | +
|
| 107 | +thread 'rustc' panicked at 'encountered error with `-Z treat_err_as_bug', /home/user/rust/src/librustc_errors/lib.rs:411:12 |
| 108 | +note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace. |
| 109 | +stack backtrace: |
| 110 | + (~~~ IRRELEVANT PART OF BACKTRACE REMOVED BY ME ~~~) |
| 111 | + 7: rustc::traits::error_reporting::<impl rustc::infer::InferCtxt<'a, 'gcx, 'tcx>>::report_selection_error |
| 112 | + at /home/user/rust/src/librustc/traits/error_reporting.rs:823 |
| 113 | + 8: rustc::traits::error_reporting::<impl rustc::infer::InferCtxt<'a, 'gcx, 'tcx>>::report_fulfillment_errors |
| 114 | + at /home/user/rust/src/librustc/traits/error_reporting.rs:160 |
| 115 | + at /home/user/rust/src/librustc/traits/error_reporting.rs:112 |
| 116 | + 9: rustc_typeck::check::FnCtxt::select_obligations_where_possible |
| 117 | + at /home/user/rust/src/librustc_typeck/check/mod.rs:2192 |
| 118 | + (~~~ IRRELEVANT PART OF BACKTRACE REMOVED BY ME ~~~) |
| 119 | + 36: rustc_driver::run_compiler |
| 120 | + at /home/user/rust/src/librustc_driver/lib.rs:253 |
| 121 | +$ # Cool, now I have a backtrace for the error |
| 122 | +``` |
| 123 | + |
| 124 | +## Getting logging output |
| 125 | +[getting-logging-output]: #getting-logging-output |
| 126 | + |
| 127 | +The compiler has a lot of `debug!` calls, which print out logging information |
| 128 | +at many points. These are very useful to at least narrow down the location of |
| 129 | +a bug if not to find it entirely, or just to orient yourself to why a compiler |
| 130 | +is doing a particular thing. |
| 131 | + |
| 132 | +To see the logs, you need to set the `RUST_LOG` environment variable to |
| 133 | +your log filter, e.g. to get the logs for a specific module, you can run the |
| 134 | +compiler as `RUST_LOG=module::path rustc my-file.rs`. The Rust logs are |
| 135 | +powered by [env-logger], and you can look at the docs linked there to see |
| 136 | +the full `RUST_LOG` syntax. All `debug!` output will then appear in |
| 137 | +standard error. |
| 138 | + |
| 139 | +Note that unless you use a very strict filter, the logger will emit a *lot* |
| 140 | +of output - so it's typically a good idea to pipe standard error to a file |
| 141 | +and look at the log output with a text editor. |
| 142 | + |
| 143 | +So to put it together. |
| 144 | +``` |
| 145 | +# This puts the output of all debug calls in `librustc/traits` into |
| 146 | +# standard error, which might fill your console backscroll. |
| 147 | +$ RUST_LOG=rustc::traits rustc +local my-file.rs |
| 148 | +
|
| 149 | +# This puts the output of all debug calls in `librustc/traits` in |
| 150 | +# `traits-log`, so you can then see it with a text editor. |
| 151 | +$ RUST_LOG=rustc::traits rustc +local my-file.rs 2>traits-log |
| 152 | +
|
| 153 | +# Not recommended. This will show the output of all `debug!` calls |
| 154 | +# in the Rust compiler, and there are a *lot* of them, so it will be |
| 155 | +# hard to find anything. |
| 156 | +$ RUST_LOG=debug rustc +local my-file.rs 2>all-log |
| 157 | +
|
| 158 | +# This will show the output of all `info!` calls in `rustc_trans`. |
| 159 | +# |
| 160 | +# There's an `info!` statement in `trans_instance` that outputs |
| 161 | +# every function that is translated. This is useful to find out |
| 162 | +# which function triggers an LLVM assertion, and this is an `info!` |
| 163 | +# log rather than a `debug!` log so it will work on the official |
| 164 | +# compilers. |
| 165 | +$ RUST_LOG=rustc_trans=info rustc +local my-file.rs |
| 166 | +``` |
| 167 | + |
| 168 | +While calls to `info!` are included in every build of the compiler, |
| 169 | +calls to `debug!` are only included in the program if the |
| 170 | +`debug-assertions=yes` is turned on in config.toml (it is |
| 171 | +turned off by default), so if you don't see `DEBUG` logs, especially |
| 172 | +if you run the compiler with `RUST_LOG=rustc rustc some.rs` and only see |
| 173 | +`INFO` logs, make sure that `debug-assertions=yes` is turned on in your |
| 174 | +config.toml. |
| 175 | + |
| 176 | +I also think that in some cases just setting it will not trigger a rebuild, |
| 177 | +so if you changed it and you already have a compiler built, you might |
| 178 | +want to call `x.py clean` to force one. |
| 179 | + |
| 180 | +### Logging etiquette |
| 181 | + |
| 182 | +Because calls to `debug!` are removed by default, in most cases, don't worry |
| 183 | +about adding "unnecessary" calls to `debug!` and leaving them in in code |
| 184 | +you commit - they won't slow |
| 185 | +down the performance of what we ship, and if they helped you pinning down |
| 186 | +a bug, they will probably help someone else with a different one. |
| 187 | + |
| 188 | +However, there are still a few concerns that you might care about: |
| 189 | + |
| 190 | +### Expensive operations in logs |
| 191 | + |
| 192 | +A note of caution: the expressions *within* the `debug!` call are run |
| 193 | +whenever RUST_LOG is set, even if the filter would exclude the log. This means that if in the module `rustc::foo` you have a statement |
| 194 | + |
| 195 | +```Rust |
| 196 | +debug!("{:?}", random_operation(tcx)); |
| 197 | +``` |
| 198 | + |
| 199 | +Then if someone runs a debug `rustc` with `RUST_LOG=rustc::bar`, then `random_operation()` will still run - even while it's output will never be needed! |
| 200 | + |
| 201 | +This means that you should not put anything too expensive or likely |
| 202 | +to crash there - that would annoy anyone who wants to use logging for their own module. Note that if `RUST_LOG` is unset (the default), then the code will not run - this means that if your logging code panics, then no-one will know it until someone tries to use logging to find *another* bug. |
| 203 | + |
| 204 | +If you *need* to do an expensive operation in a log, be aware that while log expressions are *evaluated* even if logging is not enabled in your module, they are not *formatted* unless it *is*. This means you can put your expensive/crashy operations inside an `fmt::Debug` impl, and they will not be run unless your log is enabled: |
| 205 | + |
| 206 | +```Rust |
| 207 | +use std::fmt; |
| 208 | + |
| 209 | +struct ExpensiveOperationContainer<'a, 'gcx, 'tcx> |
| 210 | + where 'tcx: 'gcx, 'a: 'tcx |
| 211 | +{ |
| 212 | + tcx: TyCtxt<'a, 'gcx, 'tcx> |
| 213 | +} |
| 214 | + |
| 215 | +impl<'a, 'gcx, 'tcx> fmt::Debug for ExpensiveOperationContainer<'a, 'gcx, 'tcx> { |
| 216 | + fn fmt(&self, fmt: &mut fmt::Formatter) -> fmt::Result { |
| 217 | + let value = random_operation(tcx); |
| 218 | + fmt::Debug::fmt(&value, fmt) |
| 219 | + } |
| 220 | +} |
| 221 | + |
| 222 | +debug!("{:?}", ExpensiveOperationContainer { tcx }); |
| 223 | +``` |
| 224 | + |
| 225 | +## Formatting Graphviz output (.dot files) |
| 226 | +[formatting-graphviz-output]: #formatting-graphviz-output |
| 227 | + |
| 228 | +Some compiler options for debugging specific features yield graphviz graphs - e.g. |
| 229 | +the `#[rustc_mir(borrowck_graphviz_postflow="suffix.dot")]` attribute |
| 230 | +dumps various borrow-checker dataflow graphs. |
| 231 | + |
| 232 | +These all produce `.dot` files. To view these files, install graphviz (e.g. |
| 233 | +`apt-get install graphviz`) and then run the following commands: |
| 234 | + |
| 235 | +``` |
| 236 | +$ dot -T pdf maybe_init_suffix.dot > maybe_init_suffix.pdf |
| 237 | +$ firefox maybe_init_suffix.pdf # Or your favorite pdf viewer |
| 238 | +``` |
| 239 | + |
| 240 | +## Debugging LLVM |
| 241 | +[debugging-llvm]: #debugging-llvm |
| 242 | + |
| 243 | +LLVM is a big project on its own that probably needs to have its own debugging |
| 244 | +document (not that I could find one). But here are some tips that are important |
| 245 | +in a rustc context: |
| 246 | + |
| 247 | +The official compilers (including nightlies) have LLVM assertions disabled, |
| 248 | +which means that LLVM assertion failures can show up as compiler crashes (not |
| 249 | +ICEs but "real" crashes) and other sorts of weird behavior. If you are |
| 250 | +encountering these, it is a good idea to try using a compiler with LLVM |
| 251 | +assertions enabled - either an "alt" nightly or a compiler you build yourself |
| 252 | +by setting `[llvm] assertions=true` in your config.toml - and |
| 253 | +see whether anything turns up. |
| 254 | + |
| 255 | +The rustc build process builds the LLVM tools into `./build/<host-triple>/llvm/bin`. They can be called directly. |
| 256 | + |
| 257 | +The default rustc compilation pipeline has multiple codegen units, which is hard |
| 258 | +to replicate manually and means that LLVM is called multiple times in parallel. |
| 259 | +If you can get away with it (i.e. if it doesn't make your bug disappear), |
| 260 | +passing `-C codegen-units=1` to rustc will make debugging easier. |
| 261 | + |
| 262 | +If you want to play with the optimization pipeline, you can use the `opt` from |
| 263 | +there on the IR rustc emits with `--emit=llvm-ir`. Note |
| 264 | +that rustc emits different IR depending on whether `-O` is enabled, even without |
| 265 | +LLVM's optimizations, so if you want to play with the IR rustc emits, you should: |
| 266 | +``` |
| 267 | +$ rustc +local my-file.rs --emit=llvm-ir -O -C no-prepopulate-passes \ |
| 268 | + -C codegen-units=1 |
| 269 | +$ OPT=./build/$TRIPLE/llvm/bin/opt |
| 270 | +$ $OPT -S -O2 < my-file.ll > my |
| 271 | +``` |
| 272 | + |
| 273 | +If you just want to get the LLVM IR during the LLVM pipeline, to e.g. see which |
| 274 | +IR causes an optimization-time assertion to fail, or to see when |
| 275 | +LLVM performs a particular optimization, you can pass the rustc flag |
| 276 | +`-C llvm-args=-print-after-all`, and possibly add |
| 277 | +`-C llvm-args='-filter-print-funcs=EXACT_FUNCTION_NAME` (e.g. |
| 278 | +`-C llvm-args='-filter-print-funcs=_ZN11collections3str21_$LT$impl$u20$str$GT$7replace17hbe10ea2e7c809b0bE'`). |
| 279 | + |
| 280 | +That produces a lot of output into standard error, so you'll want to pipe |
| 281 | +that to some file. Also, if you are using neither `-filter-print-funcs` nor |
| 282 | +`-C codegen-units=1`, then, because the multiple codegen units run in parallel, |
| 283 | +the printouts will mix together and you won't be able to read anything. |
| 284 | + |
| 285 | +If you want just the IR for a specific function (say, you want to see |
| 286 | +why it causes an assertion or doesn't optimize correctly), you can use |
| 287 | +`llvm-extract`, e.g. |
| 288 | +``` |
| 289 | +$ ./build/$TRIPLE/llvm/bin/llvm-extract \ |
| 290 | + -func='_ZN11collections3str21_$LT$impl$u20$str$GT$7replace17hbe10ea2e7c809b0bE' \ |
| 291 | + -S \ |
| 292 | + < unextracted.ll \ |
| 293 | + > extracted.ll |
| 294 | +``` |
| 295 | + |
| 296 | +[env-logger]: https://docs.rs/env_logger/0.4.3/env_logger/ |
0 commit comments