1
<!DOCTYPE HTML PUBLIC "-//IETF//DTD HTML//EN">
5
<link rel="stylesheet" href="designstyle.css">
6
<title>Google CPU Profiler</title>
13
<script type=text/javascript>
14
var lm = new Date(document.lastModified);
15
document.write(lm.toDateString());
19
<p>This is the CPU profiler we use at Google. There are three parts
20
to using it: linking the library into an application, running the
21
code, and analyzing the output.</p>
23
<p>On the off-chance that you should need to understand it, the CPU
24
profiler data file format is documented separately,
25
<a href="cpuprofile-fileformat.html">here</a>.
28
<H1>Linking in the Library</H1>
30
<p>To install the CPU profiler into your executable, add
31
<code>-lprofiler</code> to the link-time step for your executable.
32
(It's also probably possible to add in the profiler at run-time using
33
<code>LD_PRELOAD</code>, e.g.
34
<code>% env LD_PRELOAD="/usr/lib/libprofiler.so" <binary></code>,
35
but this isn't necessarily recommended.)</p>
37
<p>This does <i>not</i> turn on CPU profiling; it just inserts the
38
code. For that reason, it's practical to just always link
39
<code>-lprofiler</code> into a binary while developing; that's what we
40
do at Google. (However, since any user can turn on the profiler by
41
setting an environment variable, it's not necessarily recommended to
42
install profiler-linked binaries into a production, running
46
<H1>Running the Code</H1>
48
<p>There are several alternatives to actually turn on CPU profiling
49
for a given run of an executable:</p>
52
<li> <p>Define the environment variable CPUPROFILE to the filename
53
to dump the profile to. For instance, to profile
54
<code>/usr/local/bin/my_binary_compiled_with_libprofiler_so</code>:</p>
55
<pre>% env CPUPROFILE=/tmp/mybin.prof /usr/local/bin/my_binary_compiled_with_libprofiler_so</pre>
57
<li> <p>In your code, bracket the code you want profiled in calls to
58
<code>ProfilerStart()</code> and <code>ProfilerStop()</code>.
59
(These functions are declared in <code><google/profiler.h></code>.)
60
<code>ProfilerStart()</code> will take
61
the profile-filename as an argument.</p>
64
<p>In Linux 2.6 and above, profiling works correctly with threads,
65
automatically profiling all threads. In Linux 2.4, profiling only
66
profiles the main thread (due to a kernel bug involving itimers and
67
threads). Profiling works correctly with sub-processes: each child
68
process gets its own profile with its own name (generated by combining
69
CPUPROFILE with the child's process id).</p>
71
<p>For security reasons, CPU profiling will not write to a file -- and
72
is thus not usable -- for setuid programs.</p>
74
<H2>Modifying Runtime Behavior</H2>
76
<p>You can more finely control the behavior of the CPU profiler via
77
environment variables.</p>
79
<table frame=box rules=sides cellpadding=5 width=100%>
82
<td><code>CPUPROFILE_FREQUENCY=<i>x</i></code></td>
85
How many interrupts/second the cpu-profiler samples.
92
<h1><a name="pprof">Analyzing the Output</a></h1>
94
<p><code>pprof</code> is the script used to analyze a profile. It has
95
many output modes, both textual and graphical. Some give just raw
96
numbers, much like the <code>-pg</code> output of <code>gcc</code>,
97
and others show the data in the form of a dependency graph.</p>
99
<p>pprof <b>requires</b> <code>perl5</code> to be installed to run.
100
It also requires <code>dot</code> to be installed for any of the
101
graphical output routines, and <code>gv</code> to be installed for
102
<code>--gv</code> mode (described below).
105
<p>Here are some ways to call pprof. These are described in more
109
% pprof /bin/ls ls.prof
110
Enters "interactive" mode
111
% pprof --text /bin/ls ls.prof
112
Outputs one line per procedure
113
% pprof --gv /bin/ls ls.prof
114
Displays annotated call-graph via 'gv'
115
% pprof --gv --focus=Mutex /bin/ls ls.prof
116
Restricts to code paths including a .*Mutex.* entry
117
% pprof --gv --focus=Mutex --ignore=string /bin/ls ls.prof
118
Code paths including Mutex but not string
119
% pprof --list=getdir /bin/ls ls.prof
120
(Per-line) annotated source listing for getdir()
121
% pprof --disasm=getdir /bin/ls ls.prof
122
(Per-PC) annotated disassembly for getdir()
123
% pprof --text localhost:1234
124
Outputs one line per procedure for localhost:1234
125
% pprof --callgrind /bin/ls ls.prof
126
Outputs the call information in callgrind format
130
<h3>Analyzing Text Output</h3>
132
<p>Text mode has lines of output that look like this:</p>
134
14 2.1% 17.2% 58 8.7% std::_Rb_tree::find
137
<p>Here is how to interpret the columns:</p>
139
<li> Number of profiling samples in this function
140
<li> Percentage of profiling samples in this function
141
<li> Percentage of profiling samples in the functions printed so far
142
<li> Number of profiling samples in this function and its callees
143
<li> Percentage of profiling samples in this function and its callees
147
<h3>Analyzing Callgrind Output</h3>
149
<p>Use <a href="http://kcachegrind.sourceforge.net">kcachegrind</a> to
150
analyze your callgrind output:</p>
152
% pprof --callgrind /bin/ls ls.prof > ls.callgrind
153
% kcachegrind ls.callgrind
156
<p>The cost is specified in 'hits', i.e. how many times a function
157
appears in the recorded call stack information. The 'calls' from
158
function a to b record how many times function b was found in the
159
stack traces directly below function a.</p>
161
<p>Tip: if you use a debug build the output will include file and line
162
number information and kcachegrind will show an annotated source
165
<h3>Node Information</h3>
167
<p>In the various graphical modes of pprof, the output is a call graph
168
annotated with timing information, like so:</p>
170
<A HREF="pprof-test-big.gif">
171
<center><table><tr><td>
172
<img src="pprof-test.gif">
173
</td></tr></table></center>
176
<p>Each node represents a procedure. The directed edges indicate
177
caller to callee relations. Each node is formatted as follows:</p>
183
<b>of</b> cumulative (percentage)
186
<p>The last one or two lines contains the timing information. (The
187
profiling is done via a sampling method, where by default we take 100
188
samples a second. Therefor one unit of time in the output corresponds
189
to about 10 milliseconds of execution time.) The "local" time is the
190
time spent executing the instructions directly contained in the
191
procedure (and in any other procedures that were inlined into the
192
procedure). The "cumulative" time is the sum of the "local" time and
193
the time spent in any callees. If the cumulative time is the same as
194
the local time, it is not printed.</p>
196
<p>For instance, the timing information for test_main_thread()
197
indicates that 155 units (about 1.55 seconds) were spent executing the
198
code in <code>test_main_thread()</code> and 200 units were spent while
199
executing <code>test_main_thread()</code> and its callees such as
200
<code>snprintf()</code>.</p>
202
<p>The size of the node is proportional to the local count. The
203
percentage displayed in the node corresponds to the count divided by
204
the total run time of the program (that is, the cumulative count for
205
<code>main()</code>).</p>
207
<h3>Edge Information</h3>
209
<p>An edge from one node to another indicates a caller to callee
210
relationship. Each edge is labelled with the time spent by the callee
211
on behalf of the caller. E.g, the edge from
212
<code>test_main_thread()</code> to <code>snprintf()</code> indicates
213
that of the 200 samples in <code>test_main_thread()</code>, 37 are
214
because of calls to <code>snprintf()</code>.</p>
216
<p>Note that <code>test_main_thread()</code> has an edge to
217
<code>vsnprintf()</code>, even though <code>test_main_thread()</code>
218
doesn't call that function directly. This is because the code was
219
compiled with <code>-O2</code>; the profile reflects the optimized
222
<h3>Meta Information</h3>
224
<p>The top of the display should contain some meta information
227
/tmp/profiler2_unittest
230
Dropped nodes with <= 1 abs(samples)
231
Dropped edges with <= 0 samples
234
<p>This section contains the name of the program, and the total
235
samples collected during the profiling run. If the
236
<code>--focus</code> option is on (see the <a href="#focus">Focus</a>
237
section below), the legend also contains the number of samples being
238
shown in the focused display. Furthermore, some unimportant nodes and
239
edges are dropped to reduce clutter. The characteristics of the
240
dropped nodes and edges are also displayed in the legend.</p>
242
<h3><a name=focus>Focus and Ignore</a></h3>
244
<p>You can ask pprof to generate a display focused on a particular
245
piece of the program. You specify a regular expression. Any portion
246
of the call-graph that is on a path which contains at least one node
247
matching the regular expression is preserved. The rest of the
248
call-graph is dropped on the floor. For example, you can focus on the
249
<code>vsnprintf()</code> libc call in <code>profiler2_unittest</code>
253
% pprof --gv --focus=vsnprintf /tmp/profiler2_unittest test.prof
255
<A HREF="pprof-vsnprintf-big.gif">
256
<center><table><tr><td>
257
<img src="pprof-vsnprintf.gif">
258
</td></tr></table></center>
261
<p>Similarly, you can supply the <code>--ignore</code> option to
262
ignore samples that match a specified regular expression. E.g., if
263
you are interested in everything except calls to
264
<code>snprintf()</code>, you can say:</p>
266
% pprof --gv --ignore=snprintf /tmp/profiler2_unittest test.prof
270
<h3>Interactive mode</a></h3>
272
<p>By default -- if you don't specify any flags to the contrary --
273
pprof runs in interactive mode. At the <code>(pprof)</code> prompt,
274
you can run many of the commands described above. You can type
275
<code>help</code> for a list of what commands are available in
276
interactive mode.</p>
278
<h3><a name=options>pprof Options</a></h3>
280
For a complete list of pprof options, you can run <code>pprof
287
<table frame=box rules=sides cellpadding=5 width=100%>
289
<td><code>--text</code></td>
291
Produces a textual listing. (Note: If you have an X display, and
292
<code>dot</code> and <code>gv</code> installed, you will probably
293
be happier with the <code>--gv</code> output.)
297
<td><code>--gv</code></td>
299
Generates annotated call-graph, converts to postscript, and
300
displays via gv (requres <code>dot</code> and <code>gv</code> be
305
<td><code>--dot</code></td>
307
Generates the annotated call-graph in dot format and
308
emits to stdout (requres <code>dot</code> be installed).
312
<td><code>--ps</code></td>
314
Generates the annotated call-graph in Postscript format and
315
emits to stdout (requres <code>dot</code> be installed).
319
<td><code>--pdf</code></td>
321
Generates the annotated call-graph in PDF format and emits to
322
stdout (requires <code>dot</code> and <code>ps2pdf</code> be
327
<td><code>--gif</code></td>
329
Generates the annotated call-graph in GIF format and
330
emits to stdout (requres <code>dot</code> be installed).
334
<td><code>--list=<<i>regexp</i>></code></td>
336
<p>Outputs source-code listing of routines whose
337
name matches <regexp>. Each line
338
in the listing is annotated with flat and cumulative
341
<p>In the presence of inlined calls, the samples
342
associated with inlined code tend to get assigned
343
to a line that follows the location of the
344
inlined call. A more precise accounting can be
345
obtained by disassembling the routine using the
350
<td><code>--disasm=<<i>regexp</i>></code></td>
352
Generates disassembly of routines that match
353
<regexp>, annotated with flat and
354
cumulative sample counts and emits to stdout.
360
<h4>Reporting Granularity</h4>
362
<p>By default, pprof produces one entry per procedure. However you can
363
use one of the following options to change the granularity of the
364
output. The <code>--files</code> option seems to be particularly
365
useless, and may be removed eventually.</p>
368
<table frame=box rules=sides cellpadding=5 width=100%>
370
<td><code>--addresses</code></td>
372
Produce one node per program address.
375
<td><code>--lines</code></td>
377
Produce one node per source line.
380
<td><code>--functions</code></td>
382
Produce one node per function (this is the default).
385
<td><code>--files</code></td>
387
Produce one node per source file.
393
<h4>Controlling the Call Graph Display</h4>
395
<p>Some nodes and edges are dropped to reduce clutter in the output
396
display. The following options control this effect:</p>
399
<table frame=box rules=sides cellpadding=5 width=100%>
401
<td><code>--nodecount=<n></code></td>
403
This option controls the number of displayed nodes. The nodes
404
are first sorted by decreasing cumulative count, and then only
405
the top N nodes are kept. The default value is 80.
409
<td><code>--nodefraction=<f></code></td>
411
This option provides another mechanism for discarding nodes
412
from the display. If the cumulative count for a node is
413
less than this option's value multiplied by the total count
414
for the profile, the node is dropped. The default value
415
is 0.005; i.e. nodes that account for less than
416
half a percent of the total time are dropped. A node
417
is dropped if either this condition is satisfied, or the
418
--nodecount condition is satisfied.
422
<td><code>--edgefraction=<f></code></td>
424
This option controls the number of displayed edges. First of all,
425
an edge is dropped if either its source or destination node is
426
dropped. Otherwise, the edge is dropped if the sample
427
count along the edge is less than this option's value multiplied
428
by the total count for the profile. The default value is
429
0.001; i.e., edges that account for less than
430
0.1% of the total time are dropped.
434
<td><code>--focus=<re></code></td>
436
This option controls what region of the graph is displayed
437
based on the regular expression supplied with the option.
438
For any path in the callgraph, we check all nodes in the path
439
against the supplied regular expression. If none of the nodes
440
match, the path is dropped from the output.
444
<td><code>--ignore=<re></code></td>
446
This option controls what region of the graph is displayed
447
based on the regular expression supplied with the option.
448
For any path in the callgraph, we check all nodes in the path
449
against the supplied regular expression. If any of the nodes
450
match, the path is dropped from the output.
456
<p>The dropped edges and nodes account for some count mismatches in
457
the display. For example, the cumulative count for
458
<code>snprintf()</code> in the first diagram above was 41. However
459
the local count (1) and the count along the outgoing edges (12+1+20+6)
460
add up to only 40.</p>
466
<li> If the program exits because of a signal, the generated profile
467
will be <font color=red>incomplete, and may perhaps be
468
completely empty</font>.
469
<li> The displayed graph may have disconnected regions because
470
of the edge-dropping heuristics described above.
471
<li> If the program linked in a library that was not compiled
472
with enough symbolic information, all samples associated
473
with the library may be charged to the last symbol found
474
in the program before the library. This will artificially
475
inflate the count for that symbol.
476
<li> If you run the program on one machine, and profile it on
477
another, and the shared libraries are different on the two
478
machines, the profiling output may be confusing: samples that
479
fall within shared libaries may be assigned to arbitrary
481
<li> If your program forks, the children will also be profiled
482
(since they inherit the same CPUPROFILE setting). Each process
483
is profiled separately; to distinguish the child profiles from
484
the parent profile and from each other, all children will have
485
their process-id appended to the CPUPROFILE name.
486
<li> Due to a hack we make to work around a possible gcc bug, your
487
profiles may end up named strangely if the first character of
488
your CPUPROFILE variable has ascii value greater than 127.
489
This should be exceedingly rare, but if you need to use such a
490
name, just set prepend <code>./</code> to your filename:
491
<code>CPUPROFILE=./Ägypten</code>.
496
<address>Sanjay Ghemawat<br>
497
<!-- Created: Tue Dec 19 10:43:14 PST 2000 -->
499
Last modified: Fri May 9 14:41:29 PDT 2008
added
removed
doc/cpuprofile.html
