| <!DOCTYPE HTML> |
| <html lang="en" class="light sidebar-visible" dir="ltr"> |
| <head> |
| <!-- Book generated using mdBook --> |
| <meta charset="UTF-8"> |
| <title>Using the tracing/logging instrumentation - Rust Compiler Development Guide</title> |
| |
| |
| <!-- Custom HTML head --> |
| |
| <meta name="description" content="A guide to developing the Rust compiler (rustc)"> |
| <meta name="viewport" content="width=device-width, initial-scale=1"> |
| <meta name="theme-color" content="#ffffff"> |
| |
| <link rel="icon" href="favicon.svg"> |
| <link rel="shortcut icon" href="favicon.png"> |
| <link rel="stylesheet" href="css/variables.css"> |
| <link rel="stylesheet" href="css/general.css"> |
| <link rel="stylesheet" href="css/chrome.css"> |
| <link rel="stylesheet" href="css/print.css" media="print"> |
| |
| <!-- Fonts --> |
| <link rel="stylesheet" href="FontAwesome/css/font-awesome.css"> |
| <link rel="stylesheet" href="fonts/fonts.css"> |
| |
| <!-- Highlight.js Stylesheets --> |
| <link rel="stylesheet" id="highlight-css" href="highlight.css"> |
| <link rel="stylesheet" id="tomorrow-night-css" href="tomorrow-night.css"> |
| <link rel="stylesheet" id="ayu-highlight-css" href="ayu-highlight.css"> |
| |
| <!-- Custom theme stylesheets --> |
| |
| |
| <!-- Provide site root and default themes to javascript --> |
| <script> |
| const path_to_root = ""; |
| const default_light_theme = "light"; |
| const default_dark_theme = "navy"; |
| </script> |
| <!-- Start loading toc.js asap --> |
| <script src="toc.js"></script> |
| </head> |
| <body> |
| <div id="body-container"> |
| <!-- Work around some values being stored in localStorage wrapped in quotes --> |
| <script> |
| try { |
| let theme = localStorage.getItem('mdbook-theme'); |
| let sidebar = localStorage.getItem('mdbook-sidebar'); |
| |
| if (theme.startsWith('"') && theme.endsWith('"')) { |
| localStorage.setItem('mdbook-theme', theme.slice(1, theme.length - 1)); |
| } |
| |
| if (sidebar.startsWith('"') && sidebar.endsWith('"')) { |
| localStorage.setItem('mdbook-sidebar', sidebar.slice(1, sidebar.length - 1)); |
| } |
| } catch (e) { } |
| </script> |
| |
| <!-- Set the theme before any content is loaded, prevents flash --> |
| <script> |
| const default_theme = window.matchMedia("(prefers-color-scheme: dark)").matches ? default_dark_theme : default_light_theme; |
| let theme; |
| try { theme = localStorage.getItem('mdbook-theme'); } catch(e) { } |
| if (theme === null || theme === undefined) { theme = default_theme; } |
| const html = document.documentElement; |
| html.classList.remove('light') |
| html.classList.add(theme); |
| html.classList.add("js"); |
| </script> |
| |
| <input type="checkbox" id="sidebar-toggle-anchor" class="hidden"> |
| |
| <!-- Hide / unhide sidebar before it is displayed --> |
| <script> |
| let sidebar = null; |
| const sidebar_toggle = document.getElementById("sidebar-toggle-anchor"); |
| if (document.body.clientWidth >= 1080) { |
| try { sidebar = localStorage.getItem('mdbook-sidebar'); } catch(e) { } |
| sidebar = sidebar || 'visible'; |
| } else { |
| sidebar = 'hidden'; |
| } |
| sidebar_toggle.checked = sidebar === 'visible'; |
| html.classList.remove('sidebar-visible'); |
| html.classList.add("sidebar-" + sidebar); |
| </script> |
| |
| <nav id="sidebar" class="sidebar" aria-label="Table of contents"> |
| <!-- populated by js --> |
| <mdbook-sidebar-scrollbox class="sidebar-scrollbox"></mdbook-sidebar-scrollbox> |
| <noscript> |
| <iframe class="sidebar-iframe-outer" src="toc.html"></iframe> |
| </noscript> |
| <div id="sidebar-resize-handle" class="sidebar-resize-handle"> |
| <div class="sidebar-resize-indicator"></div> |
| </div> |
| </nav> |
| |
| <div id="page-wrapper" class="page-wrapper"> |
| |
| <div class="page"> |
| <div id="menu-bar-hover-placeholder"></div> |
| <div id="menu-bar" class="menu-bar sticky"> |
| <div class="left-buttons"> |
| <label id="sidebar-toggle" class="icon-button" for="sidebar-toggle-anchor" title="Toggle Table of Contents" aria-label="Toggle Table of Contents" aria-controls="sidebar"> |
| <i class="fa fa-bars"></i> |
| </label> |
| <button id="theme-toggle" class="icon-button" type="button" title="Change theme" aria-label="Change theme" aria-haspopup="true" aria-expanded="false" aria-controls="theme-list"> |
| <i class="fa fa-paint-brush"></i> |
| </button> |
| <ul id="theme-list" class="theme-popup" aria-label="Themes" role="menu"> |
| <li role="none"><button role="menuitem" class="theme" id="default_theme">Auto</button></li> |
| <li role="none"><button role="menuitem" class="theme" id="light">Light</button></li> |
| <li role="none"><button role="menuitem" class="theme" id="rust">Rust</button></li> |
| <li role="none"><button role="menuitem" class="theme" id="coal">Coal</button></li> |
| <li role="none"><button role="menuitem" class="theme" id="navy">Navy</button></li> |
| <li role="none"><button role="menuitem" class="theme" id="ayu">Ayu</button></li> |
| </ul> |
| <button id="search-toggle" class="icon-button" type="button" title="Search. (Shortkey: s)" aria-label="Toggle Searchbar" aria-expanded="false" aria-keyshortcuts="S" aria-controls="searchbar"> |
| <i class="fa fa-search"></i> |
| </button> |
| </div> |
| |
| <h1 class="menu-title">Rust Compiler Development Guide</h1> |
| |
| <div class="right-buttons"> |
| <a href="print.html" title="Print this book" aria-label="Print this book"> |
| <i id="print-button" class="fa fa-print"></i> |
| </a> |
| <a href="https://github.com/rust-lang/rustc-dev-guide" title="Git repository" aria-label="Git repository"> |
| <i id="git-repository-button" class="fa fa-github"></i> |
| </a> |
| <a href="https://github.com/rust-lang/rustc-dev-guide/edit/master/src/tracing.md" title="Suggest an edit" aria-label="Suggest an edit"> |
| <i id="git-edit-button" class="fa fa-edit"></i> |
| </a> |
| |
| </div> |
| </div> |
| |
| <div id="search-wrapper" class="hidden"> |
| <form id="searchbar-outer" class="searchbar-outer"> |
| <input type="search" id="searchbar" name="searchbar" placeholder="Search this book ..." aria-controls="searchresults-outer" aria-describedby="searchresults-header"> |
| </form> |
| <div id="searchresults-outer" class="searchresults-outer hidden"> |
| <div id="searchresults-header" class="searchresults-header"></div> |
| <ul id="searchresults"> |
| </ul> |
| </div> |
| </div> |
| |
| <!-- Apply ARIA attributes after the sidebar and the sidebar toggle button are added to the DOM --> |
| <script> |
| document.getElementById('sidebar-toggle').setAttribute('aria-expanded', sidebar === 'visible'); |
| document.getElementById('sidebar').setAttribute('aria-hidden', sidebar !== 'visible'); |
| Array.from(document.querySelectorAll('#sidebar a')).forEach(function(link) { |
| link.setAttribute('tabIndex', sidebar === 'visible' ? 0 : -1); |
| }); |
| </script> |
| |
| <div id="content" class="content"> |
| <main> |
| <h1 id="using-tracing-to-debug-the-compiler"><a class="header" href="#using-tracing-to-debug-the-compiler">Using tracing to debug the compiler</a></h1> |
| <ul> |
| <li><a href="#function-level-filters">Function level filters</a> |
| <ul> |
| <li><a href="#i-dont-want-everything">I don't want everything</a></li> |
| <li><a href="#i-dont-want-all-calls">I don't want all calls</a></li> |
| </ul> |
| </li> |
| <li><a href="#query-level-filters">Query level filters</a></li> |
| <li><a href="#broad-module-level-filters">Broad module level filters</a></li> |
| <li><a href="#log-colors">Log colors</a></li> |
| <li><a href="#how-to-keep-or-remove-debug-and-trace-calls-from-the-resulting-binary">How to keep or remove <code>debug!</code> and <code>trace!</code> calls from the resulting binary</a></li> |
| <li><a href="#logging-etiquette-and-conventions">Logging etiquette and conventions</a></li> |
| </ul> |
| <p>The compiler has a lot of <a href="https://docs.rs/tracing/0.1/tracing/macro.debug.html"><code>debug!</code></a> (or <code>trace!</code>) 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.</p> |
| <p>To see the logs, you need to set the <code>RUSTC_LOG</code> environment variable to your |
| log filter. The full syntax of the log filters can be found in the <a href="https://docs.rs/tracing-subscriber/0.2.24/tracing_subscriber/filter/struct.EnvFilter.html#directives">rustdoc |
| of <code>tracing-subscriber</code></a>.</p> |
| <h2 id="function-level-filters"><a class="header" href="#function-level-filters">Function level filters</a></h2> |
| <p>Lots of functions in rustc are annotated with</p> |
| <pre><code>#[instrument(level = "debug", skip(self))] |
| fn foo(&self, bar: Type) {} |
| </code></pre> |
| <p>which allows you to use</p> |
| <pre><code>RUSTC_LOG=[foo] |
| </code></pre> |
| <p>to do the following all at once</p> |
| <ul> |
| <li>log all function calls to <code>foo</code></li> |
| <li>log the arguments (except for those in the <code>skip</code> list)</li> |
| <li>log everything (from anywhere else in the compiler) until the function returns</li> |
| </ul> |
| <h3 id="i-dont-want-everything"><a class="header" href="#i-dont-want-everything">I don't want everything</a></h3> |
| <p>Depending on the scope of the function, you may not want to log everything in its body. |
| As an example: the <code>do_mir_borrowck</code> function will dump hundreds of lines even for trivial |
| code being borrowchecked.</p> |
| <p>Since you can combine all filters, you can add a crate/module path, e.g.</p> |
| <pre><code>RUSTC_LOG=rustc_borrowck[do_mir_borrowck] |
| </code></pre> |
| <h3 id="i-dont-want-all-calls"><a class="header" href="#i-dont-want-all-calls">I don't want all calls</a></h3> |
| <p>If you are compiling libcore, you likely don't want <em>all</em> borrowck dumps, but only one |
| for a specific function. You can filter function calls by their arguments by regexing them.</p> |
| <pre><code>RUSTC_LOG=[do_mir_borrowck{id=\.\*from_utf8_unchecked\.\*}] |
| </code></pre> |
| <p>will only give you the logs of borrowchecking <code>from_utf8_unchecked</code>. Note that you will |
| still get a short message per ignored <code>do_mir_borrowck</code>, 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.</p> |
| <h2 id="query-level-filters"><a class="header" href="#query-level-filters">Query level filters</a></h2> |
| <p>Every <a href="query.html">query</a> is automatically tagged with a logging span so that |
| you can display all log messages during the execution of the query. For |
| example, if you want to log everything during type checking:</p> |
| <pre><code>RUSTC_LOG=[typeck] |
| </code></pre> |
| <p>The query arguments are included as a tracing field which means that you can |
| filter on the debug display of the arguments. For example, the <code>typeck</code> query |
| has an argument <code>key: LocalDefId</code> of what is being checked. You can use a |
| regex to match on that <code>LocalDefId</code> to log type checking for a specific |
| function:</p> |
| <pre><code>RUSTC_LOG=[typeck{key=.*name_of_item.*}] |
| </code></pre> |
| <p>Different queries have different arguments. You can find a list of queries and |
| their arguments in |
| <a href="https://github.com/rust-lang/rust/blob/master/compiler/rustc_middle/src/query/mod.rs#L18"><code>rustc_middle/src/query/mod.rs</code></a>.</p> |
| <h2 id="broad-module-level-filters"><a class="header" href="#broad-module-level-filters">Broad module level filters</a></h2> |
| <p>You can also use filters similar to the <code>log</code> 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.</p> |
| <p>Your log filter can be just <code>debug</code> to get all <code>debug!</code> output and |
| higher (e.g., it will also include <code>info!</code>), or <code>path::to::module</code> to get <em>all</em> |
| output (which will include <code>trace!</code>) from a particular module, or |
| <code>path::to::module=debug</code> to get <code>debug!</code> output and higher from a particular |
| module.</p> |
| <p>For example, to get the <code>debug!</code> output and higher for a specific module, you |
| can run the compiler with <code>RUSTC_LOG=path::to::module=debug rustc my-file.rs</code>. |
| All <code>debug!</code> output will then appear in standard error.</p> |
| <p>Note that you can use a partial path and the filter will still work. For |
| example, if you want to see <code>info!</code> output from only |
| <code>rustdoc::passes::collect_intra_doc_links</code>, you could use |
| <code>RUSTDOC_LOG=rustdoc::passes::collect_intra_doc_links=info</code> <em>or</em> you could use |
| <code>RUSTDOC_LOG=rustdoc::passes::collect_intra=info</code>.</p> |
| <p>If you are developing rustdoc, use <code>RUSTDOC_LOG</code> instead. If you are developing |
| Miri, use <code>MIRI_LOG</code> instead. You get the idea :)</p> |
| <p>See the <a href="https://docs.rs/tracing"><code>tracing</code></a> crate's docs, and specifically the docs for <a href="https://docs.rs/tracing/0.1/tracing/macro.debug.html"><code>debug!</code></a> to |
| see the full syntax you can use. (Note: unlike the compiler, the <a href="https://docs.rs/tracing"><code>tracing</code></a> |
| crate and its examples use the <code>RUST_LOG</code> environment variable. rustc, rustdoc, |
| and other tools set custom environment variables.)</p> |
| <p><strong>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)</strong>. It's typically a good idea to pipe standard error to a file and |
| look at the log output with a text editor.</p> |
| <p>So, to put it together:</p> |
| <pre><code class="language-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 all logs in `rustc_codegen_ssa` and `rustc_resolve`. |
| $ RUSTC_LOG=rustc_codegen_ssa,rustc_resolve 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 |
| </code></pre> |
| <h2 id="log-colors"><a class="header" href="#log-colors">Log colors</a></h2> |
| <p>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 <code>less</code>. But then there won't be any colors, which makes |
| it hard to pick out what you're looking for!</p> |
| <p>You can override whether to have colors in log output with the <code>RUSTC_LOG_COLOR</code> |
| environment variable (or <code>RUSTDOC_LOG_COLOR</code> for rustdoc, or <code>MIRI_LOG_COLOR</code> |
| for Miri, etc.). There are three options: <code>auto</code> (the default), <code>always</code>, and |
| <code>never</code>. So, if you want to enable colors when piping to <code>less</code>, use something |
| similar to this command:</p> |
| <pre><code class="language-bash"># The `-R` switch tells less to print ANSI colors without escaping them. |
| $ RUSTC_LOG=debug RUSTC_LOG_COLOR=always rustc +stage1 ... | less -R |
| </code></pre> |
| <p>Note that <code>MIRI_LOG_COLOR</code> will only color logs that come from Miri, not logs |
| from rustc functions that Miri calls. Use <code>RUSTC_LOG_COLOR</code> to color logs from |
| rustc.</p> |
| <h2 id="how-to-keep-or-remove-debug-and-trace-calls-from-the-resulting-binary"><a class="header" href="#how-to-keep-or-remove-debug-and-trace-calls-from-the-resulting-binary">How to keep or remove <code>debug!</code> and <code>trace!</code> calls from the resulting binary</a></h2> |
| <p>While calls to <code>error!</code>, <code>warn!</code> and <code>info!</code> are included in every build of the compiler, |
| calls to <code>debug!</code> and <code>trace!</code> are only included in the program if |
| <code>debug-logging=true</code> is turned on in bootstrap.toml (it is |
| turned off by default), so if you don't see <code>DEBUG</code> logs, especially |
| if you run the compiler with <code>RUSTC_LOG=rustc rustc some.rs</code> and only see |
| <code>INFO</code> logs, make sure that <code>debug-logging=true</code> is turned on in your |
| bootstrap.toml.</p> |
| <h2 id="logging-etiquette-and-conventions"><a class="header" href="#logging-etiquette-and-conventions">Logging etiquette and conventions</a></h2> |
| <p>Because calls to <code>debug!</code> are removed by default, in most cases, don't worry |
| about the performance of adding "unnecessary" calls to <code>debug!</code> and leaving them in code you |
| commit - they won't slow down the performance of what we ship.</p> |
| <p>That said, there can also be excessive tracing calls, especially |
| when they are redundant with other calls nearby or in functions called from |
| here. There is no perfect balance to hit here, and is left to the reviewer's |
| discretion to decide whether to let you leave <code>debug!</code> statements in or whether to ask |
| you to remove them before merging.</p> |
| <p>It may be preferable to use <code>trace!</code> over <code>debug!</code> for very noisy logs.</p> |
| <p>A loosely followed convention is to use <code>#[instrument(level = "debug")]</code> |
| (<a href="https://docs.rs/tracing-attributes/0.1.17/tracing_attributes/attr.instrument.html">also see the attribute's documentation</a>) |
| in favour of <code>debug!("foo(...)")</code> at the start of a function <code>foo</code>. |
| Within functions, prefer <code>debug!(?variable.field)</code> over <code>debug!("xyz = {:?}", variable.field)</code> |
| and <code>debug!(bar = ?var.method(arg))</code> over <code>debug!("bar = {:?}", var.method(arg))</code>. |
| The documentation for this syntax can be found <a href="https://docs.rs/tracing/0.1.28/tracing/#recording-fields">here</a>.</p> |
| <p>One thing to be <strong>careful</strong> of is <strong>expensive</strong> operations in logs.</p> |
| <p>If in the module <code>rustc::foo</code> you have a statement</p> |
| <pre><code class="language-Rust">debug!(x = ?random_operation(tcx)); |
| </code></pre> |
| <p>Then if someone runs a debug <code>rustc</code> with <code>RUSTC_LOG=rustc::foo</code>, then |
| <code>random_operation()</code> will run. <code>RUSTC_LOG</code> filters that do not enable this |
| debug statement will not execute <code>random_operation</code>.</p> |
| <p>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 that module. |
| No-one will know it until someone tries to use logging to find <em>another</em> bug.</p> |
| |
| </main> |
| |
| <nav class="nav-wrapper" aria-label="Page navigation"> |
| <!-- Mobile navigation buttons --> |
| <a rel="prev" href="compiler-debugging.html" class="mobile-nav-chapters previous" title="Previous chapter" aria-label="Previous chapter" aria-keyshortcuts="Left"> |
| <i class="fa fa-angle-left"></i> |
| </a> |
| |
| <a rel="next prefetch" href="profiling.html" class="mobile-nav-chapters next" title="Next chapter" aria-label="Next chapter" aria-keyshortcuts="Right"> |
| <i class="fa fa-angle-right"></i> |
| </a> |
| |
| <div style="clear: both"></div> |
| </nav> |
| </div> |
| </div> |
| |
| <nav class="nav-wide-wrapper" aria-label="Page navigation"> |
| <a rel="prev" href="compiler-debugging.html" class="nav-chapters previous" title="Previous chapter" aria-label="Previous chapter" aria-keyshortcuts="Left"> |
| <i class="fa fa-angle-left"></i> |
| </a> |
| |
| <a rel="next prefetch" href="profiling.html" class="nav-chapters next" title="Next chapter" aria-label="Next chapter" aria-keyshortcuts="Right"> |
| <i class="fa fa-angle-right"></i> |
| </a> |
| </nav> |
| |
| </div> |
| |
| |
| |
| |
| <script> |
| window.playground_copyable = true; |
| </script> |
| |
| |
| <script src="elasticlunr.min.js"></script> |
| <script src="mark.min.js"></script> |
| <script src="searcher.js"></script> |
| |
| <script src="clipboard.min.js"></script> |
| <script src="highlight.js"></script> |
| <script src="book.js"></script> |
| |
| <!-- Custom JS scripts --> |
| <script src="mermaid.min.js"></script> |
| <script src="mermaid-init.js"></script> |
| |
| |
| </div> |
| </body> |
| </html> |
