399 lines
23 KiB
HTML
399 lines
23 KiB
HTML
<!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>
|