Google Git
Sign in
rust / rust-lang / rustc-dev-guide / refs/heads/gh-pages / . / profiling / with_perf.html
blob: 01c0625a9cce705616d880f514272f3b5274c476 [file] [log] [blame]
<!DOCTYPE HTML>
<html lang="en" class="light sidebar-visible" dir="ltr">
<head>
<!-- Book generated using mdBook -->
<meta charset="UTF-8">
<title>with the linux perf tool - 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/profiling/with_perf.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="profiling-with-perf"><a class="header" href="#profiling-with-perf">Profiling with perf</a></h1>
<p>This is a guide for how to profile rustc with <a href="https://perf.wiki.kernel.org/index.php/Main_Page">perf</a>.</p>
<h2 id="initial-steps"><a class="header" href="#initial-steps">Initial steps</a></h2>
<ul>
<li>Get a clean checkout of rust-lang/master, or whatever it is you want
to profile.</li>
<li>Set the following settings in your <code>bootstrap.toml</code>:
<ul>
<li><code>rust.debuginfo-level = 1</code> - enables line debuginfo</li>
<li><code>rust.jemalloc = false</code> - lets you do memory use profiling with valgrind</li>
<li>leave everything else the defaults</li>
</ul>
</li>
<li>Run <code>./x build</code> to get a full build</li>
<li>Make a rustup toolchain pointing to that result
<ul>
<li>see <a href="../building/how-to-build-and-run.html#toolchain">the "build and run" section for instructions</a></li>
</ul>
</li>
</ul>
<h2 id="gathering-a-perf-profile"><a class="header" href="#gathering-a-perf-profile">Gathering a perf profile</a></h2>
<p>perf is an excellent tool on linux that can be used to gather and
analyze all kinds of information. Mostly it is used to figure out
where a program spends its time. It can also be used for other sorts
of events, though, like cache misses and so forth.</p>
<h3 id="the-basics"><a class="header" href="#the-basics">The basics</a></h3>
<p>The basic <code>perf</code> command is this:</p>
<pre><code class="language-bash">perf record -F99 --call-graph dwarf XXX
</code></pre>
<p>The <code>-F99</code> tells perf to sample at 99 Hz, which avoids generating too
much data for longer runs (why 99 Hz you ask? It is often chosen
because it is unlikely to be in lockstep with other periodic
activity). The <code>--call-graph dwarf</code> tells perf to get call-graph
information from debuginfo, which is accurate. The <code>XXX</code> is the
command you want to profile. So, for example, you might do:</p>
<pre><code class="language-bash">perf record -F99 --call-graph dwarf cargo +&lt;toolchain&gt; rustc
</code></pre>
<p>to run <code>cargo</code> -- here <code>&lt;toolchain&gt;</code> should be the name of the toolchain
you made in the beginning. But there are some things to be aware of:</p>
<ul>
<li>You probably don't want to profile the time spend building
dependencies. So something like <code>cargo build; cargo clean -p $C</code> may
be helpful (where <code>$C</code> is the crate name)
<ul>
<li>Though usually I just do <code>touch src/lib.rs</code> and rebuild instead. =)</li>
</ul>
</li>
<li>You probably don't want incremental messing about with your
profile. So something like <code>CARGO_INCREMENTAL=0</code> can be helpful.</li>
</ul>
<p>In case to avoid the issue of <code>addr2line xxx/elf: could not read first record</code> when reading
collected data from <code>cargo</code>, you may need use the latest version of <code>addr2line</code>:</p>
<pre><code class="language-bash">cargo install addr2line --features="bin"
</code></pre>
<h3 id="gathering-a-perf-profile-from-a-perfrust-langorg-test"><a class="header" href="#gathering-a-perf-profile-from-a-perfrust-langorg-test">Gathering a perf profile from a <code>perf.rust-lang.org</code> test</a></h3>
<p>Often we want to analyze a specific test from <code>perf.rust-lang.org</code>.
The easiest way to do that is to use the <a href="https://github.com/rust-lang/rustc-perf">rustc-perf</a>
benchmarking suite, this approach is described <a href="with_rustc_perf.html">here</a>.</p>
<p>Instead of using the benchmark suite CLI, you can also profile the benchmarks manually. First,
you need to clone the <a href="https://github.com/rust-lang/rustc-perf">rustc-perf</a> repository:</p>
<pre><code class="language-bash">$ git clone https://github.com/rust-lang/rustc-perf
</code></pre>
<p>and then find the source code of the test that you want to profile. Sources for the tests
are found in <a href="https://github.com/rust-lang/rustc-perf/tree/master/collector/compile-benchmarks">the <code>collector/compile-benchmarks</code> directory</a>
and <a href="https://github.com/rust-lang/rustc-perf/tree/master/collector/runtime-benchmarks">the <code>collector/runtime-benchmarks</code> directory</a>. So let's
go into the directory of a specific test; we'll use <code>clap-rs</code> as an example:</p>
<pre><code class="language-bash">cd collector/compile-benchmarks/clap-3.1.6
</code></pre>
<p>In this case, let's say we want to profile the <code>cargo check</code>
performance. In that case, I would first run some basic commands to
build the dependencies:</p>
<pre><code class="language-bash"># Setup: first clean out any old results and build the dependencies:
cargo +&lt;toolchain&gt; clean
CARGO_INCREMENTAL=0 cargo +&lt;toolchain&gt; check
</code></pre>
<p>(Again, <code>&lt;toolchain&gt;</code> should be replaced with the name of the
toolchain we made in the first step.)</p>
<p>Next: we want record the execution time for <em>just</em> the clap-rs crate,
running cargo check. I tend to use <code>cargo rustc</code> for this, since it
also allows me to add explicit flags, which we'll do later on.</p>
<pre><code class="language-bash">touch src/lib.rs
CARGO_INCREMENTAL=0 perf record -F99 --call-graph dwarf cargo rustc --profile check --lib
</code></pre>
<p>Note that final command: it's a doozy! It uses the <code>cargo rustc</code>
command, which executes rustc with (potentially) additional options;
the <code>--profile check</code> and <code>--lib</code> options specify that we are doing a
<code>cargo check</code> execution, and that this is a library (not a binary).</p>
<p>At this point, we can use <code>perf</code> tooling to analyze the results. For example:</p>
<pre><code class="language-bash">perf report
</code></pre>
<p>will open up an interactive TUI program. In simple cases, that can be
helpful. For more detailed examination, the <a href="https://github.com/nikomatsakis/perf-focus"><code>perf-focus</code> tool</a>
can be helpful; it is covered below.</p>
<p><strong>A note of caution.</strong> Each of the rustc-perf tests is its own special
snowflake. In particular, some of them are not libraries, in which
case you would want to do <code>touch src/main.rs</code> and avoid passing
<code>--lib</code>. I'm not sure how best to tell which test is which to be
honest.</p>
<h3 id="gathering-nll-data"><a class="header" href="#gathering-nll-data">Gathering NLL data</a></h3>
<p>If you want to profile an NLL run, you can just pass extra options to
the <code>cargo rustc</code> command, like so:</p>
<pre><code class="language-bash">touch src/lib.rs
CARGO_INCREMENTAL=0 perf record -F99 --call-graph dwarf cargo rustc --profile check --lib -- -Z borrowck=mir
</code></pre>
<h2 id="analyzing-a-perf-profile-with-perf-focus"><a class="header" href="#analyzing-a-perf-profile-with-perf-focus">Analyzing a perf profile with <code>perf focus</code></a></h2>
<p>Once you've gathered a perf profile, we want to get some information
about it. For this, I personally use <a href="https://github.com/nikomatsakis/perf-focus">perf focus</a>. It's a kind of
simple but useful tool that lets you answer queries like:</p>
<ul>
<li>"how much time was spent in function F" (no matter where it was called from)</li>
<li>"how much time was spent in function F when it was called from G"</li>
<li>"how much time was spent in function F <em>excluding</em> time spent in G"</li>
<li>"what functions does F call and how much time does it spend in them"</li>
</ul>
<p>To understand how it works, you have to know just a bit about
perf. Basically, perf works by <em>sampling</em> your process on a regular
basis (or whenever some event occurs). For each sample, perf gathers a
backtrace. <code>perf focus</code> lets you write a regular expression that tests
which functions appear in that backtrace, and then tells you which
percentage of samples had a backtrace that met the regular
expression. It's probably easiest to explain by walking through how I
would analyze NLL performance.</p>
<h3 id="installing-perf-focus"><a class="header" href="#installing-perf-focus">Installing <code>perf-focus</code></a></h3>
<p>You can install perf-focus using <code>cargo install</code>:</p>
<pre><code class="language-bash">cargo install perf-focus
</code></pre>
<h3 id="example-how-much-time-is-spent-in-mir-borrowck"><a class="header" href="#example-how-much-time-is-spent-in-mir-borrowck">Example: How much time is spent in MIR borrowck?</a></h3>
<p>Let's say we've gathered the NLL data for a test. We'd like to know
how much time it is spending in the MIR borrow-checker. The "main"
function of the MIR borrowck is called <code>do_mir_borrowck</code>, so we can do
this command:</p>
<pre><code class="language-bash">$ perf focus '{do_mir_borrowck}'
Matcher : {do_mir_borrowck}
Matches : 228
Not Matches: 542
Percentage : 29%
</code></pre>
<p>The <code>'{do_mir_borrowck}'</code> argument is called the <strong>matcher</strong>. It
specifies the test to be applied on the backtrace. In this case, the
<code>{X}</code> indicates that there must be <em>some</em> function on the backtrace
that meets the regular expression <code>X</code>. In this case, that regex is
just the name of the function we want (in fact, it's a subset of the name;
the full name includes a bunch of other stuff, like the module
path). In this mode, perf-focus just prints out the percentage of
samples where <code>do_mir_borrowck</code> was on the stack: in this case, 29%.</p>
<p><strong>A note about c++filt.</strong> To get the data from <code>perf</code>, <code>perf focus</code>
currently executes <code>perf script</code> (perhaps there is a better
way...). I've sometimes found that <code>perf script</code> outputs C++ mangled
names. This is annoying. You can tell by running <code>perf script | head</code> yourself — if you see names like <code>5rustc6middle</code> instead of
<code>rustc::middle</code>, then you have the same problem. You can solve this
by doing:</p>
<pre><code class="language-bash">perf script | c++filt | perf focus --from-stdin ...
</code></pre>
<p>This will pipe the output from <code>perf script</code> through <code>c++filt</code> and
should mostly convert those names into a more friendly format. The
<code>--from-stdin</code> flag to <code>perf focus</code> tells it to get its data from
stdin, rather than executing <code>perf focus</code>. We should make this more
convenient (at worst, maybe add a <code>c++filt</code> option to <code>perf focus</code>, or
just always use it — it's pretty harmless).</p>
<h3 id="example-how-much-time-does-mir-borrowck-spend-solving-traits"><a class="header" href="#example-how-much-time-does-mir-borrowck-spend-solving-traits">Example: How much time does MIR borrowck spend solving traits?</a></h3>
<p>Perhaps we'd like to know how much time MIR borrowck spends in the
trait checker. We can ask this using a more complex regex:</p>
<pre><code class="language-bash">$ perf focus '{do_mir_borrowck}..{^rustc::traits}'
Matcher : {do_mir_borrowck},..{^rustc::traits}
Matches : 12
Not Matches: 1311
Percentage : 0%
</code></pre>
<p>Here we used the <code>..</code> operator to ask "how often do we have
<code>do_mir_borrowck</code> on the stack and then, later, some function whose
name begins with <code>rustc::traits</code>?" (basically, code in that module). It
turns out the answer is "almost never" — only 12 samples fit that
description (if you ever see <em>no</em> samples, that often indicates your
query is messed up).</p>
<p>If you're curious, you can find out exactly which samples by using the
<code>--print-match</code> option. This will print out the full backtrace for
each sample. The <code>|</code> at the front of the line indicates the part that
the regular expression matched.</p>
<h3 id="example-where-does-mir-borrowck-spend-its-time"><a class="header" href="#example-where-does-mir-borrowck-spend-its-time">Example: Where does MIR borrowck spend its time?</a></h3>
<p>Often we want to do more "explorational" queries. Like, we know that
MIR borrowck is 29% of the time, but where does that time get spent?
For that, the <code>--tree-callees</code> option is often the best tool. You
usually also want to give <code>--tree-min-percent</code> or
<code>--tree-max-depth</code>. The result looks like this:</p>
<pre><code class="language-bash">$ perf focus '{do_mir_borrowck}' --tree-callees --tree-min-percent 3
Matcher : {do_mir_borrowck}
Matches : 577
Not Matches: 746
Percentage : 43%
Tree
| matched `{do_mir_borrowck}` (43% total, 0% self)
: | rustc_borrowck::nll::compute_regions (20% total, 0% self)
: : | rustc_borrowck::nll::type_check::type_check_internal (13% total, 0% self)
: : : | core::ops::function::FnOnce::call_once (5% total, 0% self)
: : : : | rustc_borrowck::nll::type_check::liveness::generate (5% total, 3% self)
: : : | &lt;rustc_borrowck::nll::type_check::TypeVerifier&lt;'a, 'b, 'tcx&gt; as rustc::mir::visit::Visitor&lt;'tcx&gt;&gt;::visit_mir (3% total, 0% self)
: | rustc::mir::visit::Visitor::visit_mir (8% total, 6% self)
: | &lt;rustc_borrowck::MirBorrowckCtxt&lt;'cx, 'tcx&gt; as rustc_mir_dataflow::DataflowResultsConsumer&lt;'cx, 'tcx&gt;&gt;::visit_statement_entry (5% total, 0% self)
: | rustc_mir_dataflow::do_dataflow (3% total, 0% self)
</code></pre>
<p>What happens with <code>--tree-callees</code> is that</p>
<ul>
<li>we find each sample matching the regular expression</li>
<li>we look at the code that occurs <em>after</em> the regex match and try
to build up a call tree</li>
</ul>
<p>The <code>--tree-min-percent 3</code> option says "only show me things that take
more than 3% of the time". Without this, the tree often gets really
noisy and includes random stuff like the innards of
malloc. <code>--tree-max-depth</code> can be useful too, it just limits how many
levels we print.</p>
<p>For each line, we display the percent of time in that function
altogether ("total") and the percent of time spent in <strong>just that
function and not some callee of that function</strong> (self). Usually
"total" is the more interesting number, but not always.</p>
<h3 id="relative-percentages"><a class="header" href="#relative-percentages">Relative percentages</a></h3>
<p>By default, all in perf-focus are relative to the <strong>total program
execution</strong>. This is useful to help you keep perspective — often as
we drill down to find hot spots, we can lose sight of the fact that,
in terms of overall program execution, this "hot spot" is actually not
important. It also ensures that percentages between different queries
are easily compared against one another.</p>
<p>That said, sometimes it's useful to get relative percentages, so <code>perf focus</code> offers a <code>--relative</code> option. In this case, the percentages are
listed only for samples that match (vs all samples). So for example we
could get our percentages relative to the borrowck itself
like so:</p>
<pre><code class="language-bash">$ perf focus '{do_mir_borrowck}' --tree-callees --relative --tree-max-depth 1 --tree-min-percent 5
Matcher : {do_mir_borrowck}
Matches : 577
Not Matches: 746
Percentage : 100%
Tree
| matched `{do_mir_borrowck}` (100% total, 0% self)
: | rustc_borrowck::nll::compute_regions (47% total, 0% self) [...]
: | rustc::mir::visit::Visitor::visit_mir (19% total, 15% self) [...]
: | &lt;rustc_borrowck::MirBorrowckCtxt&lt;'cx, 'tcx&gt; as rustc_mir_dataflow::DataflowResultsConsumer&lt;'cx, 'tcx&gt;&gt;::visit_statement_entry (13% total, 0% self) [...]
: | rustc_mir_dataflow::do_dataflow (8% total, 1% self) [...]
</code></pre>
<p>Here you see that <code>compute_regions</code> came up as "47% total" — that
means that 47% of <code>do_mir_borrowck</code> is spent in that function. Before,
we saw 20% — that's because <code>do_mir_borrowck</code> itself is only 43% of
the total time (and <code>.47 * .43 = .20</code>).</p>
</main>
<nav class="nav-wrapper" aria-label="Page navigation">
<!-- Mobile navigation buttons -->
<a rel="prev" href="../profiling.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/wpa_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="../profiling.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/wpa_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>