1 |
205 |
julius |
\input texinfo @c -*-texinfo-*-
|
2 |
|
|
@setfilename gprof.info
|
3 |
|
|
@c Copyright 1988, 1992, 1993, 1998, 1999, 2000, 2001, 2002, 2003,
|
4 |
|
|
@c 2004, 2007, 2008, 2009
|
5 |
|
|
@c Free Software Foundation, Inc.
|
6 |
|
|
@settitle GNU gprof
|
7 |
|
|
@setchapternewpage odd
|
8 |
|
|
|
9 |
|
|
@c man begin INCLUDE
|
10 |
|
|
@include bfdver.texi
|
11 |
|
|
@c man end
|
12 |
|
|
|
13 |
|
|
@ifinfo
|
14 |
|
|
@c This is a dir.info fragment to support semi-automated addition of
|
15 |
|
|
@c manuals to an info tree. zoo@cygnus.com is developing this facility.
|
16 |
|
|
@format
|
17 |
|
|
START-INFO-DIR-ENTRY
|
18 |
|
|
* gprof: (gprof). Profiling your program's execution
|
19 |
|
|
END-INFO-DIR-ENTRY
|
20 |
|
|
@end format
|
21 |
|
|
@end ifinfo
|
22 |
|
|
|
23 |
|
|
@copying
|
24 |
|
|
This file documents the gprof profiler of the GNU system.
|
25 |
|
|
|
26 |
|
|
@c man begin COPYRIGHT
|
27 |
|
|
Copyright @copyright{} 1988, 92, 97, 98, 99, 2000, 2001, 2003, 2007, 2008, 2009 Free Software Foundation, Inc.
|
28 |
|
|
|
29 |
|
|
Permission is granted to copy, distribute and/or modify this document
|
30 |
|
|
under the terms of the GNU Free Documentation License, Version 1.3
|
31 |
|
|
or any later version published by the Free Software Foundation;
|
32 |
|
|
with no Invariant Sections, with no Front-Cover Texts, and with no
|
33 |
|
|
Back-Cover Texts. A copy of the license is included in the
|
34 |
|
|
section entitled ``GNU Free Documentation License''.
|
35 |
|
|
|
36 |
|
|
@c man end
|
37 |
|
|
@end copying
|
38 |
|
|
|
39 |
|
|
@finalout
|
40 |
|
|
@smallbook
|
41 |
|
|
|
42 |
|
|
@titlepage
|
43 |
|
|
@title GNU gprof
|
44 |
|
|
@subtitle The @sc{gnu} Profiler
|
45 |
|
|
@ifset VERSION_PACKAGE
|
46 |
|
|
@subtitle @value{VERSION_PACKAGE}
|
47 |
|
|
@end ifset
|
48 |
|
|
@subtitle Version @value{VERSION}
|
49 |
|
|
@author Jay Fenlason and Richard Stallman
|
50 |
|
|
|
51 |
|
|
@page
|
52 |
|
|
|
53 |
|
|
This manual describes the @sc{gnu} profiler, @code{gprof}, and how you
|
54 |
|
|
can use it to determine which parts of a program are taking most of the
|
55 |
|
|
execution time. We assume that you know how to write, compile, and
|
56 |
|
|
execute programs. @sc{gnu} @code{gprof} was written by Jay Fenlason.
|
57 |
|
|
Eric S. Raymond made some minor corrections and additions in 2003.
|
58 |
|
|
|
59 |
|
|
@vskip 0pt plus 1filll
|
60 |
|
|
Copyright @copyright{} 1988, 92, 97, 98, 99, 2000, 2003, 2008, 2009 Free Software Foundation, Inc.
|
61 |
|
|
|
62 |
|
|
Permission is granted to copy, distribute and/or modify this document
|
63 |
|
|
under the terms of the GNU Free Documentation License, Version 1.3
|
64 |
|
|
or any later version published by the Free Software Foundation;
|
65 |
|
|
with no Invariant Sections, with no Front-Cover Texts, and with no
|
66 |
|
|
Back-Cover Texts. A copy of the license is included in the
|
67 |
|
|
section entitled ``GNU Free Documentation License''.
|
68 |
|
|
|
69 |
|
|
@end titlepage
|
70 |
|
|
@contents
|
71 |
|
|
|
72 |
|
|
@ifnottex
|
73 |
|
|
@node Top
|
74 |
|
|
@top Profiling a Program: Where Does It Spend Its Time?
|
75 |
|
|
|
76 |
|
|
This manual describes the @sc{gnu} profiler, @code{gprof}, and how you
|
77 |
|
|
can use it to determine which parts of a program are taking most of the
|
78 |
|
|
execution time. We assume that you know how to write, compile, and
|
79 |
|
|
execute programs. @sc{gnu} @code{gprof} was written by Jay Fenlason.
|
80 |
|
|
|
81 |
|
|
This manual is for @code{gprof}
|
82 |
|
|
@ifset VERSION_PACKAGE
|
83 |
|
|
@value{VERSION_PACKAGE}
|
84 |
|
|
@end ifset
|
85 |
|
|
version @value{VERSION}.
|
86 |
|
|
|
87 |
|
|
This document is distributed under the terms of the GNU Free
|
88 |
|
|
Documentation License version 1.3. A copy of the license is included
|
89 |
|
|
in the section entitled ``GNU Free Documentation License''.
|
90 |
|
|
|
91 |
|
|
@menu
|
92 |
|
|
* Introduction:: What profiling means, and why it is useful.
|
93 |
|
|
|
94 |
|
|
* Compiling:: How to compile your program for profiling.
|
95 |
|
|
* Executing:: Executing your program to generate profile data
|
96 |
|
|
* Invoking:: How to run @code{gprof}, and its options
|
97 |
|
|
|
98 |
|
|
* Output:: Interpreting @code{gprof}'s output
|
99 |
|
|
|
100 |
|
|
* Inaccuracy:: Potential problems you should be aware of
|
101 |
|
|
* How do I?:: Answers to common questions
|
102 |
|
|
* Incompatibilities:: (between @sc{gnu} @code{gprof} and Unix @code{gprof}.)
|
103 |
|
|
* Details:: Details of how profiling is done
|
104 |
|
|
* GNU Free Documentation License:: GNU Free Documentation License
|
105 |
|
|
@end menu
|
106 |
|
|
@end ifnottex
|
107 |
|
|
|
108 |
|
|
@node Introduction
|
109 |
|
|
@chapter Introduction to Profiling
|
110 |
|
|
|
111 |
|
|
@ifset man
|
112 |
|
|
@c man title gprof display call graph profile data
|
113 |
|
|
|
114 |
|
|
@smallexample
|
115 |
|
|
@c man begin SYNOPSIS
|
116 |
|
|
gprof [ -[abcDhilLrsTvwxyz] ] [ -[ACeEfFJnNOpPqQZ][@var{name}] ]
|
117 |
|
|
[ -I @var{dirs} ] [ -d[@var{num}] ] [ -k @var{from/to} ]
|
118 |
|
|
[ -m @var{min-count} ] [ -R @var{map_file} ] [ -t @var{table-length} ]
|
119 |
|
|
[ --[no-]annotated-source[=@var{name}] ]
|
120 |
|
|
[ --[no-]exec-counts[=@var{name}] ]
|
121 |
|
|
[ --[no-]flat-profile[=@var{name}] ] [ --[no-]graph[=@var{name}] ]
|
122 |
|
|
[ --[no-]time=@var{name}] [ --all-lines ] [ --brief ]
|
123 |
|
|
[ --debug[=@var{level}] ] [ --function-ordering ]
|
124 |
|
|
[ --file-ordering @var{map_file} ] [ --directory-path=@var{dirs} ]
|
125 |
|
|
[ --display-unused-functions ] [ --file-format=@var{name} ]
|
126 |
|
|
[ --file-info ] [ --help ] [ --line ] [ --min-count=@var{n} ]
|
127 |
|
|
[ --no-static ] [ --print-path ] [ --separate-files ]
|
128 |
|
|
[ --static-call-graph ] [ --sum ] [ --table-length=@var{len} ]
|
129 |
|
|
[ --traditional ] [ --version ] [ --width=@var{n} ]
|
130 |
|
|
[ --ignore-non-functions ] [ --demangle[=@var{STYLE}] ]
|
131 |
|
|
[ --no-demangle ] [--external-symbol-table=name]
|
132 |
|
|
[ @var{image-file} ] [ @var{profile-file} @dots{} ]
|
133 |
|
|
@c man end
|
134 |
|
|
@end smallexample
|
135 |
|
|
|
136 |
|
|
@c man begin DESCRIPTION
|
137 |
|
|
@code{gprof} produces an execution profile of C, Pascal, or Fortran77
|
138 |
|
|
programs. The effect of called routines is incorporated in the profile
|
139 |
|
|
of each caller. The profile data is taken from the call graph profile file
|
140 |
|
|
(@file{gmon.out} default) which is created by programs
|
141 |
|
|
that are compiled with the @samp{-pg} option of
|
142 |
|
|
@code{cc}, @code{pc}, and @code{f77}.
|
143 |
|
|
The @samp{-pg} option also links in versions of the library routines
|
144 |
|
|
that are compiled for profiling. @code{Gprof} reads the given object
|
145 |
|
|
file (the default is @code{a.out}) and establishes the relation between
|
146 |
|
|
its symbol table and the call graph profile from @file{gmon.out}.
|
147 |
|
|
If more than one profile file is specified, the @code{gprof}
|
148 |
|
|
output shows the sum of the profile information in the given profile files.
|
149 |
|
|
|
150 |
|
|
@code{Gprof} calculates the amount of time spent in each routine.
|
151 |
|
|
Next, these times are propagated along the edges of the call graph.
|
152 |
|
|
Cycles are discovered, and calls into a cycle are made to share the time
|
153 |
|
|
of the cycle.
|
154 |
|
|
|
155 |
|
|
@c man end
|
156 |
|
|
|
157 |
|
|
@c man begin BUGS
|
158 |
|
|
The granularity of the sampling is shown, but remains
|
159 |
|
|
statistical at best.
|
160 |
|
|
We assume that the time for each execution of a function
|
161 |
|
|
can be expressed by the total time for the function divided
|
162 |
|
|
by the number of times the function is called.
|
163 |
|
|
Thus the time propagated along the call graph arcs to the function's
|
164 |
|
|
parents is directly proportional to the number of times that
|
165 |
|
|
arc is traversed.
|
166 |
|
|
|
167 |
|
|
Parents that are not themselves profiled will have the time of
|
168 |
|
|
their profiled children propagated to them, but they will appear
|
169 |
|
|
to be spontaneously invoked in the call graph listing, and will
|
170 |
|
|
not have their time propagated further.
|
171 |
|
|
Similarly, signal catchers, even though profiled, will appear
|
172 |
|
|
to be spontaneous (although for more obscure reasons).
|
173 |
|
|
Any profiled children of signal catchers should have their times
|
174 |
|
|
propagated properly, unless the signal catcher was invoked during
|
175 |
|
|
the execution of the profiling routine, in which case all is lost.
|
176 |
|
|
|
177 |
|
|
The profiled program must call @code{exit}(2)
|
178 |
|
|
or return normally for the profiling information to be saved
|
179 |
|
|
in the @file{gmon.out} file.
|
180 |
|
|
@c man end
|
181 |
|
|
|
182 |
|
|
@c man begin FILES
|
183 |
|
|
@table @code
|
184 |
|
|
@item @file{a.out}
|
185 |
|
|
the namelist and text space.
|
186 |
|
|
@item @file{gmon.out}
|
187 |
|
|
dynamic call graph and profile.
|
188 |
|
|
@item @file{gmon.sum}
|
189 |
|
|
summarized dynamic call graph and profile.
|
190 |
|
|
@end table
|
191 |
|
|
@c man end
|
192 |
|
|
|
193 |
|
|
@c man begin SEEALSO
|
194 |
|
|
monitor(3), profil(2), cc(1), prof(1), and the Info entry for @file{gprof}.
|
195 |
|
|
|
196 |
|
|
``An Execution Profiler for Modular Programs'',
|
197 |
|
|
by S. Graham, P. Kessler, M. McKusick;
|
198 |
|
|
Software - Practice and Experience,
|
199 |
|
|
Vol. 13, pp. 671-685, 1983.
|
200 |
|
|
|
201 |
|
|
``gprof: A Call Graph Execution Profiler'',
|
202 |
|
|
by S. Graham, P. Kessler, M. McKusick;
|
203 |
|
|
Proceedings of the SIGPLAN '82 Symposium on Compiler Construction,
|
204 |
|
|
SIGPLAN Notices, Vol. 17, No 6, pp. 120-126, June 1982.
|
205 |
|
|
@c man end
|
206 |
|
|
@end ifset
|
207 |
|
|
|
208 |
|
|
Profiling allows you to learn where your program spent its time and which
|
209 |
|
|
functions called which other functions while it was executing. This
|
210 |
|
|
information can show you which pieces of your program are slower than you
|
211 |
|
|
expected, and might be candidates for rewriting to make your program
|
212 |
|
|
execute faster. It can also tell you which functions are being called more
|
213 |
|
|
or less often than you expected. This may help you spot bugs that had
|
214 |
|
|
otherwise been unnoticed.
|
215 |
|
|
|
216 |
|
|
Since the profiler uses information collected during the actual execution
|
217 |
|
|
of your program, it can be used on programs that are too large or too
|
218 |
|
|
complex to analyze by reading the source. However, how your program is run
|
219 |
|
|
will affect the information that shows up in the profile data. If you
|
220 |
|
|
don't use some feature of your program while it is being profiled, no
|
221 |
|
|
profile information will be generated for that feature.
|
222 |
|
|
|
223 |
|
|
Profiling has several steps:
|
224 |
|
|
|
225 |
|
|
@itemize @bullet
|
226 |
|
|
@item
|
227 |
|
|
You must compile and link your program with profiling enabled.
|
228 |
|
|
@xref{Compiling, ,Compiling a Program for Profiling}.
|
229 |
|
|
|
230 |
|
|
@item
|
231 |
|
|
You must execute your program to generate a profile data file.
|
232 |
|
|
@xref{Executing, ,Executing the Program}.
|
233 |
|
|
|
234 |
|
|
@item
|
235 |
|
|
You must run @code{gprof} to analyze the profile data.
|
236 |
|
|
@xref{Invoking, ,@code{gprof} Command Summary}.
|
237 |
|
|
@end itemize
|
238 |
|
|
|
239 |
|
|
The next three chapters explain these steps in greater detail.
|
240 |
|
|
|
241 |
|
|
@c man begin DESCRIPTION
|
242 |
|
|
|
243 |
|
|
Several forms of output are available from the analysis.
|
244 |
|
|
|
245 |
|
|
The @dfn{flat profile} shows how much time your program spent in each function,
|
246 |
|
|
and how many times that function was called. If you simply want to know
|
247 |
|
|
which functions burn most of the cycles, it is stated concisely here.
|
248 |
|
|
@xref{Flat Profile, ,The Flat Profile}.
|
249 |
|
|
|
250 |
|
|
The @dfn{call graph} shows, for each function, which functions called it, which
|
251 |
|
|
other functions it called, and how many times. There is also an estimate
|
252 |
|
|
of how much time was spent in the subroutines of each function. This can
|
253 |
|
|
suggest places where you might try to eliminate function calls that use a
|
254 |
|
|
lot of time. @xref{Call Graph, ,The Call Graph}.
|
255 |
|
|
|
256 |
|
|
The @dfn{annotated source} listing is a copy of the program's
|
257 |
|
|
source code, labeled with the number of times each line of the
|
258 |
|
|
program was executed. @xref{Annotated Source, ,The Annotated Source
|
259 |
|
|
Listing}.
|
260 |
|
|
@c man end
|
261 |
|
|
|
262 |
|
|
To better understand how profiling works, you may wish to read
|
263 |
|
|
a description of its implementation.
|
264 |
|
|
@xref{Implementation, ,Implementation of Profiling}.
|
265 |
|
|
|
266 |
|
|
@node Compiling
|
267 |
|
|
@chapter Compiling a Program for Profiling
|
268 |
|
|
|
269 |
|
|
The first step in generating profile information for your program is
|
270 |
|
|
to compile and link it with profiling enabled.
|
271 |
|
|
|
272 |
|
|
To compile a source file for profiling, specify the @samp{-pg} option when
|
273 |
|
|
you run the compiler. (This is in addition to the options you normally
|
274 |
|
|
use.)
|
275 |
|
|
|
276 |
|
|
To link the program for profiling, if you use a compiler such as @code{cc}
|
277 |
|
|
to do the linking, simply specify @samp{-pg} in addition to your usual
|
278 |
|
|
options. The same option, @samp{-pg}, alters either compilation or linking
|
279 |
|
|
to do what is necessary for profiling. Here are examples:
|
280 |
|
|
|
281 |
|
|
@example
|
282 |
|
|
cc -g -c myprog.c utils.c -pg
|
283 |
|
|
cc -o myprog myprog.o utils.o -pg
|
284 |
|
|
@end example
|
285 |
|
|
|
286 |
|
|
The @samp{-pg} option also works with a command that both compiles and links:
|
287 |
|
|
|
288 |
|
|
@example
|
289 |
|
|
cc -o myprog myprog.c utils.c -g -pg
|
290 |
|
|
@end example
|
291 |
|
|
|
292 |
|
|
Note: The @samp{-pg} option must be part of your compilation options
|
293 |
|
|
as well as your link options. If it is not then no call-graph data
|
294 |
|
|
will be gathered and when you run @code{gprof} you will get an error
|
295 |
|
|
message like this:
|
296 |
|
|
|
297 |
|
|
@example
|
298 |
|
|
gprof: gmon.out file is missing call-graph data
|
299 |
|
|
@end example
|
300 |
|
|
|
301 |
|
|
If you add the @samp{-Q} switch to suppress the printing of the call
|
302 |
|
|
graph data you will still be able to see the time samples:
|
303 |
|
|
|
304 |
|
|
@example
|
305 |
|
|
Flat profile:
|
306 |
|
|
|
307 |
|
|
Each sample counts as 0.01 seconds.
|
308 |
|
|
% cumulative self self total
|
309 |
|
|
time seconds seconds calls Ts/call Ts/call name
|
310 |
|
|
44.12 0.07 0.07 zazLoop
|
311 |
|
|
35.29 0.14 0.06 main
|
312 |
|
|
20.59 0.17 0.04 bazMillion
|
313 |
|
|
@end example
|
314 |
|
|
|
315 |
|
|
If you run the linker @code{ld} directly instead of through a compiler
|
316 |
|
|
such as @code{cc}, you may have to specify a profiling startup file
|
317 |
|
|
@file{gcrt0.o} as the first input file instead of the usual startup
|
318 |
|
|
file @file{crt0.o}. In addition, you would probably want to
|
319 |
|
|
specify the profiling C library, @file{libc_p.a}, by writing
|
320 |
|
|
@samp{-lc_p} instead of the usual @samp{-lc}. This is not absolutely
|
321 |
|
|
necessary, but doing this gives you number-of-calls information for
|
322 |
|
|
standard library functions such as @code{read} and @code{open}. For
|
323 |
|
|
example:
|
324 |
|
|
|
325 |
|
|
@example
|
326 |
|
|
ld -o myprog /lib/gcrt0.o myprog.o utils.o -lc_p
|
327 |
|
|
@end example
|
328 |
|
|
|
329 |
|
|
If you are running the program on a system which supports shared
|
330 |
|
|
libraries you may run into problems with the profiling support code in
|
331 |
|
|
a shared library being called before that library has been fully
|
332 |
|
|
initialised. This is usually detected by the program encountering a
|
333 |
|
|
segmentation fault as soon as it is run. The solution is to link
|
334 |
|
|
against a static version of the library containing the profiling
|
335 |
|
|
support code, which for @code{gcc} users can be done via the
|
336 |
|
|
@samp{-static} or @samp{-static-libgcc} command line option. For
|
337 |
|
|
example:
|
338 |
|
|
|
339 |
|
|
@example
|
340 |
|
|
gcc -g -pg -static-libgcc myprog.c utils.c -o myprog
|
341 |
|
|
@end example
|
342 |
|
|
|
343 |
|
|
If you compile only some of the modules of the program with @samp{-pg}, you
|
344 |
|
|
can still profile the program, but you won't get complete information about
|
345 |
|
|
the modules that were compiled without @samp{-pg}. The only information
|
346 |
|
|
you get for the functions in those modules is the total time spent in them;
|
347 |
|
|
there is no record of how many times they were called, or from where. This
|
348 |
|
|
will not affect the flat profile (except that the @code{calls} field for
|
349 |
|
|
the functions will be blank), but will greatly reduce the usefulness of the
|
350 |
|
|
call graph.
|
351 |
|
|
|
352 |
|
|
If you wish to perform line-by-line profiling you should use the
|
353 |
|
|
@code{gcov} tool instead of @code{gprof}. See that tool's manual or
|
354 |
|
|
info pages for more details of how to do this.
|
355 |
|
|
|
356 |
|
|
Note, older versions of @code{gcc} produce line-by-line profiling
|
357 |
|
|
information that works with @code{gprof} rather than @code{gcov} so
|
358 |
|
|
there is still support for displaying this kind of information in
|
359 |
|
|
@code{gprof}. @xref{Line-by-line, ,Line-by-line Profiling}.
|
360 |
|
|
|
361 |
|
|
It also worth noting that @code{gcc} implements a
|
362 |
|
|
@samp{-finstrument-functions} command line option which will insert
|
363 |
|
|
calls to special user supplied instrumentation routines at the entry
|
364 |
|
|
and exit of every function in their program. This can be used to
|
365 |
|
|
implement an alternative profiling scheme.
|
366 |
|
|
|
367 |
|
|
@node Executing
|
368 |
|
|
@chapter Executing the Program
|
369 |
|
|
|
370 |
|
|
Once the program is compiled for profiling, you must run it in order to
|
371 |
|
|
generate the information that @code{gprof} needs. Simply run the program
|
372 |
|
|
as usual, using the normal arguments, file names, etc. The program should
|
373 |
|
|
run normally, producing the same output as usual. It will, however, run
|
374 |
|
|
somewhat slower than normal because of the time spent collecting and
|
375 |
|
|
writing the profile data.
|
376 |
|
|
|
377 |
|
|
The way you run the program---the arguments and input that you give
|
378 |
|
|
it---may have a dramatic effect on what the profile information shows. The
|
379 |
|
|
profile data will describe the parts of the program that were activated for
|
380 |
|
|
the particular input you use. For example, if the first command you give
|
381 |
|
|
to your program is to quit, the profile data will show the time used in
|
382 |
|
|
initialization and in cleanup, but not much else.
|
383 |
|
|
|
384 |
|
|
Your program will write the profile data into a file called @file{gmon.out}
|
385 |
|
|
just before exiting. If there is already a file called @file{gmon.out},
|
386 |
|
|
its contents are overwritten. There is currently no way to tell the
|
387 |
|
|
program to write the profile data under a different name, but you can rename
|
388 |
|
|
the file afterwards if you are concerned that it may be overwritten.
|
389 |
|
|
|
390 |
|
|
In order to write the @file{gmon.out} file properly, your program must exit
|
391 |
|
|
normally: by returning from @code{main} or by calling @code{exit}. Calling
|
392 |
|
|
the low-level function @code{_exit} does not write the profile data, and
|
393 |
|
|
neither does abnormal termination due to an unhandled signal.
|
394 |
|
|
|
395 |
|
|
The @file{gmon.out} file is written in the program's @emph{current working
|
396 |
|
|
directory} at the time it exits. This means that if your program calls
|
397 |
|
|
@code{chdir}, the @file{gmon.out} file will be left in the last directory
|
398 |
|
|
your program @code{chdir}'d to. If you don't have permission to write in
|
399 |
|
|
this directory, the file is not written, and you will get an error message.
|
400 |
|
|
|
401 |
|
|
Older versions of the @sc{gnu} profiling library may also write a file
|
402 |
|
|
called @file{bb.out}. This file, if present, contains an human-readable
|
403 |
|
|
listing of the basic-block execution counts. Unfortunately, the
|
404 |
|
|
appearance of a human-readable @file{bb.out} means the basic-block
|
405 |
|
|
counts didn't get written into @file{gmon.out}.
|
406 |
|
|
The Perl script @code{bbconv.pl}, included with the @code{gprof}
|
407 |
|
|
source distribution, will convert a @file{bb.out} file into
|
408 |
|
|
a format readable by @code{gprof}. Invoke it like this:
|
409 |
|
|
|
410 |
|
|
@smallexample
|
411 |
|
|
bbconv.pl < bb.out > @var{bh-data}
|
412 |
|
|
@end smallexample
|
413 |
|
|
|
414 |
|
|
This translates the information in @file{bb.out} into a form that
|
415 |
|
|
@code{gprof} can understand. But you still need to tell @code{gprof}
|
416 |
|
|
about the existence of this translated information. To do that, include
|
417 |
|
|
@var{bb-data} on the @code{gprof} command line, @emph{along with
|
418 |
|
|
@file{gmon.out}}, like this:
|
419 |
|
|
|
420 |
|
|
@smallexample
|
421 |
|
|
gprof @var{options} @var{executable-file} gmon.out @var{bb-data} [@var{yet-more-profile-data-files}@dots{}] [> @var{outfile}]
|
422 |
|
|
@end smallexample
|
423 |
|
|
|
424 |
|
|
@node Invoking
|
425 |
|
|
@chapter @code{gprof} Command Summary
|
426 |
|
|
|
427 |
|
|
After you have a profile data file @file{gmon.out}, you can run @code{gprof}
|
428 |
|
|
to interpret the information in it. The @code{gprof} program prints a
|
429 |
|
|
flat profile and a call graph on standard output. Typically you would
|
430 |
|
|
redirect the output of @code{gprof} into a file with @samp{>}.
|
431 |
|
|
|
432 |
|
|
You run @code{gprof} like this:
|
433 |
|
|
|
434 |
|
|
@smallexample
|
435 |
|
|
gprof @var{options} [@var{executable-file} [@var{profile-data-files}@dots{}]] [> @var{outfile}]
|
436 |
|
|
@end smallexample
|
437 |
|
|
|
438 |
|
|
@noindent
|
439 |
|
|
Here square-brackets indicate optional arguments.
|
440 |
|
|
|
441 |
|
|
If you omit the executable file name, the file @file{a.out} is used. If
|
442 |
|
|
you give no profile data file name, the file @file{gmon.out} is used. If
|
443 |
|
|
any file is not in the proper format, or if the profile data file does not
|
444 |
|
|
appear to belong to the executable file, an error message is printed.
|
445 |
|
|
|
446 |
|
|
You can give more than one profile data file by entering all their names
|
447 |
|
|
after the executable file name; then the statistics in all the data files
|
448 |
|
|
are summed together.
|
449 |
|
|
|
450 |
|
|
The order of these options does not matter.
|
451 |
|
|
|
452 |
|
|
@menu
|
453 |
|
|
* Output Options:: Controlling @code{gprof}'s output style
|
454 |
|
|
* Analysis Options:: Controlling how @code{gprof} analyzes its data
|
455 |
|
|
* Miscellaneous Options::
|
456 |
|
|
* Deprecated Options:: Options you no longer need to use, but which
|
457 |
|
|
have been retained for compatibility
|
458 |
|
|
* Symspecs:: Specifying functions to include or exclude
|
459 |
|
|
@end menu
|
460 |
|
|
|
461 |
|
|
@node Output Options
|
462 |
|
|
@section Output Options
|
463 |
|
|
|
464 |
|
|
@c man begin OPTIONS
|
465 |
|
|
These options specify which of several output formats
|
466 |
|
|
@code{gprof} should produce.
|
467 |
|
|
|
468 |
|
|
Many of these options take an optional @dfn{symspec} to specify
|
469 |
|
|
functions to be included or excluded. These options can be
|
470 |
|
|
specified multiple times, with different symspecs, to include
|
471 |
|
|
or exclude sets of symbols. @xref{Symspecs, ,Symspecs}.
|
472 |
|
|
|
473 |
|
|
Specifying any of these options overrides the default (@samp{-p -q}),
|
474 |
|
|
which prints a flat profile and call graph analysis
|
475 |
|
|
for all functions.
|
476 |
|
|
|
477 |
|
|
@table @code
|
478 |
|
|
|
479 |
|
|
@item -A[@var{symspec}]
|
480 |
|
|
@itemx --annotated-source[=@var{symspec}]
|
481 |
|
|
The @samp{-A} option causes @code{gprof} to print annotated source code.
|
482 |
|
|
If @var{symspec} is specified, print output only for matching symbols.
|
483 |
|
|
@xref{Annotated Source, ,The Annotated Source Listing}.
|
484 |
|
|
|
485 |
|
|
@item -b
|
486 |
|
|
@itemx --brief
|
487 |
|
|
If the @samp{-b} option is given, @code{gprof} doesn't print the
|
488 |
|
|
verbose blurbs that try to explain the meaning of all of the fields in
|
489 |
|
|
the tables. This is useful if you intend to print out the output, or
|
490 |
|
|
are tired of seeing the blurbs.
|
491 |
|
|
|
492 |
|
|
@item -C[@var{symspec}]
|
493 |
|
|
@itemx --exec-counts[=@var{symspec}]
|
494 |
|
|
The @samp{-C} option causes @code{gprof} to
|
495 |
|
|
print a tally of functions and the number of times each was called.
|
496 |
|
|
If @var{symspec} is specified, print tally only for matching symbols.
|
497 |
|
|
|
498 |
|
|
If the profile data file contains basic-block count records, specifying
|
499 |
|
|
the @samp{-l} option, along with @samp{-C}, will cause basic-block
|
500 |
|
|
execution counts to be tallied and displayed.
|
501 |
|
|
|
502 |
|
|
@item -i
|
503 |
|
|
@itemx --file-info
|
504 |
|
|
The @samp{-i} option causes @code{gprof} to display summary information
|
505 |
|
|
about the profile data file(s) and then exit. The number of histogram,
|
506 |
|
|
call graph, and basic-block count records is displayed.
|
507 |
|
|
|
508 |
|
|
@item -I @var{dirs}
|
509 |
|
|
@itemx --directory-path=@var{dirs}
|
510 |
|
|
The @samp{-I} option specifies a list of search directories in
|
511 |
|
|
which to find source files. Environment variable @var{GPROF_PATH}
|
512 |
|
|
can also be used to convey this information.
|
513 |
|
|
Used mostly for annotated source output.
|
514 |
|
|
|
515 |
|
|
@item -J[@var{symspec}]
|
516 |
|
|
@itemx --no-annotated-source[=@var{symspec}]
|
517 |
|
|
The @samp{-J} option causes @code{gprof} not to
|
518 |
|
|
print annotated source code.
|
519 |
|
|
If @var{symspec} is specified, @code{gprof} prints annotated source,
|
520 |
|
|
but excludes matching symbols.
|
521 |
|
|
|
522 |
|
|
@item -L
|
523 |
|
|
@itemx --print-path
|
524 |
|
|
Normally, source filenames are printed with the path
|
525 |
|
|
component suppressed. The @samp{-L} option causes @code{gprof}
|
526 |
|
|
to print the full pathname of
|
527 |
|
|
source filenames, which is determined
|
528 |
|
|
from symbolic debugging information in the image file
|
529 |
|
|
and is relative to the directory in which the compiler
|
530 |
|
|
was invoked.
|
531 |
|
|
|
532 |
|
|
@item -p[@var{symspec}]
|
533 |
|
|
@itemx --flat-profile[=@var{symspec}]
|
534 |
|
|
The @samp{-p} option causes @code{gprof} to print a flat profile.
|
535 |
|
|
If @var{symspec} is specified, print flat profile only for matching symbols.
|
536 |
|
|
@xref{Flat Profile, ,The Flat Profile}.
|
537 |
|
|
|
538 |
|
|
@item -P[@var{symspec}]
|
539 |
|
|
@itemx --no-flat-profile[=@var{symspec}]
|
540 |
|
|
The @samp{-P} option causes @code{gprof} to suppress printing a flat profile.
|
541 |
|
|
If @var{symspec} is specified, @code{gprof} prints a flat profile,
|
542 |
|
|
but excludes matching symbols.
|
543 |
|
|
|
544 |
|
|
@item -q[@var{symspec}]
|
545 |
|
|
@itemx --graph[=@var{symspec}]
|
546 |
|
|
The @samp{-q} option causes @code{gprof} to print the call graph analysis.
|
547 |
|
|
If @var{symspec} is specified, print call graph only for matching symbols
|
548 |
|
|
and their children.
|
549 |
|
|
@xref{Call Graph, ,The Call Graph}.
|
550 |
|
|
|
551 |
|
|
@item -Q[@var{symspec}]
|
552 |
|
|
@itemx --no-graph[=@var{symspec}]
|
553 |
|
|
The @samp{-Q} option causes @code{gprof} to suppress printing the
|
554 |
|
|
call graph.
|
555 |
|
|
If @var{symspec} is specified, @code{gprof} prints a call graph,
|
556 |
|
|
but excludes matching symbols.
|
557 |
|
|
|
558 |
|
|
@item -t
|
559 |
|
|
@itemx --table-length=@var{num}
|
560 |
|
|
The @samp{-t} option causes the @var{num} most active source lines in
|
561 |
|
|
each source file to be listed when source annotation is enabled. The
|
562 |
|
|
default is 10.
|
563 |
|
|
|
564 |
|
|
@item -y
|
565 |
|
|
@itemx --separate-files
|
566 |
|
|
This option affects annotated source output only.
|
567 |
|
|
Normally, @code{gprof} prints annotated source files
|
568 |
|
|
to standard-output. If this option is specified,
|
569 |
|
|
annotated source for a file named @file{path/@var{filename}}
|
570 |
|
|
is generated in the file @file{@var{filename}-ann}. If the underlying
|
571 |
|
|
file system would truncate @file{@var{filename}-ann} so that it
|
572 |
|
|
overwrites the original @file{@var{filename}}, @code{gprof} generates
|
573 |
|
|
annotated source in the file @file{@var{filename}.ann} instead (if the
|
574 |
|
|
original file name has an extension, that extension is @emph{replaced}
|
575 |
|
|
with @file{.ann}).
|
576 |
|
|
|
577 |
|
|
@item -Z[@var{symspec}]
|
578 |
|
|
@itemx --no-exec-counts[=@var{symspec}]
|
579 |
|
|
The @samp{-Z} option causes @code{gprof} not to
|
580 |
|
|
print a tally of functions and the number of times each was called.
|
581 |
|
|
If @var{symspec} is specified, print tally, but exclude matching symbols.
|
582 |
|
|
|
583 |
|
|
@item -r
|
584 |
|
|
@itemx --function-ordering
|
585 |
|
|
The @samp{--function-ordering} option causes @code{gprof} to print a
|
586 |
|
|
suggested function ordering for the program based on profiling data.
|
587 |
|
|
This option suggests an ordering which may improve paging, tlb and
|
588 |
|
|
cache behavior for the program on systems which support arbitrary
|
589 |
|
|
ordering of functions in an executable.
|
590 |
|
|
|
591 |
|
|
The exact details of how to force the linker to place functions
|
592 |
|
|
in a particular order is system dependent and out of the scope of this
|
593 |
|
|
manual.
|
594 |
|
|
|
595 |
|
|
@item -R @var{map_file}
|
596 |
|
|
@itemx --file-ordering @var{map_file}
|
597 |
|
|
The @samp{--file-ordering} option causes @code{gprof} to print a
|
598 |
|
|
suggested .o link line ordering for the program based on profiling data.
|
599 |
|
|
This option suggests an ordering which may improve paging, tlb and
|
600 |
|
|
cache behavior for the program on systems which do not support arbitrary
|
601 |
|
|
ordering of functions in an executable.
|
602 |
|
|
|
603 |
|
|
Use of the @samp{-a} argument is highly recommended with this option.
|
604 |
|
|
|
605 |
|
|
The @var{map_file} argument is a pathname to a file which provides
|
606 |
|
|
function name to object file mappings. The format of the file is similar to
|
607 |
|
|
the output of the program @code{nm}.
|
608 |
|
|
|
609 |
|
|
@smallexample
|
610 |
|
|
@group
|
611 |
|
|
c-parse.o:00000000 T yyparse
|
612 |
|
|
c-parse.o:00000004 C yyerrflag
|
613 |
|
|
c-lang.o:00000000 T maybe_objc_method_name
|
614 |
|
|
c-lang.o:00000000 T print_lang_statistics
|
615 |
|
|
c-lang.o:00000000 T recognize_objc_keyword
|
616 |
|
|
c-decl.o:00000000 T print_lang_identifier
|
617 |
|
|
c-decl.o:00000000 T print_lang_type
|
618 |
|
|
@dots{}
|
619 |
|
|
|
620 |
|
|
@end group
|
621 |
|
|
@end smallexample
|
622 |
|
|
|
623 |
|
|
To create a @var{map_file} with @sc{gnu} @code{nm}, type a command like
|
624 |
|
|
@kbd{nm --extern-only --defined-only -v --print-file-name program-name}.
|
625 |
|
|
|
626 |
|
|
@item -T
|
627 |
|
|
@itemx --traditional
|
628 |
|
|
The @samp{-T} option causes @code{gprof} to print its output in
|
629 |
|
|
``traditional'' BSD style.
|
630 |
|
|
|
631 |
|
|
@item -w @var{width}
|
632 |
|
|
@itemx --width=@var{width}
|
633 |
|
|
Sets width of output lines to @var{width}.
|
634 |
|
|
Currently only used when printing the function index at the bottom
|
635 |
|
|
of the call graph.
|
636 |
|
|
|
637 |
|
|
@item -x
|
638 |
|
|
@itemx --all-lines
|
639 |
|
|
This option affects annotated source output only.
|
640 |
|
|
By default, only the lines at the beginning of a basic-block
|
641 |
|
|
are annotated. If this option is specified, every line in
|
642 |
|
|
a basic-block is annotated by repeating the annotation for the
|
643 |
|
|
first line. This behavior is similar to @code{tcov}'s @samp{-a}.
|
644 |
|
|
|
645 |
|
|
@item --demangle[=@var{style}]
|
646 |
|
|
@itemx --no-demangle
|
647 |
|
|
These options control whether C++ symbol names should be demangled when
|
648 |
|
|
printing output. The default is to demangle symbols. The
|
649 |
|
|
@code{--no-demangle} option may be used to turn off demangling. Different
|
650 |
|
|
compilers have different mangling styles. The optional demangling style
|
651 |
|
|
argument can be used to choose an appropriate demangling style for your
|
652 |
|
|
compiler.
|
653 |
|
|
@end table
|
654 |
|
|
|
655 |
|
|
@node Analysis Options
|
656 |
|
|
@section Analysis Options
|
657 |
|
|
|
658 |
|
|
@table @code
|
659 |
|
|
|
660 |
|
|
@item -a
|
661 |
|
|
@itemx --no-static
|
662 |
|
|
The @samp{-a} option causes @code{gprof} to suppress the printing of
|
663 |
|
|
statically declared (private) functions. (These are functions whose
|
664 |
|
|
names are not listed as global, and which are not visible outside the
|
665 |
|
|
file/function/block where they were defined.) Time spent in these
|
666 |
|
|
functions, calls to/from them, etc., will all be attributed to the
|
667 |
|
|
function that was loaded directly before it in the executable file.
|
668 |
|
|
@c This is compatible with Unix @code{gprof}, but a bad idea.
|
669 |
|
|
This option affects both the flat profile and the call graph.
|
670 |
|
|
|
671 |
|
|
@item -c
|
672 |
|
|
@itemx --static-call-graph
|
673 |
|
|
The @samp{-c} option causes the call graph of the program to be
|
674 |
|
|
augmented by a heuristic which examines the text space of the object
|
675 |
|
|
file and identifies function calls in the binary machine code.
|
676 |
|
|
Since normal call graph records are only generated when functions are
|
677 |
|
|
entered, this option identifies children that could have been called,
|
678 |
|
|
but never were. Calls to functions that were not compiled with
|
679 |
|
|
profiling enabled are also identified, but only if symbol table
|
680 |
|
|
entries are present for them.
|
681 |
|
|
Calls to dynamic library routines are typically @emph{not} found
|
682 |
|
|
by this option.
|
683 |
|
|
Parents or children identified via this heuristic
|
684 |
|
|
are indicated in the call graph with call counts of @samp{0}.
|
685 |
|
|
|
686 |
|
|
@item -D
|
687 |
|
|
@itemx --ignore-non-functions
|
688 |
|
|
The @samp{-D} option causes @code{gprof} to ignore symbols which
|
689 |
|
|
are not known to be functions. This option will give more accurate
|
690 |
|
|
profile data on systems where it is supported (Solaris and HPUX for
|
691 |
|
|
example).
|
692 |
|
|
|
693 |
|
|
@item -k @var{from}/@var{to}
|
694 |
|
|
The @samp{-k} option allows you to delete from the call graph any arcs from
|
695 |
|
|
symbols matching symspec @var{from} to those matching symspec @var{to}.
|
696 |
|
|
|
697 |
|
|
@item -l
|
698 |
|
|
@itemx --line
|
699 |
|
|
The @samp{-l} option enables line-by-line profiling, which causes
|
700 |
|
|
histogram hits to be charged to individual source code lines,
|
701 |
|
|
instead of functions. This feature only works with programs compiled
|
702 |
|
|
by older versions of the @code{gcc} compiler. Newer versions of
|
703 |
|
|
@code{gcc} are designed to work with the @code{gcov} tool instead.
|
704 |
|
|
|
705 |
|
|
If the program was compiled with basic-block counting enabled,
|
706 |
|
|
this option will also identify how many times each line of
|
707 |
|
|
code was executed.
|
708 |
|
|
While line-by-line profiling can help isolate where in a large function
|
709 |
|
|
a program is spending its time, it also significantly increases
|
710 |
|
|
the running time of @code{gprof}, and magnifies statistical
|
711 |
|
|
inaccuracies.
|
712 |
|
|
@xref{Sampling Error, ,Statistical Sampling Error}.
|
713 |
|
|
|
714 |
|
|
@item -m @var{num}
|
715 |
|
|
@itemx --min-count=@var{num}
|
716 |
|
|
This option affects execution count output only.
|
717 |
|
|
Symbols that are executed less than @var{num} times are suppressed.
|
718 |
|
|
|
719 |
|
|
@item -n@var{symspec}
|
720 |
|
|
@itemx --time=@var{symspec}
|
721 |
|
|
The @samp{-n} option causes @code{gprof}, in its call graph analysis,
|
722 |
|
|
to only propagate times for symbols matching @var{symspec}.
|
723 |
|
|
|
724 |
|
|
@item -N@var{symspec}
|
725 |
|
|
@itemx --no-time=@var{symspec}
|
726 |
|
|
The @samp{-n} option causes @code{gprof}, in its call graph analysis,
|
727 |
|
|
not to propagate times for symbols matching @var{symspec}.
|
728 |
|
|
|
729 |
|
|
@item -S@var{filename}
|
730 |
|
|
@itemx --external-symbol-table=@var{filename}
|
731 |
|
|
The @samp{-S} option causes @code{gprof} to read an external symbol table
|
732 |
|
|
file, such as @file{/proc/kallsyms}, rather than read the symbol table
|
733 |
|
|
from the given object file (the default is @code{a.out}). This is useful
|
734 |
|
|
for profiling kernel modules.
|
735 |
|
|
|
736 |
|
|
@item -z
|
737 |
|
|
@itemx --display-unused-functions
|
738 |
|
|
If you give the @samp{-z} option, @code{gprof} will mention all
|
739 |
|
|
functions in the flat profile, even those that were never called, and
|
740 |
|
|
that had no time spent in them. This is useful in conjunction with the
|
741 |
|
|
@samp{-c} option for discovering which routines were never called.
|
742 |
|
|
|
743 |
|
|
@end table
|
744 |
|
|
|
745 |
|
|
@node Miscellaneous Options
|
746 |
|
|
@section Miscellaneous Options
|
747 |
|
|
|
748 |
|
|
@table @code
|
749 |
|
|
|
750 |
|
|
@item -d[@var{num}]
|
751 |
|
|
@itemx --debug[=@var{num}]
|
752 |
|
|
The @samp{-d @var{num}} option specifies debugging options.
|
753 |
|
|
If @var{num} is not specified, enable all debugging.
|
754 |
|
|
@xref{Debugging, ,Debugging @code{gprof}}.
|
755 |
|
|
|
756 |
|
|
@item -h
|
757 |
|
|
@itemx --help
|
758 |
|
|
The @samp{-h} option prints command line usage.
|
759 |
|
|
|
760 |
|
|
@item -O@var{name}
|
761 |
|
|
@itemx --file-format=@var{name}
|
762 |
|
|
Selects the format of the profile data files. Recognized formats are
|
763 |
|
|
@samp{auto} (the default), @samp{bsd}, @samp{4.4bsd}, @samp{magic}, and
|
764 |
|
|
@samp{prof} (not yet supported).
|
765 |
|
|
|
766 |
|
|
@item -s
|
767 |
|
|
@itemx --sum
|
768 |
|
|
The @samp{-s} option causes @code{gprof} to summarize the information
|
769 |
|
|
in the profile data files it read in, and write out a profile data
|
770 |
|
|
file called @file{gmon.sum}, which contains all the information from
|
771 |
|
|
the profile data files that @code{gprof} read in. The file @file{gmon.sum}
|
772 |
|
|
may be one of the specified input files; the effect of this is to
|
773 |
|
|
merge the data in the other input files into @file{gmon.sum}.
|
774 |
|
|
|
775 |
|
|
Eventually you can run @code{gprof} again without @samp{-s} to analyze the
|
776 |
|
|
cumulative data in the file @file{gmon.sum}.
|
777 |
|
|
|
778 |
|
|
@item -v
|
779 |
|
|
@itemx --version
|
780 |
|
|
The @samp{-v} flag causes @code{gprof} to print the current version
|
781 |
|
|
number, and then exit.
|
782 |
|
|
|
783 |
|
|
@end table
|
784 |
|
|
|
785 |
|
|
@node Deprecated Options
|
786 |
|
|
@section Deprecated Options
|
787 |
|
|
|
788 |
|
|
@table @code
|
789 |
|
|
|
790 |
|
|
These options have been replaced with newer versions that use symspecs.
|
791 |
|
|
|
792 |
|
|
@item -e @var{function_name}
|
793 |
|
|
The @samp{-e @var{function}} option tells @code{gprof} to not print
|
794 |
|
|
information about the function @var{function_name} (and its
|
795 |
|
|
children@dots{}) in the call graph. The function will still be listed
|
796 |
|
|
as a child of any functions that call it, but its index number will be
|
797 |
|
|
shown as @samp{[not printed]}. More than one @samp{-e} option may be
|
798 |
|
|
given; only one @var{function_name} may be indicated with each @samp{-e}
|
799 |
|
|
option.
|
800 |
|
|
|
801 |
|
|
@item -E @var{function_name}
|
802 |
|
|
The @code{-E @var{function}} option works like the @code{-e} option, but
|
803 |
|
|
time spent in the function (and children who were not called from
|
804 |
|
|
anywhere else), will not be used to compute the percentages-of-time for
|
805 |
|
|
the call graph. More than one @samp{-E} option may be given; only one
|
806 |
|
|
@var{function_name} may be indicated with each @samp{-E} option.
|
807 |
|
|
|
808 |
|
|
@item -f @var{function_name}
|
809 |
|
|
The @samp{-f @var{function}} option causes @code{gprof} to limit the
|
810 |
|
|
call graph to the function @var{function_name} and its children (and
|
811 |
|
|
their children@dots{}). More than one @samp{-f} option may be given;
|
812 |
|
|
only one @var{function_name} may be indicated with each @samp{-f}
|
813 |
|
|
option.
|
814 |
|
|
|
815 |
|
|
@item -F @var{function_name}
|
816 |
|
|
The @samp{-F @var{function}} option works like the @code{-f} option, but
|
817 |
|
|
only time spent in the function and its children (and their
|
818 |
|
|
children@dots{}) will be used to determine total-time and
|
819 |
|
|
percentages-of-time for the call graph. More than one @samp{-F} option
|
820 |
|
|
may be given; only one @var{function_name} may be indicated with each
|
821 |
|
|
@samp{-F} option. The @samp{-F} option overrides the @samp{-E} option.
|
822 |
|
|
|
823 |
|
|
@end table
|
824 |
|
|
|
825 |
|
|
@c man end
|
826 |
|
|
|
827 |
|
|
Note that only one function can be specified with each @code{-e},
|
828 |
|
|
@code{-E}, @code{-f} or @code{-F} option. To specify more than one
|
829 |
|
|
function, use multiple options. For example, this command:
|
830 |
|
|
|
831 |
|
|
@example
|
832 |
|
|
gprof -e boring -f foo -f bar myprogram > gprof.output
|
833 |
|
|
@end example
|
834 |
|
|
|
835 |
|
|
@noindent
|
836 |
|
|
lists in the call graph all functions that were reached from either
|
837 |
|
|
@code{foo} or @code{bar} and were not reachable from @code{boring}.
|
838 |
|
|
|
839 |
|
|
@node Symspecs
|
840 |
|
|
@section Symspecs
|
841 |
|
|
|
842 |
|
|
Many of the output options allow functions to be included or excluded
|
843 |
|
|
using @dfn{symspecs} (symbol specifications), which observe the
|
844 |
|
|
following syntax:
|
845 |
|
|
|
846 |
|
|
@example
|
847 |
|
|
filename_containing_a_dot
|
848 |
|
|
| funcname_not_containing_a_dot
|
849 |
|
|
| linenumber
|
850 |
|
|
| ( [ any_filename ] `:' ( any_funcname | linenumber ) )
|
851 |
|
|
@end example
|
852 |
|
|
|
853 |
|
|
Here are some sample symspecs:
|
854 |
|
|
|
855 |
|
|
@table @samp
|
856 |
|
|
@item main.c
|
857 |
|
|
Selects everything in file @file{main.c}---the
|
858 |
|
|
dot in the string tells @code{gprof} to interpret
|
859 |
|
|
the string as a filename, rather than as
|
860 |
|
|
a function name. To select a file whose
|
861 |
|
|
name does not contain a dot, a trailing colon
|
862 |
|
|
should be specified. For example, @samp{odd:} is
|
863 |
|
|
interpreted as the file named @file{odd}.
|
864 |
|
|
|
865 |
|
|
@item main
|
866 |
|
|
Selects all functions named @samp{main}.
|
867 |
|
|
|
868 |
|
|
Note that there may be multiple instances of the same function name
|
869 |
|
|
because some of the definitions may be local (i.e., static). Unless a
|
870 |
|
|
function name is unique in a program, you must use the colon notation
|
871 |
|
|
explained below to specify a function from a specific source file.
|
872 |
|
|
|
873 |
|
|
Sometimes, function names contain dots. In such cases, it is necessary
|
874 |
|
|
to add a leading colon to the name. For example, @samp{:.mul} selects
|
875 |
|
|
function @samp{.mul}.
|
876 |
|
|
|
877 |
|
|
In some object file formats, symbols have a leading underscore.
|
878 |
|
|
@code{gprof} will normally not print these underscores. When you name a
|
879 |
|
|
symbol in a symspec, you should type it exactly as @code{gprof} prints
|
880 |
|
|
it in its output. For example, if the compiler produces a symbol
|
881 |
|
|
@samp{_main} from your @code{main} function, @code{gprof} still prints
|
882 |
|
|
it as @samp{main} in its output, so you should use @samp{main} in
|
883 |
|
|
symspecs.
|
884 |
|
|
|
885 |
|
|
@item main.c:main
|
886 |
|
|
Selects function @samp{main} in file @file{main.c}.
|
887 |
|
|
|
888 |
|
|
@item main.c:134
|
889 |
|
|
Selects line 134 in file @file{main.c}.
|
890 |
|
|
@end table
|
891 |
|
|
|
892 |
|
|
@node Output
|
893 |
|
|
@chapter Interpreting @code{gprof}'s Output
|
894 |
|
|
|
895 |
|
|
@code{gprof} can produce several different output styles, the
|
896 |
|
|
most important of which are described below. The simplest output
|
897 |
|
|
styles (file information, execution count, and function and file ordering)
|
898 |
|
|
are not described here, but are documented with the respective options
|
899 |
|
|
that trigger them.
|
900 |
|
|
@xref{Output Options, ,Output Options}.
|
901 |
|
|
|
902 |
|
|
@menu
|
903 |
|
|
* Flat Profile:: The flat profile shows how much time was spent
|
904 |
|
|
executing directly in each function.
|
905 |
|
|
* Call Graph:: The call graph shows which functions called which
|
906 |
|
|
others, and how much time each function used
|
907 |
|
|
when its subroutine calls are included.
|
908 |
|
|
* Line-by-line:: @code{gprof} can analyze individual source code lines
|
909 |
|
|
* Annotated Source:: The annotated source listing displays source code
|
910 |
|
|
labeled with execution counts
|
911 |
|
|
@end menu
|
912 |
|
|
|
913 |
|
|
|
914 |
|
|
@node Flat Profile
|
915 |
|
|
@section The Flat Profile
|
916 |
|
|
@cindex flat profile
|
917 |
|
|
|
918 |
|
|
The @dfn{flat profile} shows the total amount of time your program
|
919 |
|
|
spent executing each function. Unless the @samp{-z} option is given,
|
920 |
|
|
functions with no apparent time spent in them, and no apparent calls
|
921 |
|
|
to them, are not mentioned. Note that if a function was not compiled
|
922 |
|
|
for profiling, and didn't run long enough to show up on the program
|
923 |
|
|
counter histogram, it will be indistinguishable from a function that
|
924 |
|
|
was never called.
|
925 |
|
|
|
926 |
|
|
This is part of a flat profile for a small program:
|
927 |
|
|
|
928 |
|
|
@smallexample
|
929 |
|
|
@group
|
930 |
|
|
Flat profile:
|
931 |
|
|
|
932 |
|
|
Each sample counts as 0.01 seconds.
|
933 |
|
|
% cumulative self self total
|
934 |
|
|
time seconds seconds calls ms/call ms/call name
|
935 |
|
|
33.34 0.02 0.02 7208 0.00 0.00 open
|
936 |
|
|
16.67 0.03 0.01 244 0.04 0.12 offtime
|
937 |
|
|
16.67 0.04 0.01 8 1.25 1.25 memccpy
|
938 |
|
|
16.67 0.05 0.01 7 1.43 1.43 write
|
939 |
|
|
16.67 0.06 0.01 mcount
|
940 |
|
|
0.00 0.06 0.00 236 0.00 0.00 tzset
|
941 |
|
|
0.00 0.06 0.00 192 0.00 0.00 tolower
|
942 |
|
|
0.00 0.06 0.00 47 0.00 0.00 strlen
|
943 |
|
|
0.00 0.06 0.00 45 0.00 0.00 strchr
|
944 |
|
|
0.00 0.06 0.00 1 0.00 50.00 main
|
945 |
|
|
0.00 0.06 0.00 1 0.00 0.00 memcpy
|
946 |
|
|
0.00 0.06 0.00 1 0.00 10.11 print
|
947 |
|
|
0.00 0.06 0.00 1 0.00 0.00 profil
|
948 |
|
|
0.00 0.06 0.00 1 0.00 50.00 report
|
949 |
|
|
@dots{}
|
950 |
|
|
@end group
|
951 |
|
|
@end smallexample
|
952 |
|
|
|
953 |
|
|
@noindent
|
954 |
|
|
The functions are sorted first by decreasing run-time spent in them,
|
955 |
|
|
then by decreasing number of calls, then alphabetically by name. The
|
956 |
|
|
functions @samp{mcount} and @samp{profil} are part of the profiling
|
957 |
|
|
apparatus and appear in every flat profile; their time gives a measure of
|
958 |
|
|
the amount of overhead due to profiling.
|
959 |
|
|
|
960 |
|
|
Just before the column headers, a statement appears indicating
|
961 |
|
|
how much time each sample counted as.
|
962 |
|
|
This @dfn{sampling period} estimates the margin of error in each of the time
|
963 |
|
|
figures. A time figure that is not much larger than this is not
|
964 |
|
|
reliable. In this example, each sample counted as 0.01 seconds,
|
965 |
|
|
suggesting a 100 Hz sampling rate.
|
966 |
|
|
The program's total execution time was 0.06
|
967 |
|
|
seconds, as indicated by the @samp{cumulative seconds} field. Since
|
968 |
|
|
each sample counted for 0.01 seconds, this means only six samples
|
969 |
|
|
were taken during the run. Two of the samples occurred while the
|
970 |
|
|
program was in the @samp{open} function, as indicated by the
|
971 |
|
|
@samp{self seconds} field. Each of the other four samples
|
972 |
|
|
occurred one each in @samp{offtime}, @samp{memccpy}, @samp{write},
|
973 |
|
|
and @samp{mcount}.
|
974 |
|
|
Since only six samples were taken, none of these values can
|
975 |
|
|
be regarded as particularly reliable.
|
976 |
|
|
In another run,
|
977 |
|
|
the @samp{self seconds} field for
|
978 |
|
|
@samp{mcount} might well be @samp{0.00} or @samp{0.02}.
|
979 |
|
|
@xref{Sampling Error, ,Statistical Sampling Error},
|
980 |
|
|
for a complete discussion.
|
981 |
|
|
|
982 |
|
|
The remaining functions in the listing (those whose
|
983 |
|
|
@samp{self seconds} field is @samp{0.00}) didn't appear
|
984 |
|
|
in the histogram samples at all. However, the call graph
|
985 |
|
|
indicated that they were called, so therefore they are listed,
|
986 |
|
|
sorted in decreasing order by the @samp{calls} field.
|
987 |
|
|
Clearly some time was spent executing these functions,
|
988 |
|
|
but the paucity of histogram samples prevents any
|
989 |
|
|
determination of how much time each took.
|
990 |
|
|
|
991 |
|
|
Here is what the fields in each line mean:
|
992 |
|
|
|
993 |
|
|
@table @code
|
994 |
|
|
@item % time
|
995 |
|
|
This is the percentage of the total execution time your program spent
|
996 |
|
|
in this function. These should all add up to 100%.
|
997 |
|
|
|
998 |
|
|
@item cumulative seconds
|
999 |
|
|
This is the cumulative total number of seconds the computer spent
|
1000 |
|
|
executing this functions, plus the time spent in all the functions
|
1001 |
|
|
above this one in this table.
|
1002 |
|
|
|
1003 |
|
|
@item self seconds
|
1004 |
|
|
This is the number of seconds accounted for by this function alone.
|
1005 |
|
|
The flat profile listing is sorted first by this number.
|
1006 |
|
|
|
1007 |
|
|
@item calls
|
1008 |
|
|
This is the total number of times the function was called. If the
|
1009 |
|
|
function was never called, or the number of times it was called cannot
|
1010 |
|
|
be determined (probably because the function was not compiled with
|
1011 |
|
|
profiling enabled), the @dfn{calls} field is blank.
|
1012 |
|
|
|
1013 |
|
|
@item self ms/call
|
1014 |
|
|
This represents the average number of milliseconds spent in this
|
1015 |
|
|
function per call, if this function is profiled. Otherwise, this field
|
1016 |
|
|
is blank for this function.
|
1017 |
|
|
|
1018 |
|
|
@item total ms/call
|
1019 |
|
|
This represents the average number of milliseconds spent in this
|
1020 |
|
|
function and its descendants per call, if this function is profiled.
|
1021 |
|
|
Otherwise, this field is blank for this function.
|
1022 |
|
|
This is the only field in the flat profile that uses call graph analysis.
|
1023 |
|
|
|
1024 |
|
|
@item name
|
1025 |
|
|
This is the name of the function. The flat profile is sorted by this
|
1026 |
|
|
field alphabetically after the @dfn{self seconds} and @dfn{calls}
|
1027 |
|
|
fields are sorted.
|
1028 |
|
|
@end table
|
1029 |
|
|
|
1030 |
|
|
@node Call Graph
|
1031 |
|
|
@section The Call Graph
|
1032 |
|
|
@cindex call graph
|
1033 |
|
|
|
1034 |
|
|
The @dfn{call graph} shows how much time was spent in each function
|
1035 |
|
|
and its children. From this information, you can find functions that,
|
1036 |
|
|
while they themselves may not have used much time, called other
|
1037 |
|
|
functions that did use unusual amounts of time.
|
1038 |
|
|
|
1039 |
|
|
Here is a sample call from a small program. This call came from the
|
1040 |
|
|
same @code{gprof} run as the flat profile example in the previous
|
1041 |
|
|
section.
|
1042 |
|
|
|
1043 |
|
|
@smallexample
|
1044 |
|
|
@group
|
1045 |
|
|
granularity: each sample hit covers 2 byte(s) for 20.00% of 0.05 seconds
|
1046 |
|
|
|
1047 |
|
|
index % time self children called name
|
1048 |
|
|
<spontaneous>
|
1049 |
|
|
[1] 100.0 0.00 0.05 start [1]
|
1050 |
|
|
0.00 0.05 1/1 main [2]
|
1051 |
|
|
0.00 0.00 1/2 on_exit [28]
|
1052 |
|
|
0.00 0.00 1/1 exit [59]
|
1053 |
|
|
-----------------------------------------------
|
1054 |
|
|
0.00 0.05 1/1 start [1]
|
1055 |
|
|
[2] 100.0 0.00 0.05 1 main [2]
|
1056 |
|
|
0.00 0.05 1/1 report [3]
|
1057 |
|
|
-----------------------------------------------
|
1058 |
|
|
0.00 0.05 1/1 main [2]
|
1059 |
|
|
[3] 100.0 0.00 0.05 1 report [3]
|
1060 |
|
|
0.00 0.03 8/8 timelocal [6]
|
1061 |
|
|
0.00 0.01 1/1 print [9]
|
1062 |
|
|
0.00 0.01 9/9 fgets [12]
|
1063 |
|
|
0.00 0.00 12/34 strncmp <cycle 1> [40]
|
1064 |
|
|
0.00 0.00 8/8 lookup [20]
|
1065 |
|
|
0.00 0.00 1/1 fopen [21]
|
1066 |
|
|
0.00 0.00 8/8 chewtime [24]
|
1067 |
|
|
0.00 0.00 8/16 skipspace [44]
|
1068 |
|
|
-----------------------------------------------
|
1069 |
|
|
[4] 59.8 0.01 0.02 8+472 <cycle 2 as a whole> [4]
|
1070 |
|
|
0.01 0.02 244+260 offtime <cycle 2> [7]
|
1071 |
|
|
0.00 0.00 236+1 tzset <cycle 2> [26]
|
1072 |
|
|
-----------------------------------------------
|
1073 |
|
|
@end group
|
1074 |
|
|
@end smallexample
|
1075 |
|
|
|
1076 |
|
|
The lines full of dashes divide this table into @dfn{entries}, one for each
|
1077 |
|
|
function. Each entry has one or more lines.
|
1078 |
|
|
|
1079 |
|
|
In each entry, the primary line is the one that starts with an index number
|
1080 |
|
|
in square brackets. The end of this line says which function the entry is
|
1081 |
|
|
for. The preceding lines in the entry describe the callers of this
|
1082 |
|
|
function and the following lines describe its subroutines (also called
|
1083 |
|
|
@dfn{children} when we speak of the call graph).
|
1084 |
|
|
|
1085 |
|
|
The entries are sorted by time spent in the function and its subroutines.
|
1086 |
|
|
|
1087 |
|
|
The internal profiling function @code{mcount} (@pxref{Flat Profile, ,The
|
1088 |
|
|
Flat Profile}) is never mentioned in the call graph.
|
1089 |
|
|
|
1090 |
|
|
@menu
|
1091 |
|
|
* Primary:: Details of the primary line's contents.
|
1092 |
|
|
* Callers:: Details of caller-lines' contents.
|
1093 |
|
|
* Subroutines:: Details of subroutine-lines' contents.
|
1094 |
|
|
* Cycles:: When there are cycles of recursion,
|
1095 |
|
|
such as @code{a} calls @code{b} calls @code{a}@dots{}
|
1096 |
|
|
@end menu
|
1097 |
|
|
|
1098 |
|
|
@node Primary
|
1099 |
|
|
@subsection The Primary Line
|
1100 |
|
|
|
1101 |
|
|
The @dfn{primary line} in a call graph entry is the line that
|
1102 |
|
|
describes the function which the entry is about and gives the overall
|
1103 |
|
|
statistics for this function.
|
1104 |
|
|
|
1105 |
|
|
For reference, we repeat the primary line from the entry for function
|
1106 |
|
|
@code{report} in our main example, together with the heading line that
|
1107 |
|
|
shows the names of the fields:
|
1108 |
|
|
|
1109 |
|
|
@smallexample
|
1110 |
|
|
@group
|
1111 |
|
|
index % time self children called name
|
1112 |
|
|
@dots{}
|
1113 |
|
|
[3] 100.0 0.00 0.05 1 report [3]
|
1114 |
|
|
@end group
|
1115 |
|
|
@end smallexample
|
1116 |
|
|
|
1117 |
|
|
Here is what the fields in the primary line mean:
|
1118 |
|
|
|
1119 |
|
|
@table @code
|
1120 |
|
|
@item index
|
1121 |
|
|
Entries are numbered with consecutive integers. Each function
|
1122 |
|
|
therefore has an index number, which appears at the beginning of its
|
1123 |
|
|
primary line.
|
1124 |
|
|
|
1125 |
|
|
Each cross-reference to a function, as a caller or subroutine of
|
1126 |
|
|
another, gives its index number as well as its name. The index number
|
1127 |
|
|
guides you if you wish to look for the entry for that function.
|
1128 |
|
|
|
1129 |
|
|
@item % time
|
1130 |
|
|
This is the percentage of the total time that was spent in this
|
1131 |
|
|
function, including time spent in subroutines called from this
|
1132 |
|
|
function.
|
1133 |
|
|
|
1134 |
|
|
The time spent in this function is counted again for the callers of
|
1135 |
|
|
this function. Therefore, adding up these percentages is meaningless.
|
1136 |
|
|
|
1137 |
|
|
@item self
|
1138 |
|
|
This is the total amount of time spent in this function. This
|
1139 |
|
|
should be identical to the number printed in the @code{seconds} field
|
1140 |
|
|
for this function in the flat profile.
|
1141 |
|
|
|
1142 |
|
|
@item children
|
1143 |
|
|
This is the total amount of time spent in the subroutine calls made by
|
1144 |
|
|
this function. This should be equal to the sum of all the @code{self}
|
1145 |
|
|
and @code{children} entries of the children listed directly below this
|
1146 |
|
|
function.
|
1147 |
|
|
|
1148 |
|
|
@item called
|
1149 |
|
|
This is the number of times the function was called.
|
1150 |
|
|
|
1151 |
|
|
If the function called itself recursively, there are two numbers,
|
1152 |
|
|
separated by a @samp{+}. The first number counts non-recursive calls,
|
1153 |
|
|
and the second counts recursive calls.
|
1154 |
|
|
|
1155 |
|
|
In the example above, the function @code{report} was called once from
|
1156 |
|
|
@code{main}.
|
1157 |
|
|
|
1158 |
|
|
@item name
|
1159 |
|
|
This is the name of the current function. The index number is
|
1160 |
|
|
repeated after it.
|
1161 |
|
|
|
1162 |
|
|
If the function is part of a cycle of recursion, the cycle number is
|
1163 |
|
|
printed between the function's name and the index number
|
1164 |
|
|
(@pxref{Cycles, ,How Mutually Recursive Functions Are Described}).
|
1165 |
|
|
For example, if function @code{gnurr} is part of
|
1166 |
|
|
cycle number one, and has index number twelve, its primary line would
|
1167 |
|
|
be end like this:
|
1168 |
|
|
|
1169 |
|
|
@example
|
1170 |
|
|
gnurr <cycle 1> [12]
|
1171 |
|
|
@end example
|
1172 |
|
|
@end table
|
1173 |
|
|
|
1174 |
|
|
@node Callers
|
1175 |
|
|
@subsection Lines for a Function's Callers
|
1176 |
|
|
|
1177 |
|
|
A function's entry has a line for each function it was called by.
|
1178 |
|
|
These lines' fields correspond to the fields of the primary line, but
|
1179 |
|
|
their meanings are different because of the difference in context.
|
1180 |
|
|
|
1181 |
|
|
For reference, we repeat two lines from the entry for the function
|
1182 |
|
|
@code{report}, the primary line and one caller-line preceding it, together
|
1183 |
|
|
with the heading line that shows the names of the fields:
|
1184 |
|
|
|
1185 |
|
|
@smallexample
|
1186 |
|
|
index % time self children called name
|
1187 |
|
|
@dots{}
|
1188 |
|
|
0.00 0.05 1/1 main [2]
|
1189 |
|
|
[3] 100.0 0.00 0.05 1 report [3]
|
1190 |
|
|
@end smallexample
|
1191 |
|
|
|
1192 |
|
|
Here are the meanings of the fields in the caller-line for @code{report}
|
1193 |
|
|
called from @code{main}:
|
1194 |
|
|
|
1195 |
|
|
@table @code
|
1196 |
|
|
@item self
|
1197 |
|
|
An estimate of the amount of time spent in @code{report} itself when it was
|
1198 |
|
|
called from @code{main}.
|
1199 |
|
|
|
1200 |
|
|
@item children
|
1201 |
|
|
An estimate of the amount of time spent in subroutines of @code{report}
|
1202 |
|
|
when @code{report} was called from @code{main}.
|
1203 |
|
|
|
1204 |
|
|
The sum of the @code{self} and @code{children} fields is an estimate
|
1205 |
|
|
of the amount of time spent within calls to @code{report} from @code{main}.
|
1206 |
|
|
|
1207 |
|
|
@item called
|
1208 |
|
|
Two numbers: the number of times @code{report} was called from @code{main},
|
1209 |
|
|
followed by the total number of non-recursive calls to @code{report} from
|
1210 |
|
|
all its callers.
|
1211 |
|
|
|
1212 |
|
|
@item name and index number
|
1213 |
|
|
The name of the caller of @code{report} to which this line applies,
|
1214 |
|
|
followed by the caller's index number.
|
1215 |
|
|
|
1216 |
|
|
Not all functions have entries in the call graph; some
|
1217 |
|
|
options to @code{gprof} request the omission of certain functions.
|
1218 |
|
|
When a caller has no entry of its own, it still has caller-lines
|
1219 |
|
|
in the entries of the functions it calls.
|
1220 |
|
|
|
1221 |
|
|
If the caller is part of a recursion cycle, the cycle number is
|
1222 |
|
|
printed between the name and the index number.
|
1223 |
|
|
@end table
|
1224 |
|
|
|
1225 |
|
|
If the identity of the callers of a function cannot be determined, a
|
1226 |
|
|
dummy caller-line is printed which has @samp{<spontaneous>} as the
|
1227 |
|
|
``caller's name'' and all other fields blank. This can happen for
|
1228 |
|
|
signal handlers.
|
1229 |
|
|
@c What if some calls have determinable callers' names but not all?
|
1230 |
|
|
@c FIXME - still relevant?
|
1231 |
|
|
|
1232 |
|
|
@node Subroutines
|
1233 |
|
|
@subsection Lines for a Function's Subroutines
|
1234 |
|
|
|
1235 |
|
|
A function's entry has a line for each of its subroutines---in other
|
1236 |
|
|
words, a line for each other function that it called. These lines'
|
1237 |
|
|
fields correspond to the fields of the primary line, but their meanings
|
1238 |
|
|
are different because of the difference in context.
|
1239 |
|
|
|
1240 |
|
|
For reference, we repeat two lines from the entry for the function
|
1241 |
|
|
@code{main}, the primary line and a line for a subroutine, together
|
1242 |
|
|
with the heading line that shows the names of the fields:
|
1243 |
|
|
|
1244 |
|
|
@smallexample
|
1245 |
|
|
index % time self children called name
|
1246 |
|
|
@dots{}
|
1247 |
|
|
[2] 100.0 0.00 0.05 1 main [2]
|
1248 |
|
|
0.00 0.05 1/1 report [3]
|
1249 |
|
|
@end smallexample
|
1250 |
|
|
|
1251 |
|
|
Here are the meanings of the fields in the subroutine-line for @code{main}
|
1252 |
|
|
calling @code{report}:
|
1253 |
|
|
|
1254 |
|
|
@table @code
|
1255 |
|
|
@item self
|
1256 |
|
|
An estimate of the amount of time spent directly within @code{report}
|
1257 |
|
|
when @code{report} was called from @code{main}.
|
1258 |
|
|
|
1259 |
|
|
@item children
|
1260 |
|
|
An estimate of the amount of time spent in subroutines of @code{report}
|
1261 |
|
|
when @code{report} was called from @code{main}.
|
1262 |
|
|
|
1263 |
|
|
The sum of the @code{self} and @code{children} fields is an estimate
|
1264 |
|
|
of the total time spent in calls to @code{report} from @code{main}.
|
1265 |
|
|
|
1266 |
|
|
@item called
|
1267 |
|
|
Two numbers, the number of calls to @code{report} from @code{main}
|
1268 |
|
|
followed by the total number of non-recursive calls to @code{report}.
|
1269 |
|
|
This ratio is used to determine how much of @code{report}'s @code{self}
|
1270 |
|
|
and @code{children} time gets credited to @code{main}.
|
1271 |
|
|
@xref{Assumptions, ,Estimating @code{children} Times}.
|
1272 |
|
|
|
1273 |
|
|
@item name
|
1274 |
|
|
The name of the subroutine of @code{main} to which this line applies,
|
1275 |
|
|
followed by the subroutine's index number.
|
1276 |
|
|
|
1277 |
|
|
If the caller is part of a recursion cycle, the cycle number is
|
1278 |
|
|
printed between the name and the index number.
|
1279 |
|
|
@end table
|
1280 |
|
|
|
1281 |
|
|
@node Cycles
|
1282 |
|
|
@subsection How Mutually Recursive Functions Are Described
|
1283 |
|
|
@cindex cycle
|
1284 |
|
|
@cindex recursion cycle
|
1285 |
|
|
|
1286 |
|
|
The graph may be complicated by the presence of @dfn{cycles of
|
1287 |
|
|
recursion} in the call graph. A cycle exists if a function calls
|
1288 |
|
|
another function that (directly or indirectly) calls (or appears to
|
1289 |
|
|
call) the original function. For example: if @code{a} calls @code{b},
|
1290 |
|
|
and @code{b} calls @code{a}, then @code{a} and @code{b} form a cycle.
|
1291 |
|
|
|
1292 |
|
|
Whenever there are call paths both ways between a pair of functions, they
|
1293 |
|
|
belong to the same cycle. If @code{a} and @code{b} call each other and
|
1294 |
|
|
@code{b} and @code{c} call each other, all three make one cycle. Note that
|
1295 |
|
|
even if @code{b} only calls @code{a} if it was not called from @code{a},
|
1296 |
|
|
@code{gprof} cannot determine this, so @code{a} and @code{b} are still
|
1297 |
|
|
considered a cycle.
|
1298 |
|
|
|
1299 |
|
|
The cycles are numbered with consecutive integers. When a function
|
1300 |
|
|
belongs to a cycle, each time the function name appears in the call graph
|
1301 |
|
|
it is followed by @samp{<cycle @var{number}>}.
|
1302 |
|
|
|
1303 |
|
|
The reason cycles matter is that they make the time values in the call
|
1304 |
|
|
graph paradoxical. The ``time spent in children'' of @code{a} should
|
1305 |
|
|
include the time spent in its subroutine @code{b} and in @code{b}'s
|
1306 |
|
|
subroutines---but one of @code{b}'s subroutines is @code{a}! How much of
|
1307 |
|
|
@code{a}'s time should be included in the children of @code{a}, when
|
1308 |
|
|
@code{a} is indirectly recursive?
|
1309 |
|
|
|
1310 |
|
|
The way @code{gprof} resolves this paradox is by creating a single entry
|
1311 |
|
|
for the cycle as a whole. The primary line of this entry describes the
|
1312 |
|
|
total time spent directly in the functions of the cycle. The
|
1313 |
|
|
``subroutines'' of the cycle are the individual functions of the cycle, and
|
1314 |
|
|
all other functions that were called directly by them. The ``callers'' of
|
1315 |
|
|
the cycle are the functions, outside the cycle, that called functions in
|
1316 |
|
|
the cycle.
|
1317 |
|
|
|
1318 |
|
|
Here is an example portion of a call graph which shows a cycle containing
|
1319 |
|
|
functions @code{a} and @code{b}. The cycle was entered by a call to
|
1320 |
|
|
@code{a} from @code{main}; both @code{a} and @code{b} called @code{c}.
|
1321 |
|
|
|
1322 |
|
|
@smallexample
|
1323 |
|
|
index % time self children called name
|
1324 |
|
|
----------------------------------------
|
1325 |
|
|
1.77 0 1/1 main [2]
|
1326 |
|
|
[3] 91.71 1.77 0 1+5 <cycle 1 as a whole> [3]
|
1327 |
|
|
1.02 0 3 b <cycle 1> [4]
|
1328 |
|
|
0.75 0 2 a <cycle 1> [5]
|
1329 |
|
|
----------------------------------------
|
1330 |
|
|
3 a <cycle 1> [5]
|
1331 |
|
|
[4] 52.85 1.02 0 0 b <cycle 1> [4]
|
1332 |
|
|
2 a <cycle 1> [5]
|
1333 |
|
|
|
1334 |
|
|
----------------------------------------
|
1335 |
|
|
1.77 0 1/1 main [2]
|
1336 |
|
|
2 b <cycle 1> [4]
|
1337 |
|
|
[5] 38.86 0.75 0 1 a <cycle 1> [5]
|
1338 |
|
|
3 b <cycle 1> [4]
|
1339 |
|
|
|
1340 |
|
|
----------------------------------------
|
1341 |
|
|
@end smallexample
|
1342 |
|
|
|
1343 |
|
|
@noindent
|
1344 |
|
|
(The entire call graph for this program contains in addition an entry for
|
1345 |
|
|
@code{main}, which calls @code{a}, and an entry for @code{c}, with callers
|
1346 |
|
|
@code{a} and @code{b}.)
|
1347 |
|
|
|
1348 |
|
|
@smallexample
|
1349 |
|
|
index % time self children called name
|
1350 |
|
|
<spontaneous>
|
1351 |
|
|
[1] 100.00 0 1.93 0 start [1]
|
1352 |
|
|
0.16 1.77 1/1 main [2]
|
1353 |
|
|
----------------------------------------
|
1354 |
|
|
0.16 1.77 1/1 start [1]
|
1355 |
|
|
[2] 100.00 0.16 1.77 1 main [2]
|
1356 |
|
|
1.77 0 1/1 a <cycle 1> [5]
|
1357 |
|
|
----------------------------------------
|
1358 |
|
|
1.77 0 1/1 main [2]
|
1359 |
|
|
[3] 91.71 1.77 0 1+5 <cycle 1 as a whole> [3]
|
1360 |
|
|
1.02 0 3 b <cycle 1> [4]
|
1361 |
|
|
0.75 0 2 a <cycle 1> [5]
|
1362 |
|
|
|
1363 |
|
|
----------------------------------------
|
1364 |
|
|
3 a <cycle 1> [5]
|
1365 |
|
|
[4] 52.85 1.02 0 0 b <cycle 1> [4]
|
1366 |
|
|
2 a <cycle 1> [5]
|
1367 |
|
|
|
1368 |
|
|
----------------------------------------
|
1369 |
|
|
1.77 0 1/1 main [2]
|
1370 |
|
|
2 b <cycle 1> [4]
|
1371 |
|
|
[5] 38.86 0.75 0 1 a <cycle 1> [5]
|
1372 |
|
|
3 b <cycle 1> [4]
|
1373 |
|
|
|
1374 |
|
|
----------------------------------------
|
1375 |
|
|
|
1376 |
|
|
|
1377 |
|
|
[6] 0.00 0 0 6 c [6]
|
1378 |
|
|
----------------------------------------
|
1379 |
|
|
@end smallexample
|
1380 |
|
|
|
1381 |
|
|
The @code{self} field of the cycle's primary line is the total time
|
1382 |
|
|
spent in all the functions of the cycle. It equals the sum of the
|
1383 |
|
|
@code{self} fields for the individual functions in the cycle, found
|
1384 |
|
|
in the entry in the subroutine lines for these functions.
|
1385 |
|
|
|
1386 |
|
|
The @code{children} fields of the cycle's primary line and subroutine lines
|
1387 |
|
|
count only subroutines outside the cycle. Even though @code{a} calls
|
1388 |
|
|
@code{b}, the time spent in those calls to @code{b} is not counted in
|
1389 |
|
|
@code{a}'s @code{children} time. Thus, we do not encounter the problem of
|
1390 |
|
|
what to do when the time in those calls to @code{b} includes indirect
|
1391 |
|
|
recursive calls back to @code{a}.
|
1392 |
|
|
|
1393 |
|
|
The @code{children} field of a caller-line in the cycle's entry estimates
|
1394 |
|
|
the amount of time spent @emph{in the whole cycle}, and its other
|
1395 |
|
|
subroutines, on the times when that caller called a function in the cycle.
|
1396 |
|
|
|
1397 |
|
|
The @code{called} field in the primary line for the cycle has two numbers:
|
1398 |
|
|
first, the number of times functions in the cycle were called by functions
|
1399 |
|
|
outside the cycle; second, the number of times they were called by
|
1400 |
|
|
functions in the cycle (including times when a function in the cycle calls
|
1401 |
|
|
itself). This is a generalization of the usual split into non-recursive and
|
1402 |
|
|
recursive calls.
|
1403 |
|
|
|
1404 |
|
|
The @code{called} field of a subroutine-line for a cycle member in the
|
1405 |
|
|
cycle's entry says how many time that function was called from functions in
|
1406 |
|
|
the cycle. The total of all these is the second number in the primary line's
|
1407 |
|
|
@code{called} field.
|
1408 |
|
|
|
1409 |
|
|
In the individual entry for a function in a cycle, the other functions in
|
1410 |
|
|
the same cycle can appear as subroutines and as callers. These lines show
|
1411 |
|
|
how many times each function in the cycle called or was called from each other
|
1412 |
|
|
function in the cycle. The @code{self} and @code{children} fields in these
|
1413 |
|
|
lines are blank because of the difficulty of defining meanings for them
|
1414 |
|
|
when recursion is going on.
|
1415 |
|
|
|
1416 |
|
|
@node Line-by-line
|
1417 |
|
|
@section Line-by-line Profiling
|
1418 |
|
|
|
1419 |
|
|
@code{gprof}'s @samp{-l} option causes the program to perform
|
1420 |
|
|
@dfn{line-by-line} profiling. In this mode, histogram
|
1421 |
|
|
samples are assigned not to functions, but to individual
|
1422 |
|
|
lines of source code. This only works with programs compiled with
|
1423 |
|
|
older versions of the @code{gcc} compiler. Newer versions of @code{gcc}
|
1424 |
|
|
use a different program - @code{gcov} - to display line-by-line
|
1425 |
|
|
profiling information.
|
1426 |
|
|
|
1427 |
|
|
With the older versions of @code{gcc} the program usually has to be
|
1428 |
|
|
compiled with a @samp{-g} option, in addition to @samp{-pg}, in order
|
1429 |
|
|
to generate debugging symbols for tracking source code lines.
|
1430 |
|
|
Note, in much older versions of @code{gcc} the program had to be
|
1431 |
|
|
compiled with the @samp{-a} command line option as well.
|
1432 |
|
|
|
1433 |
|
|
The flat profile is the most useful output table
|
1434 |
|
|
in line-by-line mode.
|
1435 |
|
|
The call graph isn't as useful as normal, since
|
1436 |
|
|
the current version of @code{gprof} does not propagate
|
1437 |
|
|
call graph arcs from source code lines to the enclosing function.
|
1438 |
|
|
The call graph does, however, show each line of code
|
1439 |
|
|
that called each function, along with a count.
|
1440 |
|
|
|
1441 |
|
|
Here is a section of @code{gprof}'s output, without line-by-line profiling.
|
1442 |
|
|
Note that @code{ct_init} accounted for four histogram hits, and
|
1443 |
|
|
13327 calls to @code{init_block}.
|
1444 |
|
|
|
1445 |
|
|
@smallexample
|
1446 |
|
|
Flat profile:
|
1447 |
|
|
|
1448 |
|
|
Each sample counts as 0.01 seconds.
|
1449 |
|
|
% cumulative self self total
|
1450 |
|
|
time seconds seconds calls us/call us/call name
|
1451 |
|
|
30.77 0.13 0.04 6335 6.31 6.31 ct_init
|
1452 |
|
|
|
1453 |
|
|
|
1454 |
|
|
Call graph (explanation follows)
|
1455 |
|
|
|
1456 |
|
|
|
1457 |
|
|
granularity: each sample hit covers 4 byte(s) for 7.69% of 0.13 seconds
|
1458 |
|
|
|
1459 |
|
|
index % time self children called name
|
1460 |
|
|
|
1461 |
|
|
0.00 0.00 1/13496 name_too_long
|
1462 |
|
|
0.00 0.00 40/13496 deflate
|
1463 |
|
|
0.00 0.00 128/13496 deflate_fast
|
1464 |
|
|
0.00 0.00 13327/13496 ct_init
|
1465 |
|
|
[7] 0.0 0.00 0.00 13496 init_block
|
1466 |
|
|
|
1467 |
|
|
@end smallexample
|
1468 |
|
|
|
1469 |
|
|
Now let's look at some of @code{gprof}'s output from the same program run,
|
1470 |
|
|
this time with line-by-line profiling enabled. Note that @code{ct_init}'s
|
1471 |
|
|
four histogram hits are broken down into four lines of source code---one hit
|
1472 |
|
|
occurred on each of lines 349, 351, 382 and 385. In the call graph,
|
1473 |
|
|
note how
|
1474 |
|
|
@code{ct_init}'s 13327 calls to @code{init_block} are broken down
|
1475 |
|
|
into one call from line 396, 3071 calls from line 384, 3730 calls
|
1476 |
|
|
from line 385, and 6525 calls from 387.
|
1477 |
|
|
|
1478 |
|
|
@smallexample
|
1479 |
|
|
Flat profile:
|
1480 |
|
|
|
1481 |
|
|
Each sample counts as 0.01 seconds.
|
1482 |
|
|
% cumulative self
|
1483 |
|
|
time seconds seconds calls name
|
1484 |
|
|
7.69 0.10 0.01 ct_init (trees.c:349)
|
1485 |
|
|
7.69 0.11 0.01 ct_init (trees.c:351)
|
1486 |
|
|
7.69 0.12 0.01 ct_init (trees.c:382)
|
1487 |
|
|
7.69 0.13 0.01 ct_init (trees.c:385)
|
1488 |
|
|
|
1489 |
|
|
|
1490 |
|
|
Call graph (explanation follows)
|
1491 |
|
|
|
1492 |
|
|
|
1493 |
|
|
granularity: each sample hit covers 4 byte(s) for 7.69% of 0.13 seconds
|
1494 |
|
|
|
1495 |
|
|
% time self children called name
|
1496 |
|
|
|
1497 |
|
|
0.00 0.00 1/13496 name_too_long (gzip.c:1440)
|
1498 |
|
|
0.00 0.00 1/13496 deflate (deflate.c:763)
|
1499 |
|
|
0.00 0.00 1/13496 ct_init (trees.c:396)
|
1500 |
|
|
0.00 0.00 2/13496 deflate (deflate.c:727)
|
1501 |
|
|
0.00 0.00 4/13496 deflate (deflate.c:686)
|
1502 |
|
|
0.00 0.00 5/13496 deflate (deflate.c:675)
|
1503 |
|
|
0.00 0.00 12/13496 deflate (deflate.c:679)
|
1504 |
|
|
0.00 0.00 16/13496 deflate (deflate.c:730)
|
1505 |
|
|
0.00 0.00 128/13496 deflate_fast (deflate.c:654)
|
1506 |
|
|
0.00 0.00 3071/13496 ct_init (trees.c:384)
|
1507 |
|
|
0.00 0.00 3730/13496 ct_init (trees.c:385)
|
1508 |
|
|
0.00 0.00 6525/13496 ct_init (trees.c:387)
|
1509 |
|
|
[6] 0.0 0.00 0.00 13496 init_block (trees.c:408)
|
1510 |
|
|
|
1511 |
|
|
@end smallexample
|
1512 |
|
|
|
1513 |
|
|
|
1514 |
|
|
@node Annotated Source
|
1515 |
|
|
@section The Annotated Source Listing
|
1516 |
|
|
|
1517 |
|
|
@code{gprof}'s @samp{-A} option triggers an annotated source listing,
|
1518 |
|
|
which lists the program's source code, each function labeled with the
|
1519 |
|
|
number of times it was called. You may also need to specify the
|
1520 |
|
|
@samp{-I} option, if @code{gprof} can't find the source code files.
|
1521 |
|
|
|
1522 |
|
|
With older versions of @code{gcc} compiling with @samp{gcc @dots{} -g
|
1523 |
|
|
-pg -a} augments your program with basic-block counting code, in
|
1524 |
|
|
addition to function counting code. This enables @code{gprof} to
|
1525 |
|
|
determine how many times each line of code was executed. With newer
|
1526 |
|
|
versions of @code{gcc} support for displaying basic-block counts is
|
1527 |
|
|
provided by the @code{gcov} program.
|
1528 |
|
|
|
1529 |
|
|
For example, consider the following function, taken from gzip,
|
1530 |
|
|
with line numbers added:
|
1531 |
|
|
|
1532 |
|
|
@smallexample
|
1533 |
|
|
1 ulg updcrc(s, n)
|
1534 |
|
|
2 uch *s;
|
1535 |
|
|
3 unsigned n;
|
1536 |
|
|
4 @{
|
1537 |
|
|
5 register ulg c;
|
1538 |
|
|
6
|
1539 |
|
|
7 static ulg crc = (ulg)0xffffffffL;
|
1540 |
|
|
8
|
1541 |
|
|
9 if (s == NULL) @{
|
1542 |
|
|
10 c = 0xffffffffL;
|
1543 |
|
|
11 @} else @{
|
1544 |
|
|
12 c = crc;
|
1545 |
|
|
13 if (n) do @{
|
1546 |
|
|
14 c = crc_32_tab[...];
|
1547 |
|
|
15 @} while (--n);
|
1548 |
|
|
16 @}
|
1549 |
|
|
17 crc = c;
|
1550 |
|
|
18 return c ^ 0xffffffffL;
|
1551 |
|
|
19 @}
|
1552 |
|
|
|
1553 |
|
|
@end smallexample
|
1554 |
|
|
|
1555 |
|
|
@code{updcrc} has at least five basic-blocks.
|
1556 |
|
|
One is the function itself. The
|
1557 |
|
|
@code{if} statement on line 9 generates two more basic-blocks, one
|
1558 |
|
|
for each branch of the @code{if}. A fourth basic-block results from
|
1559 |
|
|
the @code{if} on line 13, and the contents of the @code{do} loop form
|
1560 |
|
|
the fifth basic-block. The compiler may also generate additional
|
1561 |
|
|
basic-blocks to handle various special cases.
|
1562 |
|
|
|
1563 |
|
|
A program augmented for basic-block counting can be analyzed with
|
1564 |
|
|
@samp{gprof -l -A}.
|
1565 |
|
|
The @samp{-x} option is also helpful,
|
1566 |
|
|
to ensure that each line of code is labeled at least once.
|
1567 |
|
|
Here is @code{updcrc}'s
|
1568 |
|
|
annotated source listing for a sample @code{gzip} run:
|
1569 |
|
|
|
1570 |
|
|
@smallexample
|
1571 |
|
|
ulg updcrc(s, n)
|
1572 |
|
|
uch *s;
|
1573 |
|
|
unsigned n;
|
1574 |
|
|
2 ->@{
|
1575 |
|
|
register ulg c;
|
1576 |
|
|
|
1577 |
|
|
static ulg crc = (ulg)0xffffffffL;
|
1578 |
|
|
|
1579 |
|
|
2 -> if (s == NULL) @{
|
1580 |
|
|
1 -> c = 0xffffffffL;
|
1581 |
|
|
1 -> @} else @{
|
1582 |
|
|
1 -> c = crc;
|
1583 |
|
|
1 -> if (n) do @{
|
1584 |
|
|
26312 -> c = crc_32_tab[...];
|
1585 |
|
|
26312,1,26311 -> @} while (--n);
|
1586 |
|
|
@}
|
1587 |
|
|
2 -> crc = c;
|
1588 |
|
|
2 -> return c ^ 0xffffffffL;
|
1589 |
|
|
2 ->@}
|
1590 |
|
|
@end smallexample
|
1591 |
|
|
|
1592 |
|
|
In this example, the function was called twice, passing once through
|
1593 |
|
|
each branch of the @code{if} statement. The body of the @code{do}
|
1594 |
|
|
loop was executed a total of 26312 times. Note how the @code{while}
|
1595 |
|
|
statement is annotated. It began execution 26312 times, once for
|
1596 |
|
|
each iteration through the loop. One of those times (the last time)
|
1597 |
|
|
it exited, while it branched back to the beginning of the loop 26311 times.
|
1598 |
|
|
|
1599 |
|
|
@node Inaccuracy
|
1600 |
|
|
@chapter Inaccuracy of @code{gprof} Output
|
1601 |
|
|
|
1602 |
|
|
@menu
|
1603 |
|
|
* Sampling Error:: Statistical margins of error
|
1604 |
|
|
* Assumptions:: Estimating children times
|
1605 |
|
|
@end menu
|
1606 |
|
|
|
1607 |
|
|
@node Sampling Error
|
1608 |
|
|
@section Statistical Sampling Error
|
1609 |
|
|
|
1610 |
|
|
The run-time figures that @code{gprof} gives you are based on a sampling
|
1611 |
|
|
process, so they are subject to statistical inaccuracy. If a function runs
|
1612 |
|
|
only a small amount of time, so that on the average the sampling process
|
1613 |
|
|
ought to catch that function in the act only once, there is a pretty good
|
1614 |
|
|
chance it will actually find that function zero times, or twice.
|
1615 |
|
|
|
1616 |
|
|
By contrast, the number-of-calls and basic-block figures
|
1617 |
|
|
are derived by counting, not
|
1618 |
|
|
sampling. They are completely accurate and will not vary from run to run
|
1619 |
|
|
if your program is deterministic.
|
1620 |
|
|
|
1621 |
|
|
The @dfn{sampling period} that is printed at the beginning of the flat
|
1622 |
|
|
profile says how often samples are taken. The rule of thumb is that a
|
1623 |
|
|
run-time figure is accurate if it is considerably bigger than the sampling
|
1624 |
|
|
period.
|
1625 |
|
|
|
1626 |
|
|
The actual amount of error can be predicted.
|
1627 |
|
|
For @var{n} samples, the @emph{expected} error
|
1628 |
|
|
is the square-root of @var{n}. For example,
|
1629 |
|
|
if the sampling period is 0.01 seconds and @code{foo}'s run-time is 1 second,
|
1630 |
|
|
@var{n} is 100 samples (1 second/0.01 seconds), sqrt(@var{n}) is 10 samples, so
|
1631 |
|
|
the expected error in @code{foo}'s run-time is 0.1 seconds (10*0.01 seconds),
|
1632 |
|
|
or ten percent of the observed value.
|
1633 |
|
|
Again, if the sampling period is 0.01 seconds and @code{bar}'s run-time is
|
1634 |
|
|
100 seconds, @var{n} is 10000 samples, sqrt(@var{n}) is 100 samples, so
|
1635 |
|
|
the expected error in @code{bar}'s run-time is 1 second,
|
1636 |
|
|
or one percent of the observed value.
|
1637 |
|
|
It is likely to
|
1638 |
|
|
vary this much @emph{on the average} from one profiling run to the next.
|
1639 |
|
|
(@emph{Sometimes} it will vary more.)
|
1640 |
|
|
|
1641 |
|
|
This does not mean that a small run-time figure is devoid of information.
|
1642 |
|
|
If the program's @emph{total} run-time is large, a small run-time for one
|
1643 |
|
|
function does tell you that that function used an insignificant fraction of
|
1644 |
|
|
the whole program's time. Usually this means it is not worth optimizing.
|
1645 |
|
|
|
1646 |
|
|
One way to get more accuracy is to give your program more (but similar)
|
1647 |
|
|
input data so it will take longer. Another way is to combine the data from
|
1648 |
|
|
several runs, using the @samp{-s} option of @code{gprof}. Here is how:
|
1649 |
|
|
|
1650 |
|
|
@enumerate
|
1651 |
|
|
@item
|
1652 |
|
|
Run your program once.
|
1653 |
|
|
|
1654 |
|
|
@item
|
1655 |
|
|
Issue the command @samp{mv gmon.out gmon.sum}.
|
1656 |
|
|
|
1657 |
|
|
@item
|
1658 |
|
|
Run your program again, the same as before.
|
1659 |
|
|
|
1660 |
|
|
@item
|
1661 |
|
|
Merge the new data in @file{gmon.out} into @file{gmon.sum} with this command:
|
1662 |
|
|
|
1663 |
|
|
@example
|
1664 |
|
|
gprof -s @var{executable-file} gmon.out gmon.sum
|
1665 |
|
|
@end example
|
1666 |
|
|
|
1667 |
|
|
@item
|
1668 |
|
|
Repeat the last two steps as often as you wish.
|
1669 |
|
|
|
1670 |
|
|
@item
|
1671 |
|
|
Analyze the cumulative data using this command:
|
1672 |
|
|
|
1673 |
|
|
@example
|
1674 |
|
|
gprof @var{executable-file} gmon.sum > @var{output-file}
|
1675 |
|
|
@end example
|
1676 |
|
|
@end enumerate
|
1677 |
|
|
|
1678 |
|
|
@node Assumptions
|
1679 |
|
|
@section Estimating @code{children} Times
|
1680 |
|
|
|
1681 |
|
|
Some of the figures in the call graph are estimates---for example, the
|
1682 |
|
|
@code{children} time values and all the time figures in caller and
|
1683 |
|
|
subroutine lines.
|
1684 |
|
|
|
1685 |
|
|
There is no direct information about these measurements in the profile
|
1686 |
|
|
data itself. Instead, @code{gprof} estimates them by making an assumption
|
1687 |
|
|
about your program that might or might not be true.
|
1688 |
|
|
|
1689 |
|
|
The assumption made is that the average time spent in each call to any
|
1690 |
|
|
function @code{foo} is not correlated with who called @code{foo}. If
|
1691 |
|
|
@code{foo} used 5 seconds in all, and 2/5 of the calls to @code{foo} came
|
1692 |
|
|
from @code{a}, then @code{foo} contributes 2 seconds to @code{a}'s
|
1693 |
|
|
@code{children} time, by assumption.
|
1694 |
|
|
|
1695 |
|
|
This assumption is usually true enough, but for some programs it is far
|
1696 |
|
|
from true. Suppose that @code{foo} returns very quickly when its argument
|
1697 |
|
|
is zero; suppose that @code{a} always passes zero as an argument, while
|
1698 |
|
|
other callers of @code{foo} pass other arguments. In this program, all the
|
1699 |
|
|
time spent in @code{foo} is in the calls from callers other than @code{a}.
|
1700 |
|
|
But @code{gprof} has no way of knowing this; it will blindly and
|
1701 |
|
|
incorrectly charge 2 seconds of time in @code{foo} to the children of
|
1702 |
|
|
@code{a}.
|
1703 |
|
|
|
1704 |
|
|
@c FIXME - has this been fixed?
|
1705 |
|
|
We hope some day to put more complete data into @file{gmon.out}, so that
|
1706 |
|
|
this assumption is no longer needed, if we can figure out how. For the
|
1707 |
|
|
novice, the estimated figures are usually more useful than misleading.
|
1708 |
|
|
|
1709 |
|
|
@node How do I?
|
1710 |
|
|
@chapter Answers to Common Questions
|
1711 |
|
|
|
1712 |
|
|
@table @asis
|
1713 |
|
|
@item How can I get more exact information about hot spots in my program?
|
1714 |
|
|
|
1715 |
|
|
Looking at the per-line call counts only tells part of the story.
|
1716 |
|
|
Because @code{gprof} can only report call times and counts by function,
|
1717 |
|
|
the best way to get finer-grained information on where the program
|
1718 |
|
|
is spending its time is to re-factor large functions into sequences
|
1719 |
|
|
of calls to smaller ones. Beware however that this can introduce
|
1720 |
|
|
artificial hot spots since compiling with @samp{-pg} adds a significant
|
1721 |
|
|
overhead to function calls. An alternative solution is to use a
|
1722 |
|
|
non-intrusive profiler, e.g.@: oprofile.
|
1723 |
|
|
|
1724 |
|
|
@item How do I find which lines in my program were executed the most times?
|
1725 |
|
|
|
1726 |
|
|
Use the @code{gcov} program.
|
1727 |
|
|
|
1728 |
|
|
@item How do I find which lines in my program called a particular function?
|
1729 |
|
|
|
1730 |
|
|
Use @samp{gprof -l} and lookup the function in the call graph.
|
1731 |
|
|
The callers will be broken down by function and line number.
|
1732 |
|
|
|
1733 |
|
|
@item How do I analyze a program that runs for less than a second?
|
1734 |
|
|
|
1735 |
|
|
Try using a shell script like this one:
|
1736 |
|
|
|
1737 |
|
|
@example
|
1738 |
|
|
for i in `seq 1 100`; do
|
1739 |
|
|
fastprog
|
1740 |
|
|
mv gmon.out gmon.out.$i
|
1741 |
|
|
done
|
1742 |
|
|
|
1743 |
|
|
gprof -s fastprog gmon.out.*
|
1744 |
|
|
|
1745 |
|
|
gprof fastprog gmon.sum
|
1746 |
|
|
@end example
|
1747 |
|
|
|
1748 |
|
|
If your program is completely deterministic, all the call counts
|
1749 |
|
|
will be simple multiples of 100 (i.e., a function called once in
|
1750 |
|
|
each run will appear with a call count of 100).
|
1751 |
|
|
|
1752 |
|
|
@end table
|
1753 |
|
|
|
1754 |
|
|
@node Incompatibilities
|
1755 |
|
|
@chapter Incompatibilities with Unix @code{gprof}
|
1756 |
|
|
|
1757 |
|
|
@sc{gnu} @code{gprof} and Berkeley Unix @code{gprof} use the same data
|
1758 |
|
|
file @file{gmon.out}, and provide essentially the same information. But
|
1759 |
|
|
there are a few differences.
|
1760 |
|
|
|
1761 |
|
|
@itemize @bullet
|
1762 |
|
|
@item
|
1763 |
|
|
@sc{gnu} @code{gprof} uses a new, generalized file format with support
|
1764 |
|
|
for basic-block execution counts and non-realtime histograms. A magic
|
1765 |
|
|
cookie and version number allows @code{gprof} to easily identify
|
1766 |
|
|
new style files. Old BSD-style files can still be read.
|
1767 |
|
|
@xref{File Format, ,Profiling Data File Format}.
|
1768 |
|
|
|
1769 |
|
|
@item
|
1770 |
|
|
For a recursive function, Unix @code{gprof} lists the function as a
|
1771 |
|
|
parent and as a child, with a @code{calls} field that lists the number
|
1772 |
|
|
of recursive calls. @sc{gnu} @code{gprof} omits these lines and puts
|
1773 |
|
|
the number of recursive calls in the primary line.
|
1774 |
|
|
|
1775 |
|
|
@item
|
1776 |
|
|
When a function is suppressed from the call graph with @samp{-e}, @sc{gnu}
|
1777 |
|
|
@code{gprof} still lists it as a subroutine of functions that call it.
|
1778 |
|
|
|
1779 |
|
|
@item
|
1780 |
|
|
@sc{gnu} @code{gprof} accepts the @samp{-k} with its argument
|
1781 |
|
|
in the form @samp{from/to}, instead of @samp{from to}.
|
1782 |
|
|
|
1783 |
|
|
@item
|
1784 |
|
|
In the annotated source listing,
|
1785 |
|
|
if there are multiple basic blocks on the same line,
|
1786 |
|
|
@sc{gnu} @code{gprof} prints all of their counts, separated by commas.
|
1787 |
|
|
|
1788 |
|
|
@ignore - it does this now
|
1789 |
|
|
@item
|
1790 |
|
|
The function names printed in @sc{gnu} @code{gprof} output do not include
|
1791 |
|
|
the leading underscores that are added internally to the front of all
|
1792 |
|
|
C identifiers on many operating systems.
|
1793 |
|
|
@end ignore
|
1794 |
|
|
|
1795 |
|
|
@item
|
1796 |
|
|
The blurbs, field widths, and output formats are different. @sc{gnu}
|
1797 |
|
|
@code{gprof} prints blurbs after the tables, so that you can see the
|
1798 |
|
|
tables without skipping the blurbs.
|
1799 |
|
|
@end itemize
|
1800 |
|
|
|
1801 |
|
|
@node Details
|
1802 |
|
|
@chapter Details of Profiling
|
1803 |
|
|
|
1804 |
|
|
@menu
|
1805 |
|
|
* Implementation:: How a program collects profiling information
|
1806 |
|
|
* File Format:: Format of @samp{gmon.out} files
|
1807 |
|
|
* Internals:: @code{gprof}'s internal operation
|
1808 |
|
|
* Debugging:: Using @code{gprof}'s @samp{-d} option
|
1809 |
|
|
@end menu
|
1810 |
|
|
|
1811 |
|
|
@node Implementation
|
1812 |
|
|
@section Implementation of Profiling
|
1813 |
|
|
|
1814 |
|
|
Profiling works by changing how every function in your program is compiled
|
1815 |
|
|
so that when it is called, it will stash away some information about where
|
1816 |
|
|
it was called from. From this, the profiler can figure out what function
|
1817 |
|
|
called it, and can count how many times it was called. This change is made
|
1818 |
|
|
by the compiler when your program is compiled with the @samp{-pg} option,
|
1819 |
|
|
which causes every function to call @code{mcount}
|
1820 |
|
|
(or @code{_mcount}, or @code{__mcount}, depending on the OS and compiler)
|
1821 |
|
|
as one of its first operations.
|
1822 |
|
|
|
1823 |
|
|
The @code{mcount} routine, included in the profiling library,
|
1824 |
|
|
is responsible for recording in an in-memory call graph table
|
1825 |
|
|
both its parent routine (the child) and its parent's parent. This is
|
1826 |
|
|
typically done by examining the stack frame to find both
|
1827 |
|
|
the address of the child, and the return address in the original parent.
|
1828 |
|
|
Since this is a very machine-dependent operation, @code{mcount}
|
1829 |
|
|
itself is typically a short assembly-language stub routine
|
1830 |
|
|
that extracts the required
|
1831 |
|
|
information, and then calls @code{__mcount_internal}
|
1832 |
|
|
(a normal C function) with two arguments---@code{frompc} and @code{selfpc}.
|
1833 |
|
|
@code{__mcount_internal} is responsible for maintaining
|
1834 |
|
|
the in-memory call graph, which records @code{frompc}, @code{selfpc},
|
1835 |
|
|
and the number of times each of these call arcs was traversed.
|
1836 |
|
|
|
1837 |
|
|
GCC Version 2 provides a magical function (@code{__builtin_return_address}),
|
1838 |
|
|
which allows a generic @code{mcount} function to extract the
|
1839 |
|
|
required information from the stack frame. However, on some
|
1840 |
|
|
architectures, most notably the SPARC, using this builtin can be
|
1841 |
|
|
very computationally expensive, and an assembly language version
|
1842 |
|
|
of @code{mcount} is used for performance reasons.
|
1843 |
|
|
|
1844 |
|
|
Number-of-calls information for library routines is collected by using a
|
1845 |
|
|
special version of the C library. The programs in it are the same as in
|
1846 |
|
|
the usual C library, but they were compiled with @samp{-pg}. If you
|
1847 |
|
|
link your program with @samp{gcc @dots{} -pg}, it automatically uses the
|
1848 |
|
|
profiling version of the library.
|
1849 |
|
|
|
1850 |
|
|
Profiling also involves watching your program as it runs, and keeping a
|
1851 |
|
|
histogram of where the program counter happens to be every now and then.
|
1852 |
|
|
Typically the program counter is looked at around 100 times per second of
|
1853 |
|
|
run time, but the exact frequency may vary from system to system.
|
1854 |
|
|
|
1855 |
|
|
This is done is one of two ways. Most UNIX-like operating systems
|
1856 |
|
|
provide a @code{profil()} system call, which registers a memory
|
1857 |
|
|
array with the kernel, along with a scale
|
1858 |
|
|
factor that determines how the program's address space maps
|
1859 |
|
|
into the array.
|
1860 |
|
|
Typical scaling values cause every 2 to 8 bytes of address space
|
1861 |
|
|
to map into a single array slot.
|
1862 |
|
|
On every tick of the system clock
|
1863 |
|
|
(assuming the profiled program is running), the value of the
|
1864 |
|
|
program counter is examined and the corresponding slot in
|
1865 |
|
|
the memory array is incremented. Since this is done in the kernel,
|
1866 |
|
|
which had to interrupt the process anyway to handle the clock
|
1867 |
|
|
interrupt, very little additional system overhead is required.
|
1868 |
|
|
|
1869 |
|
|
However, some operating systems, most notably Linux 2.0 (and earlier),
|
1870 |
|
|
do not provide a @code{profil()} system call. On such a system,
|
1871 |
|
|
arrangements are made for the kernel to periodically deliver
|
1872 |
|
|
a signal to the process (typically via @code{setitimer()}),
|
1873 |
|
|
which then performs the same operation of examining the
|
1874 |
|
|
program counter and incrementing a slot in the memory array.
|
1875 |
|
|
Since this method requires a signal to be delivered to
|
1876 |
|
|
user space every time a sample is taken, it uses considerably
|
1877 |
|
|
more overhead than kernel-based profiling. Also, due to the
|
1878 |
|
|
added delay required to deliver the signal, this method is
|
1879 |
|
|
less accurate as well.
|
1880 |
|
|
|
1881 |
|
|
A special startup routine allocates memory for the histogram and
|
1882 |
|
|
either calls @code{profil()} or sets up
|
1883 |
|
|
a clock signal handler.
|
1884 |
|
|
This routine (@code{monstartup}) can be invoked in several ways.
|
1885 |
|
|
On Linux systems, a special profiling startup file @code{gcrt0.o},
|
1886 |
|
|
which invokes @code{monstartup} before @code{main},
|
1887 |
|
|
is used instead of the default @code{crt0.o}.
|
1888 |
|
|
Use of this special startup file is one of the effects
|
1889 |
|
|
of using @samp{gcc @dots{} -pg} to link.
|
1890 |
|
|
On SPARC systems, no special startup files are used.
|
1891 |
|
|
Rather, the @code{mcount} routine, when it is invoked for
|
1892 |
|
|
the first time (typically when @code{main} is called),
|
1893 |
|
|
calls @code{monstartup}.
|
1894 |
|
|
|
1895 |
|
|
If the compiler's @samp{-a} option was used, basic-block counting
|
1896 |
|
|
is also enabled. Each object file is then compiled with a static array
|
1897 |
|
|
of counts, initially zero.
|
1898 |
|
|
In the executable code, every time a new basic-block begins
|
1899 |
|
|
(i.e., when an @code{if} statement appears), an extra instruction
|
1900 |
|
|
is inserted to increment the corresponding count in the array.
|
1901 |
|
|
At compile time, a paired array was constructed that recorded
|
1902 |
|
|
the starting address of each basic-block. Taken together,
|
1903 |
|
|
the two arrays record the starting address of every basic-block,
|
1904 |
|
|
along with the number of times it was executed.
|
1905 |
|
|
|
1906 |
|
|
The profiling library also includes a function (@code{mcleanup}) which is
|
1907 |
|
|
typically registered using @code{atexit()} to be called as the
|
1908 |
|
|
program exits, and is responsible for writing the file @file{gmon.out}.
|
1909 |
|
|
Profiling is turned off, various headers are output, and the histogram
|
1910 |
|
|
is written, followed by the call-graph arcs and the basic-block counts.
|
1911 |
|
|
|
1912 |
|
|
The output from @code{gprof} gives no indication of parts of your program that
|
1913 |
|
|
are limited by I/O or swapping bandwidth. This is because samples of the
|
1914 |
|
|
program counter are taken at fixed intervals of the program's run time.
|
1915 |
|
|
Therefore, the
|
1916 |
|
|
time measurements in @code{gprof} output say nothing about time that your
|
1917 |
|
|
program was not running. For example, a part of the program that creates
|
1918 |
|
|
so much data that it cannot all fit in physical memory at once may run very
|
1919 |
|
|
slowly due to thrashing, but @code{gprof} will say it uses little time. On
|
1920 |
|
|
the other hand, sampling by run time has the advantage that the amount of
|
1921 |
|
|
load due to other users won't directly affect the output you get.
|
1922 |
|
|
|
1923 |
|
|
@node File Format
|
1924 |
|
|
@section Profiling Data File Format
|
1925 |
|
|
|
1926 |
|
|
The old BSD-derived file format used for profile data does not contain a
|
1927 |
|
|
magic cookie that allows to check whether a data file really is a
|
1928 |
|
|
@code{gprof} file. Furthermore, it does not provide a version number, thus
|
1929 |
|
|
rendering changes to the file format almost impossible. @sc{gnu} @code{gprof}
|
1930 |
|
|
uses a new file format that provides these features. For backward
|
1931 |
|
|
compatibility, @sc{gnu} @code{gprof} continues to support the old BSD-derived
|
1932 |
|
|
format, but not all features are supported with it. For example,
|
1933 |
|
|
basic-block execution counts cannot be accommodated by the old file
|
1934 |
|
|
format.
|
1935 |
|
|
|
1936 |
|
|
The new file format is defined in header file @file{gmon_out.h}. It
|
1937 |
|
|
consists of a header containing the magic cookie and a version number,
|
1938 |
|
|
as well as some spare bytes available for future extensions. All data
|
1939 |
|
|
in a profile data file is in the native format of the target for which
|
1940 |
|
|
the profile was collected. @sc{gnu} @code{gprof} adapts automatically
|
1941 |
|
|
to the byte-order in use.
|
1942 |
|
|
|
1943 |
|
|
In the new file format, the header is followed by a sequence of
|
1944 |
|
|
records. Currently, there are three different record types: histogram
|
1945 |
|
|
records, call-graph arc records, and basic-block execution count
|
1946 |
|
|
records. Each file can contain any number of each record type. When
|
1947 |
|
|
reading a file, @sc{gnu} @code{gprof} will ensure records of the same type are
|
1948 |
|
|
compatible with each other and compute the union of all records. For
|
1949 |
|
|
example, for basic-block execution counts, the union is simply the sum
|
1950 |
|
|
of all execution counts for each basic-block.
|
1951 |
|
|
|
1952 |
|
|
@subsection Histogram Records
|
1953 |
|
|
|
1954 |
|
|
Histogram records consist of a header that is followed by an array of
|
1955 |
|
|
bins. The header contains the text-segment range that the histogram
|
1956 |
|
|
spans, the size of the histogram in bytes (unlike in the old BSD
|
1957 |
|
|
format, this does not include the size of the header), the rate of the
|
1958 |
|
|
profiling clock, and the physical dimension that the bin counts
|
1959 |
|
|
represent after being scaled by the profiling clock rate. The
|
1960 |
|
|
physical dimension is specified in two parts: a long name of up to 15
|
1961 |
|
|
characters and a single character abbreviation. For example, a
|
1962 |
|
|
histogram representing real-time would specify the long name as
|
1963 |
|
|
``seconds'' and the abbreviation as ``s''. This feature is useful for
|
1964 |
|
|
architectures that support performance monitor hardware (which,
|
1965 |
|
|
fortunately, is becoming increasingly common). For example, under DEC
|
1966 |
|
|
OSF/1, the ``uprofile'' command can be used to produce a histogram of,
|
1967 |
|
|
say, instruction cache misses. In this case, the dimension in the
|
1968 |
|
|
histogram header could be set to ``i-cache misses'' and the abbreviation
|
1969 |
|
|
could be set to ``1'' (because it is simply a count, not a physical
|
1970 |
|
|
dimension). Also, the profiling rate would have to be set to 1 in
|
1971 |
|
|
this case.
|
1972 |
|
|
|
1973 |
|
|
Histogram bins are 16-bit numbers and each bin represent an equal
|
1974 |
|
|
amount of text-space. For example, if the text-segment is one
|
1975 |
|
|
thousand bytes long and if there are ten bins in the histogram, each
|
1976 |
|
|
bin represents one hundred bytes.
|
1977 |
|
|
|
1978 |
|
|
|
1979 |
|
|
@subsection Call-Graph Records
|
1980 |
|
|
|
1981 |
|
|
Call-graph records have a format that is identical to the one used in
|
1982 |
|
|
the BSD-derived file format. It consists of an arc in the call graph
|
1983 |
|
|
and a count indicating the number of times the arc was traversed
|
1984 |
|
|
during program execution. Arcs are specified by a pair of addresses:
|
1985 |
|
|
the first must be within caller's function and the second must be
|
1986 |
|
|
within the callee's function. When performing profiling at the
|
1987 |
|
|
function level, these addresses can point anywhere within the
|
1988 |
|
|
respective function. However, when profiling at the line-level, it is
|
1989 |
|
|
better if the addresses are as close to the call-site/entry-point as
|
1990 |
|
|
possible. This will ensure that the line-level call-graph is able to
|
1991 |
|
|
identify exactly which line of source code performed calls to a
|
1992 |
|
|
function.
|
1993 |
|
|
|
1994 |
|
|
@subsection Basic-Block Execution Count Records
|
1995 |
|
|
|
1996 |
|
|
Basic-block execution count records consist of a header followed by a
|
1997 |
|
|
sequence of address/count pairs. The header simply specifies the
|
1998 |
|
|
length of the sequence. In an address/count pair, the address
|
1999 |
|
|
identifies a basic-block and the count specifies the number of times
|
2000 |
|
|
that basic-block was executed. Any address within the basic-address can
|
2001 |
|
|
be used.
|
2002 |
|
|
|
2003 |
|
|
@node Internals
|
2004 |
|
|
@section @code{gprof}'s Internal Operation
|
2005 |
|
|
|
2006 |
|
|
Like most programs, @code{gprof} begins by processing its options.
|
2007 |
|
|
During this stage, it may building its symspec list
|
2008 |
|
|
(@code{sym_ids.c:@-sym_id_add}), if
|
2009 |
|
|
options are specified which use symspecs.
|
2010 |
|
|
@code{gprof} maintains a single linked list of symspecs,
|
2011 |
|
|
which will eventually get turned into 12 symbol tables,
|
2012 |
|
|
organized into six include/exclude pairs---one
|
2013 |
|
|
pair each for the flat profile (INCL_FLAT/EXCL_FLAT),
|
2014 |
|
|
the call graph arcs (INCL_ARCS/EXCL_ARCS),
|
2015 |
|
|
printing in the call graph (INCL_GRAPH/EXCL_GRAPH),
|
2016 |
|
|
timing propagation in the call graph (INCL_TIME/EXCL_TIME),
|
2017 |
|
|
the annotated source listing (INCL_ANNO/EXCL_ANNO),
|
2018 |
|
|
and the execution count listing (INCL_EXEC/EXCL_EXEC).
|
2019 |
|
|
|
2020 |
|
|
After option processing, @code{gprof} finishes
|
2021 |
|
|
building the symspec list by adding all the symspecs in
|
2022 |
|
|
@code{default_excluded_list} to the exclude lists
|
2023 |
|
|
EXCL_TIME and EXCL_GRAPH, and if line-by-line profiling is specified,
|
2024 |
|
|
EXCL_FLAT as well.
|
2025 |
|
|
These default excludes are not added to EXCL_ANNO, EXCL_ARCS, and EXCL_EXEC.
|
2026 |
|
|
|
2027 |
|
|
Next, the BFD library is called to open the object file,
|
2028 |
|
|
verify that it is an object file,
|
2029 |
|
|
and read its symbol table (@code{core.c:@-core_init}),
|
2030 |
|
|
using @code{bfd_canonicalize_symtab} after mallocing
|
2031 |
|
|
an appropriately sized array of symbols. At this point,
|
2032 |
|
|
function mappings are read (if the @samp{--file-ordering} option
|
2033 |
|
|
has been specified), and the core text space is read into
|
2034 |
|
|
memory (if the @samp{-c} option was given).
|
2035 |
|
|
|
2036 |
|
|
@code{gprof}'s own symbol table, an array of Sym structures,
|
2037 |
|
|
is now built.
|
2038 |
|
|
This is done in one of two ways, by one of two routines, depending
|
2039 |
|
|
on whether line-by-line profiling (@samp{-l} option) has been
|
2040 |
|
|
enabled.
|
2041 |
|
|
For normal profiling, the BFD canonical symbol table is scanned.
|
2042 |
|
|
For line-by-line profiling, every
|
2043 |
|
|
text space address is examined, and a new symbol table entry
|
2044 |
|
|
gets created every time the line number changes.
|
2045 |
|
|
In either case, two passes are made through the symbol
|
2046 |
|
|
table---one to count the size of the symbol table required,
|
2047 |
|
|
and the other to actually read the symbols. In between the
|
2048 |
|
|
two passes, a single array of type @code{Sym} is created of
|
2049 |
|
|
the appropriate length.
|
2050 |
|
|
Finally, @code{symtab.c:@-symtab_finalize}
|
2051 |
|
|
is called to sort the symbol table and remove duplicate entries
|
2052 |
|
|
(entries with the same memory address).
|
2053 |
|
|
|
2054 |
|
|
The symbol table must be a contiguous array for two reasons.
|
2055 |
|
|
First, the @code{qsort} library function (which sorts an array)
|
2056 |
|
|
will be used to sort the symbol table.
|
2057 |
|
|
Also, the symbol lookup routine (@code{symtab.c:@-sym_lookup}),
|
2058 |
|
|
which finds symbols
|
2059 |
|
|
based on memory address, uses a binary search algorithm
|
2060 |
|
|
which requires the symbol table to be a sorted array.
|
2061 |
|
|
Function symbols are indicated with an @code{is_func} flag.
|
2062 |
|
|
Line number symbols have no special flags set.
|
2063 |
|
|
Additionally, a symbol can have an @code{is_static} flag
|
2064 |
|
|
to indicate that it is a local symbol.
|
2065 |
|
|
|
2066 |
|
|
With the symbol table read, the symspecs can now be translated
|
2067 |
|
|
into Syms (@code{sym_ids.c:@-sym_id_parse}). Remember that a single
|
2068 |
|
|
symspec can match multiple symbols.
|
2069 |
|
|
An array of symbol tables
|
2070 |
|
|
(@code{syms}) is created, each entry of which is a symbol table
|
2071 |
|
|
of Syms to be included or excluded from a particular listing.
|
2072 |
|
|
The master symbol table and the symspecs are examined by nested
|
2073 |
|
|
loops, and every symbol that matches a symspec is inserted
|
2074 |
|
|
into the appropriate syms table. This is done twice, once to
|
2075 |
|
|
count the size of each required symbol table, and again to build
|
2076 |
|
|
the tables, which have been malloced between passes.
|
2077 |
|
|
From now on, to determine whether a symbol is on an include
|
2078 |
|
|
or exclude symspec list, @code{gprof} simply uses its
|
2079 |
|
|
standard symbol lookup routine on the appropriate table
|
2080 |
|
|
in the @code{syms} array.
|
2081 |
|
|
|
2082 |
|
|
Now the profile data file(s) themselves are read
|
2083 |
|
|
(@code{gmon_io.c:@-gmon_out_read}),
|
2084 |
|
|
first by checking for a new-style @samp{gmon.out} header,
|
2085 |
|
|
then assuming this is an old-style BSD @samp{gmon.out}
|
2086 |
|
|
if the magic number test failed.
|
2087 |
|
|
|
2088 |
|
|
New-style histogram records are read by @code{hist.c:@-hist_read_rec}.
|
2089 |
|
|
For the first histogram record, allocate a memory array to hold
|
2090 |
|
|
all the bins, and read them in.
|
2091 |
|
|
When multiple profile data files (or files with multiple histogram
|
2092 |
|
|
records) are read, the memory ranges of each pair of histogram records
|
2093 |
|
|
must be either equal, or non-overlapping. For each pair of histogram
|
2094 |
|
|
records, the resolution (memory region size divided by the number of
|
2095 |
|
|
bins) must be the same. The time unit must be the same for all
|
2096 |
|
|
histogram records. If the above containts are met, all histograms
|
2097 |
|
|
for the same memory range are merged.
|
2098 |
|
|
|
2099 |
|
|
As each call graph record is read (@code{call_graph.c:@-cg_read_rec}),
|
2100 |
|
|
the parent and child addresses
|
2101 |
|
|
are matched to symbol table entries, and a call graph arc is
|
2102 |
|
|
created by @code{cg_arcs.c:@-arc_add}, unless the arc fails a symspec
|
2103 |
|
|
check against INCL_ARCS/EXCL_ARCS. As each arc is added,
|
2104 |
|
|
a linked list is maintained of the parent's child arcs, and of the child's
|
2105 |
|
|
parent arcs.
|
2106 |
|
|
Both the child's call count and the arc's call count are
|
2107 |
|
|
incremented by the record's call count.
|
2108 |
|
|
|
2109 |
|
|
Basic-block records are read (@code{basic_blocks.c:@-bb_read_rec}),
|
2110 |
|
|
but only if line-by-line profiling has been selected.
|
2111 |
|
|
Each basic-block address is matched to a corresponding line
|
2112 |
|
|
symbol in the symbol table, and an entry made in the symbol's
|
2113 |
|
|
bb_addr and bb_calls arrays. Again, if multiple basic-block
|
2114 |
|
|
records are present for the same address, the call counts
|
2115 |
|
|
are cumulative.
|
2116 |
|
|
|
2117 |
|
|
A gmon.sum file is dumped, if requested (@code{gmon_io.c:@-gmon_out_write}).
|
2118 |
|
|
|
2119 |
|
|
If histograms were present in the data files, assign them to symbols
|
2120 |
|
|
(@code{hist.c:@-hist_assign_samples}) by iterating over all the sample
|
2121 |
|
|
bins and assigning them to symbols. Since the symbol table
|
2122 |
|
|
is sorted in order of ascending memory addresses, we can
|
2123 |
|
|
simple follow along in the symbol table as we make our pass
|
2124 |
|
|
over the sample bins.
|
2125 |
|
|
This step includes a symspec check against INCL_FLAT/EXCL_FLAT.
|
2126 |
|
|
Depending on the histogram
|
2127 |
|
|
scale factor, a sample bin may span multiple symbols,
|
2128 |
|
|
in which case a fraction of the sample count is allocated
|
2129 |
|
|
to each symbol, proportional to the degree of overlap.
|
2130 |
|
|
This effect is rare for normal profiling, but overlaps
|
2131 |
|
|
are more common during line-by-line profiling, and can
|
2132 |
|
|
cause each of two adjacent lines to be credited with half
|
2133 |
|
|
a hit, for example.
|
2134 |
|
|
|
2135 |
|
|
If call graph data is present, @code{cg_arcs.c:@-cg_assemble} is called.
|
2136 |
|
|
First, if @samp{-c} was specified, a machine-dependent
|
2137 |
|
|
routine (@code{find_call}) scans through each symbol's machine code,
|
2138 |
|
|
looking for subroutine call instructions, and adding them
|
2139 |
|
|
to the call graph with a zero call count.
|
2140 |
|
|
A topological sort is performed by depth-first numbering
|
2141 |
|
|
all the symbols (@code{cg_dfn.c:@-cg_dfn}), so that
|
2142 |
|
|
children are always numbered less than their parents,
|
2143 |
|
|
then making a array of pointers into the symbol table and sorting it into
|
2144 |
|
|
numerical order, which is reverse topological
|
2145 |
|
|
order (children appear before parents).
|
2146 |
|
|
Cycles are also detected at this point, all members
|
2147 |
|
|
of which are assigned the same topological number.
|
2148 |
|
|
Two passes are now made through this sorted array of symbol pointers.
|
2149 |
|
|
The first pass, from end to beginning (parents to children),
|
2150 |
|
|
computes the fraction of child time to propagate to each parent
|
2151 |
|
|
and a print flag.
|
2152 |
|
|
The print flag reflects symspec handling of INCL_GRAPH/EXCL_GRAPH,
|
2153 |
|
|
with a parent's include or exclude (print or no print) property
|
2154 |
|
|
being propagated to its children, unless they themselves explicitly appear
|
2155 |
|
|
in INCL_GRAPH or EXCL_GRAPH.
|
2156 |
|
|
A second pass, from beginning to end (children to parents) actually
|
2157 |
|
|
propagates the timings along the call graph, subject
|
2158 |
|
|
to a check against INCL_TIME/EXCL_TIME.
|
2159 |
|
|
With the print flag, fractions, and timings now stored in the symbol
|
2160 |
|
|
structures, the topological sort array is now discarded, and a
|
2161 |
|
|
new array of pointers is assembled, this time sorted by propagated time.
|
2162 |
|
|
|
2163 |
|
|
Finally, print the various outputs the user requested, which is now fairly
|
2164 |
|
|
straightforward. The call graph (@code{cg_print.c:@-cg_print}) and
|
2165 |
|
|
flat profile (@code{hist.c:@-hist_print}) are regurgitations of values
|
2166 |
|
|
already computed. The annotated source listing
|
2167 |
|
|
(@code{basic_blocks.c:@-print_annotated_source}) uses basic-block
|
2168 |
|
|
information, if present, to label each line of code with call counts,
|
2169 |
|
|
otherwise only the function call counts are presented.
|
2170 |
|
|
|
2171 |
|
|
The function ordering code is marginally well documented
|
2172 |
|
|
in the source code itself (@code{cg_print.c}). Basically,
|
2173 |
|
|
the functions with the most use and the most parents are
|
2174 |
|
|
placed first, followed by other functions with the most use,
|
2175 |
|
|
followed by lower use functions, followed by unused functions
|
2176 |
|
|
at the end.
|
2177 |
|
|
|
2178 |
|
|
@node Debugging
|
2179 |
|
|
@section Debugging @code{gprof}
|
2180 |
|
|
|
2181 |
|
|
If @code{gprof} was compiled with debugging enabled,
|
2182 |
|
|
the @samp{-d} option triggers debugging output
|
2183 |
|
|
(to stdout) which can be helpful in understanding its operation.
|
2184 |
|
|
The debugging number specified is interpreted as a sum of the following
|
2185 |
|
|
options:
|
2186 |
|
|
|
2187 |
|
|
@table @asis
|
2188 |
|
|
@item 2 - Topological sort
|
2189 |
|
|
Monitor depth-first numbering of symbols during call graph analysis
|
2190 |
|
|
@item 4 - Cycles
|
2191 |
|
|
Shows symbols as they are identified as cycle heads
|
2192 |
|
|
@item 16 - Tallying
|
2193 |
|
|
As the call graph arcs are read, show each arc and how
|
2194 |
|
|
the total calls to each function are tallied
|
2195 |
|
|
@item 32 - Call graph arc sorting
|
2196 |
|
|
Details sorting individual parents/children within each call graph entry
|
2197 |
|
|
@item 64 - Reading histogram and call graph records
|
2198 |
|
|
Shows address ranges of histograms as they are read, and each
|
2199 |
|
|
call graph arc
|
2200 |
|
|
@item 128 - Symbol table
|
2201 |
|
|
Reading, classifying, and sorting the symbol table from the object file.
|
2202 |
|
|
For line-by-line profiling (@samp{-l} option), also shows line numbers
|
2203 |
|
|
being assigned to memory addresses.
|
2204 |
|
|
@item 256 - Static call graph
|
2205 |
|
|
Trace operation of @samp{-c} option
|
2206 |
|
|
@item 512 - Symbol table and arc table lookups
|
2207 |
|
|
Detail operation of lookup routines
|
2208 |
|
|
@item 1024 - Call graph propagation
|
2209 |
|
|
Shows how function times are propagated along the call graph
|
2210 |
|
|
@item 2048 - Basic-blocks
|
2211 |
|
|
Shows basic-block records as they are read from profile data
|
2212 |
|
|
(only meaningful with @samp{-l} option)
|
2213 |
|
|
@item 4096 - Symspecs
|
2214 |
|
|
Shows symspec-to-symbol pattern matching operation
|
2215 |
|
|
@item 8192 - Annotate source
|
2216 |
|
|
Tracks operation of @samp{-A} option
|
2217 |
|
|
@end table
|
2218 |
|
|
|
2219 |
|
|
@node GNU Free Documentation License
|
2220 |
|
|
@appendix GNU Free Documentation License
|
2221 |
|
|
@include fdl.texi
|
2222 |
|
|
|
2223 |
|
|
@bye
|
2224 |
|
|
|
2225 |
|
|
NEEDS AN INDEX
|
2226 |
|
|
|
2227 |
|
|
-T - "traditional BSD style": How is it different? Should the
|
2228 |
|
|
differences be documented?
|
2229 |
|
|
|
2230 |
|
|
example flat file adds up to 100.01%...
|
2231 |
|
|
|
2232 |
|
|
note: time estimates now only go out to one decimal place (0.0), where
|
2233 |
|
|
they used to extend two (78.67).
|