1 | This is gprof.info, produced by makeinfo version 4.3 from gprof.texi.
|
---|
2 |
|
---|
3 | START-INFO-DIR-ENTRY
|
---|
4 | * gprof: (gprof). Profiling your program's execution
|
---|
5 | END-INFO-DIR-ENTRY
|
---|
6 |
|
---|
7 | This file documents the gprof profiler of the GNU system.
|
---|
8 |
|
---|
9 | Copyright (C) 1988, 92, 97, 98, 99, 2000, 2001 Free Software
|
---|
10 | Foundation, Inc.
|
---|
11 |
|
---|
12 | Permission is granted to copy, distribute and/or modify this document
|
---|
13 | under the terms of the GNU Free Documentation License, Version 1.1 or
|
---|
14 | any later version published by the Free Software Foundation; with no
|
---|
15 | Invariant Sections, with no Front-Cover Texts, and with no Back-Cover
|
---|
16 | Texts. A copy of the license is included in the section entitled "GNU
|
---|
17 | Free Documentation License".
|
---|
18 |
|
---|
19 |
|
---|
20 | File: gprof.info, Node: Top, Next: Introduction, Up: (dir)
|
---|
21 |
|
---|
22 | Profiling a Program: Where Does It Spend Its Time?
|
---|
23 | **************************************************
|
---|
24 |
|
---|
25 | This manual describes the GNU profiler, `gprof', and how you can use
|
---|
26 | it to determine which parts of a program are taking most of the
|
---|
27 | execution time. We assume that you know how to write, compile, and
|
---|
28 | execute programs. GNU `gprof' was written by Jay Fenlason.
|
---|
29 |
|
---|
30 | This document is distributed under the terms of the GNU Free
|
---|
31 | Documentation License. A copy of the license is included in the
|
---|
32 | section entitled "GNU Free Documentation License".
|
---|
33 |
|
---|
34 | * Menu:
|
---|
35 |
|
---|
36 | * Introduction:: What profiling means, and why it is useful.
|
---|
37 |
|
---|
38 | * Compiling:: How to compile your program for profiling.
|
---|
39 | * Executing:: Executing your program to generate profile data
|
---|
40 | * Invoking:: How to run `gprof', and its options
|
---|
41 |
|
---|
42 | * Output:: Interpreting `gprof''s output
|
---|
43 |
|
---|
44 | * Inaccuracy:: Potential problems you should be aware of
|
---|
45 | * How do I?:: Answers to common questions
|
---|
46 | * Incompatibilities:: (between GNU `gprof' and Unix `gprof'.)
|
---|
47 | * Details:: Details of how profiling is done
|
---|
48 | * GNU Free Documentation License:: GNU Free Documentation License
|
---|
49 |
|
---|
50 |
|
---|
51 | File: gprof.info, Node: Introduction, Next: Compiling, Prev: Top, Up: Top
|
---|
52 |
|
---|
53 | Introduction to Profiling
|
---|
54 | *************************
|
---|
55 |
|
---|
56 | Profiling allows you to learn where your program spent its time and
|
---|
57 | which functions called which other functions while it was executing.
|
---|
58 | This information can show you which pieces of your program are slower
|
---|
59 | than you expected, and might be candidates for rewriting to make your
|
---|
60 | program execute faster. It can also tell you which functions are being
|
---|
61 | called more or less often than you expected. This may help you spot
|
---|
62 | bugs that had otherwise been unnoticed.
|
---|
63 |
|
---|
64 | Since the profiler uses information collected during the actual
|
---|
65 | execution of your program, it can be used on programs that are too
|
---|
66 | large or too complex to analyze by reading the source. However, how
|
---|
67 | your program is run will affect the information that shows up in the
|
---|
68 | profile data. If you don't use some feature of your program while it
|
---|
69 | is being profiled, no profile information will be generated for that
|
---|
70 | feature.
|
---|
71 |
|
---|
72 | Profiling has several steps:
|
---|
73 |
|
---|
74 | * You must compile and link your program with profiling enabled.
|
---|
75 | *Note Compiling::.
|
---|
76 |
|
---|
77 | * You must execute your program to generate a profile data file.
|
---|
78 | *Note Executing::.
|
---|
79 |
|
---|
80 | * You must run `gprof' to analyze the profile data. *Note
|
---|
81 | Invoking::.
|
---|
82 |
|
---|
83 | The next three chapters explain these steps in greater detail.
|
---|
84 |
|
---|
85 | Several forms of output are available from the analysis.
|
---|
86 |
|
---|
87 | The "flat profile" shows how much time your program spent in each
|
---|
88 | function, and how many times that function was called. If you simply
|
---|
89 | want to know which functions burn most of the cycles, it is stated
|
---|
90 | concisely here. *Note Flat Profile::.
|
---|
91 |
|
---|
92 | The "call graph" shows, for each function, which functions called
|
---|
93 | it, which other functions it called, and how many times. There is also
|
---|
94 | an estimate of how much time was spent in the subroutines of each
|
---|
95 | function. This can suggest places where you might try to eliminate
|
---|
96 | function calls that use a lot of time. *Note Call Graph::.
|
---|
97 |
|
---|
98 | The "annotated source" listing is a copy of the program's source
|
---|
99 | code, labeled with the number of times each line of the program was
|
---|
100 | executed. *Note Annotated Source::.
|
---|
101 |
|
---|
102 | To better understand how profiling works, you may wish to read a
|
---|
103 | description of its implementation. *Note Implementation::.
|
---|
104 |
|
---|
105 |
|
---|
106 | File: gprof.info, Node: Compiling, Next: Executing, Prev: Introduction, Up: Top
|
---|
107 |
|
---|
108 | Compiling a Program for Profiling
|
---|
109 | *********************************
|
---|
110 |
|
---|
111 | The first step in generating profile information for your program is
|
---|
112 | to compile and link it with profiling enabled.
|
---|
113 |
|
---|
114 | To compile a source file for profiling, specify the `-pg' option when
|
---|
115 | you run the compiler. (This is in addition to the options you normally
|
---|
116 | use.)
|
---|
117 |
|
---|
118 | To link the program for profiling, if you use a compiler such as `cc'
|
---|
119 | to do the linking, simply specify `-pg' in addition to your usual
|
---|
120 | options. The same option, `-pg', alters either compilation or linking
|
---|
121 | to do what is necessary for profiling. Here are examples:
|
---|
122 |
|
---|
123 | cc -g -c myprog.c utils.c -pg
|
---|
124 | cc -o myprog myprog.o utils.o -pg
|
---|
125 |
|
---|
126 | The `-pg' option also works with a command that both compiles and
|
---|
127 | links:
|
---|
128 |
|
---|
129 | cc -o myprog myprog.c utils.c -g -pg
|
---|
130 |
|
---|
131 | If you run the linker `ld' directly instead of through a compiler
|
---|
132 | such as `cc', you may have to specify a profiling startup file
|
---|
133 | `gcrt0.o' as the first input file instead of the usual startup file
|
---|
134 | `crt0.o'. In addition, you would probably want to specify the
|
---|
135 | profiling C library, `libc_p.a', by writing `-lc_p' instead of the
|
---|
136 | usual `-lc'. This is not absolutely necessary, but doing this gives
|
---|
137 | you number-of-calls information for standard library functions such as
|
---|
138 | `read' and `open'. For example:
|
---|
139 |
|
---|
140 | ld -o myprog /lib/gcrt0.o myprog.o utils.o -lc_p
|
---|
141 |
|
---|
142 | If you compile only some of the modules of the program with `-pg',
|
---|
143 | you can still profile the program, but you won't get complete
|
---|
144 | information about the modules that were compiled without `-pg'. The
|
---|
145 | only information you get for the functions in those modules is the
|
---|
146 | total time spent in them; there is no record of how many times they
|
---|
147 | were called, or from where. This will not affect the flat profile
|
---|
148 | (except that the `calls' field for the functions will be blank), but
|
---|
149 | will greatly reduce the usefulness of the call graph.
|
---|
150 |
|
---|
151 | If you wish to perform line-by-line profiling, you will also need to
|
---|
152 | specify the `-g' option, instructing the compiler to insert debugging
|
---|
153 | symbols into the program that match program addresses to source code
|
---|
154 | lines. *Note Line-by-line::.
|
---|
155 |
|
---|
156 | In addition to the `-pg' and `-g' options, you may also wish to
|
---|
157 | specify the `-a' option when compiling. This will instrument the
|
---|
158 | program to perform basic-block counting. As the program runs, it will
|
---|
159 | count how many times it executed each branch of each `if' statement,
|
---|
160 | each iteration of each `do' loop, etc. This will enable `gprof' to
|
---|
161 | construct an annotated source code listing showing how many times each
|
---|
162 | line of code was executed.
|
---|
163 |
|
---|
164 |
|
---|
165 | File: gprof.info, Node: Executing, Next: Invoking, Prev: Compiling, Up: Top
|
---|
166 |
|
---|
167 | Executing the Program
|
---|
168 | *********************
|
---|
169 |
|
---|
170 | Once the program is compiled for profiling, you must run it in order
|
---|
171 | to generate the information that `gprof' needs. Simply run the program
|
---|
172 | as usual, using the normal arguments, file names, etc. The program
|
---|
173 | should run normally, producing the same output as usual. It will,
|
---|
174 | however, run somewhat slower than normal because of the time spent
|
---|
175 | collecting and the writing the profile data.
|
---|
176 |
|
---|
177 | The way you run the program--the arguments and input that you give
|
---|
178 | it--may have a dramatic effect on what the profile information shows.
|
---|
179 | The profile data will describe the parts of the program that were
|
---|
180 | activated for the particular input you use. For example, if the first
|
---|
181 | command you give to your program is to quit, the profile data will show
|
---|
182 | the time used in initialization and in cleanup, but not much else.
|
---|
183 |
|
---|
184 | Your program will write the profile data into a file called
|
---|
185 | `gmon.out' just before exiting. If there is already a file called
|
---|
186 | `gmon.out', its contents are overwritten. There is currently no way to
|
---|
187 | tell the program to write the profile data under a different name, but
|
---|
188 | you can rename the file afterward if you are concerned that it may be
|
---|
189 | overwritten.
|
---|
190 |
|
---|
191 | In order to write the `gmon.out' file properly, your program must
|
---|
192 | exit normally: by returning from `main' or by calling `exit'. Calling
|
---|
193 | the low-level function `_exit' does not write the profile data, and
|
---|
194 | neither does abnormal termination due to an unhandled signal.
|
---|
195 |
|
---|
196 | The `gmon.out' file is written in the program's _current working
|
---|
197 | directory_ at the time it exits. This means that if your program calls
|
---|
198 | `chdir', the `gmon.out' file will be left in the last directory your
|
---|
199 | program `chdir''d to. If you don't have permission to write in this
|
---|
200 | directory, the file is not written, and you will get an error message.
|
---|
201 |
|
---|
202 | Older versions of the GNU profiling library may also write a file
|
---|
203 | called `bb.out'. This file, if present, contains an human-readable
|
---|
204 | listing of the basic-block execution counts. Unfortunately, the
|
---|
205 | appearance of a human-readable `bb.out' means the basic-block counts
|
---|
206 | didn't get written into `gmon.out'. The Perl script `bbconv.pl',
|
---|
207 | included with the `gprof' source distribution, will convert a `bb.out'
|
---|
208 | file into a format readable by `gprof'. Invoke it like this:
|
---|
209 |
|
---|
210 | bbconv.pl < bb.out > BH-DATA
|
---|
211 |
|
---|
212 | This translates the information in `bb.out' into a form that `gprof'
|
---|
213 | can understand. But you still need to tell `gprof' about the existence
|
---|
214 | of this translated information. To do that, include BB-DATA on the
|
---|
215 | `gprof' command line, _along with `gmon.out'_, like this:
|
---|
216 |
|
---|
217 | gprof OPTIONS EXECUTABLE-FILE gmon.out BB-DATA [YET-MORE-PROFILE-DATA-FILES...] [> OUTFILE]
|
---|
218 |
|
---|
219 |
|
---|
220 | File: gprof.info, Node: Invoking, Next: Output, Prev: Executing, Up: Top
|
---|
221 |
|
---|
222 | `gprof' Command Summary
|
---|
223 | ***********************
|
---|
224 |
|
---|
225 | After you have a profile data file `gmon.out', you can run `gprof'
|
---|
226 | to interpret the information in it. The `gprof' program prints a flat
|
---|
227 | profile and a call graph on standard output. Typically you would
|
---|
228 | redirect the output of `gprof' into a file with `>'.
|
---|
229 |
|
---|
230 | You run `gprof' like this:
|
---|
231 |
|
---|
232 | gprof OPTIONS [EXECUTABLE-FILE [PROFILE-DATA-FILES...]] [> OUTFILE]
|
---|
233 |
|
---|
234 | Here square-brackets indicate optional arguments.
|
---|
235 |
|
---|
236 | If you omit the executable file name, the file `a.out' is used. If
|
---|
237 | you give no profile data file name, the file `gmon.out' is used. If
|
---|
238 | any file is not in the proper format, or if the profile data file does
|
---|
239 | not appear to belong to the executable file, an error message is
|
---|
240 | printed.
|
---|
241 |
|
---|
242 | You can give more than one profile data file by entering all their
|
---|
243 | names after the executable file name; then the statistics in all the
|
---|
244 | data files are summed together.
|
---|
245 |
|
---|
246 | The order of these options does not matter.
|
---|
247 |
|
---|
248 | * Menu:
|
---|
249 |
|
---|
250 | * Output Options:: Controlling `gprof''s output style
|
---|
251 | * Analysis Options:: Controlling how `gprof' analyses its data
|
---|
252 | * Miscellaneous Options::
|
---|
253 | * Deprecated Options:: Options you no longer need to use, but which
|
---|
254 | have been retained for compatibility
|
---|
255 | * Symspecs:: Specifying functions to include or exclude
|
---|
256 |
|
---|
257 |
|
---|
258 | File: gprof.info, Node: Output Options, Next: Analysis Options, Up: Invoking
|
---|
259 |
|
---|
260 | Output Options
|
---|
261 | ==============
|
---|
262 |
|
---|
263 | These options specify which of several output formats `gprof' should
|
---|
264 | produce.
|
---|
265 |
|
---|
266 | Many of these options take an optional "symspec" to specify
|
---|
267 | functions to be included or excluded. These options can be specified
|
---|
268 | multiple times, with different symspecs, to include or exclude sets of
|
---|
269 | symbols. *Note Symspecs::.
|
---|
270 |
|
---|
271 | Specifying any of these options overrides the default (`-p -q'),
|
---|
272 | which prints a flat profile and call graph analysis for all functions.
|
---|
273 |
|
---|
274 | `-A[SYMSPEC]'
|
---|
275 | `--annotated-source[=SYMSPEC]'
|
---|
276 | The `-A' option causes `gprof' to print annotated source code. If
|
---|
277 | SYMSPEC is specified, print output only for matching symbols.
|
---|
278 | *Note Annotated Source::.
|
---|
279 |
|
---|
280 | `-b'
|
---|
281 | `--brief'
|
---|
282 | If the `-b' option is given, `gprof' doesn't print the verbose
|
---|
283 | blurbs that try to explain the meaning of all of the fields in the
|
---|
284 | tables. This is useful if you intend to print out the output, or
|
---|
285 | are tired of seeing the blurbs.
|
---|
286 |
|
---|
287 | `-C[SYMSPEC]'
|
---|
288 | `--exec-counts[=SYMSPEC]'
|
---|
289 | The `-C' option causes `gprof' to print a tally of functions and
|
---|
290 | the number of times each was called. If SYMSPEC is specified,
|
---|
291 | print tally only for matching symbols.
|
---|
292 |
|
---|
293 | If the profile data file contains basic-block count records,
|
---|
294 | specifying the `-l' option, along with `-C', will cause basic-block
|
---|
295 | execution counts to be tallied and displayed.
|
---|
296 |
|
---|
297 | `-i'
|
---|
298 | `--file-info'
|
---|
299 | The `-i' option causes `gprof' to display summary information
|
---|
300 | about the profile data file(s) and then exit. The number of
|
---|
301 | histogram, call graph, and basic-block count records is displayed.
|
---|
302 |
|
---|
303 | `-I DIRS'
|
---|
304 | `--directory-path=DIRS'
|
---|
305 | The `-I' option specifies a list of search directories in which to
|
---|
306 | find source files. Environment variable GPROF_PATH can also be
|
---|
307 | used to convey this information. Used mostly for annotated source
|
---|
308 | output.
|
---|
309 |
|
---|
310 | `-J[SYMSPEC]'
|
---|
311 | `--no-annotated-source[=SYMSPEC]'
|
---|
312 | The `-J' option causes `gprof' not to print annotated source code.
|
---|
313 | If SYMSPEC is specified, `gprof' prints annotated source, but
|
---|
314 | excludes matching symbols.
|
---|
315 |
|
---|
316 | `-L'
|
---|
317 | `--print-path'
|
---|
318 | Normally, source filenames are printed with the path component
|
---|
319 | suppressed. The `-L' option causes `gprof' to print the full
|
---|
320 | pathname of source filenames, which is determined from symbolic
|
---|
321 | debugging information in the image file and is relative to the
|
---|
322 | directory in which the compiler was invoked.
|
---|
323 |
|
---|
324 | `-p[SYMSPEC]'
|
---|
325 | `--flat-profile[=SYMSPEC]'
|
---|
326 | The `-p' option causes `gprof' to print a flat profile. If
|
---|
327 | SYMSPEC is specified, print flat profile only for matching symbols.
|
---|
328 | *Note Flat Profile::.
|
---|
329 |
|
---|
330 | `-P[SYMSPEC]'
|
---|
331 | `--no-flat-profile[=SYMSPEC]'
|
---|
332 | The `-P' option causes `gprof' to suppress printing a flat profile.
|
---|
333 | If SYMSPEC is specified, `gprof' prints a flat profile, but
|
---|
334 | excludes matching symbols.
|
---|
335 |
|
---|
336 | `-q[SYMSPEC]'
|
---|
337 | `--graph[=SYMSPEC]'
|
---|
338 | The `-q' option causes `gprof' to print the call graph analysis.
|
---|
339 | If SYMSPEC is specified, print call graph only for matching symbols
|
---|
340 | and their children. *Note Call Graph::.
|
---|
341 |
|
---|
342 | `-Q[SYMSPEC]'
|
---|
343 | `--no-graph[=SYMSPEC]'
|
---|
344 | The `-Q' option causes `gprof' to suppress printing the call graph.
|
---|
345 | If SYMSPEC is specified, `gprof' prints a call graph, but excludes
|
---|
346 | matching symbols.
|
---|
347 |
|
---|
348 | `-y'
|
---|
349 | `--separate-files'
|
---|
350 | This option affects annotated source output only. Normally,
|
---|
351 | `gprof' prints annotated source files to standard-output. If this
|
---|
352 | option is specified, annotated source for a file named
|
---|
353 | `path/FILENAME' is generated in the file `FILENAME-ann'. If the
|
---|
354 | underlying filesystem would truncate `FILENAME-ann' so that it
|
---|
355 | overwrites the original `FILENAME', `gprof' generates annotated
|
---|
356 | source in the file `FILENAME.ann' instead (if the original file
|
---|
357 | name has an extension, that extension is _replaced_ with `.ann').
|
---|
358 |
|
---|
359 | `-Z[SYMSPEC]'
|
---|
360 | `--no-exec-counts[=SYMSPEC]'
|
---|
361 | The `-Z' option causes `gprof' not to print a tally of functions
|
---|
362 | and the number of times each was called. If SYMSPEC is specified,
|
---|
363 | print tally, but exclude matching symbols.
|
---|
364 |
|
---|
365 | `--function-ordering'
|
---|
366 | The `--function-ordering' option causes `gprof' to print a
|
---|
367 | suggested function ordering for the program based on profiling
|
---|
368 | data. This option suggests an ordering which may improve paging,
|
---|
369 | tlb and cache behavior for the program on systems which support
|
---|
370 | arbitrary ordering of functions in an executable.
|
---|
371 |
|
---|
372 | The exact details of how to force the linker to place functions in
|
---|
373 | a particular order is system dependent and out of the scope of this
|
---|
374 | manual.
|
---|
375 |
|
---|
376 | `--file-ordering MAP_FILE'
|
---|
377 | The `--file-ordering' option causes `gprof' to print a suggested
|
---|
378 | .o link line ordering for the program based on profiling data.
|
---|
379 | This option suggests an ordering which may improve paging, tlb and
|
---|
380 | cache behavior for the program on systems which do not support
|
---|
381 | arbitrary ordering of functions in an executable.
|
---|
382 |
|
---|
383 | Use of the `-a' argument is highly recommended with this option.
|
---|
384 |
|
---|
385 | The MAP_FILE argument is a pathname to a file which provides
|
---|
386 | function name to object file mappings. The format of the file is
|
---|
387 | similar to the output of the program `nm'.
|
---|
388 |
|
---|
389 | c-parse.o:00000000 T yyparse
|
---|
390 | c-parse.o:00000004 C yyerrflag
|
---|
391 | c-lang.o:00000000 T maybe_objc_method_name
|
---|
392 | c-lang.o:00000000 T print_lang_statistics
|
---|
393 | c-lang.o:00000000 T recognize_objc_keyword
|
---|
394 | c-decl.o:00000000 T print_lang_identifier
|
---|
395 | c-decl.o:00000000 T print_lang_type
|
---|
396 | ...
|
---|
397 |
|
---|
398 | To create a MAP_FILE with GNU `nm', type a command like `nm
|
---|
399 | --extern-only --defined-only -v --print-file-name program-name'.
|
---|
400 |
|
---|
401 | `-T'
|
---|
402 | `--traditional'
|
---|
403 | The `-T' option causes `gprof' to print its output in
|
---|
404 | "traditional" BSD style.
|
---|
405 |
|
---|
406 | `-w WIDTH'
|
---|
407 | `--width=WIDTH'
|
---|
408 | Sets width of output lines to WIDTH. Currently only used when
|
---|
409 | printing the function index at the bottom of the call graph.
|
---|
410 |
|
---|
411 | `-x'
|
---|
412 | `--all-lines'
|
---|
413 | This option affects annotated source output only. By default,
|
---|
414 | only the lines at the beginning of a basic-block are annotated.
|
---|
415 | If this option is specified, every line in a basic-block is
|
---|
416 | annotated by repeating the annotation for the first line. This
|
---|
417 | behavior is similar to `tcov''s `-a'.
|
---|
418 |
|
---|
419 | `--demangle[=STYLE]'
|
---|
420 | `--no-demangle'
|
---|
421 | These options control whether C++ symbol names should be demangled
|
---|
422 | when printing output. The default is to demangle symbols. The
|
---|
423 | `--no-demangle' option may be used to turn off demangling.
|
---|
424 | Different compilers have different mangling styles. The optional
|
---|
425 | demangling style argument can be used to choose an appropriate
|
---|
426 | demangling style for your compiler.
|
---|
427 |
|
---|
428 |
|
---|
429 | File: gprof.info, Node: Analysis Options, Next: Miscellaneous Options, Prev: Output Options, Up: Invoking
|
---|
430 |
|
---|
431 | Analysis Options
|
---|
432 | ================
|
---|
433 |
|
---|
434 | `-a'
|
---|
435 | `--no-static'
|
---|
436 | The `-a' option causes `gprof' to suppress the printing of
|
---|
437 | statically declared (private) functions. (These are functions
|
---|
438 | whose names are not listed as global, and which are not visible
|
---|
439 | outside the file/function/block where they were defined.) Time
|
---|
440 | spent in these functions, calls to/from them, etc, will all be
|
---|
441 | attributed to the function that was loaded directly before it in
|
---|
442 | the executable file. This option affects both the flat profile
|
---|
443 | and the call graph.
|
---|
444 |
|
---|
445 | `-c'
|
---|
446 | `--static-call-graph'
|
---|
447 | The `-c' option causes the call graph of the program to be
|
---|
448 | augmented by a heuristic which examines the text space of the
|
---|
449 | object file and identifies function calls in the binary machine
|
---|
450 | code. Since normal call graph records are only generated when
|
---|
451 | functions are entered, this option identifies children that could
|
---|
452 | have been called, but never were. Calls to functions that were
|
---|
453 | not compiled with profiling enabled are also identified, but only
|
---|
454 | if symbol table entries are present for them. Calls to dynamic
|
---|
455 | library routines are typically _not_ found by this option.
|
---|
456 | Parents or children identified via this heuristic are indicated in
|
---|
457 | the call graph with call counts of `0'.
|
---|
458 |
|
---|
459 | `-D'
|
---|
460 | `--ignore-non-functions'
|
---|
461 | The `-D' option causes `gprof' to ignore symbols which are not
|
---|
462 | known to be functions. This option will give more accurate
|
---|
463 | profile data on systems where it is supported (Solaris and HPUX for
|
---|
464 | example).
|
---|
465 |
|
---|
466 | `-k FROM/TO'
|
---|
467 | The `-k' option allows you to delete from the call graph any arcs
|
---|
468 | from symbols matching symspec FROM to those matching symspec TO.
|
---|
469 |
|
---|
470 | `-l'
|
---|
471 | `--line'
|
---|
472 | The `-l' option enables line-by-line profiling, which causes
|
---|
473 | histogram hits to be charged to individual source code lines,
|
---|
474 | instead of functions. If the program was compiled with
|
---|
475 | basic-block counting enabled, this option will also identify how
|
---|
476 | many times each line of code was executed. While line-by-line
|
---|
477 | profiling can help isolate where in a large function a program is
|
---|
478 | spending its time, it also significantly increases the running
|
---|
479 | time of `gprof', and magnifies statistical inaccuracies. *Note
|
---|
480 | Sampling Error::.
|
---|
481 |
|
---|
482 | `-m NUM'
|
---|
483 | `--min-count=NUM'
|
---|
484 | This option affects execution count output only. Symbols that are
|
---|
485 | executed less than NUM times are suppressed.
|
---|
486 |
|
---|
487 | `-n[SYMSPEC]'
|
---|
488 | `--time[=SYMSPEC]'
|
---|
489 | The `-n' option causes `gprof', in its call graph analysis, to
|
---|
490 | only propagate times for symbols matching SYMSPEC.
|
---|
491 |
|
---|
492 | `-N[SYMSPEC]'
|
---|
493 | `--no-time[=SYMSPEC]'
|
---|
494 | The `-n' option causes `gprof', in its call graph analysis, not to
|
---|
495 | propagate times for symbols matching SYMSPEC.
|
---|
496 |
|
---|
497 | `-z'
|
---|
498 | `--display-unused-functions'
|
---|
499 | If you give the `-z' option, `gprof' will mention all functions in
|
---|
500 | the flat profile, even those that were never called, and that had
|
---|
501 | no time spent in them. This is useful in conjunction with the
|
---|
502 | `-c' option for discovering which routines were never called.
|
---|
503 |
|
---|
504 |
|
---|
505 | File: gprof.info, Node: Miscellaneous Options, Next: Deprecated Options, Prev: Analysis Options, Up: Invoking
|
---|
506 |
|
---|
507 | Miscellaneous Options
|
---|
508 | =====================
|
---|
509 |
|
---|
510 | `-d[NUM]'
|
---|
511 | `--debug[=NUM]'
|
---|
512 | The `-d NUM' option specifies debugging options. If NUM is not
|
---|
513 | specified, enable all debugging. *Note Debugging::.
|
---|
514 |
|
---|
515 | `-ONAME'
|
---|
516 | `--file-format=NAME'
|
---|
517 | Selects the format of the profile data files. Recognized formats
|
---|
518 | are `auto' (the default), `bsd', `4.4bsd', `magic', and `prof'
|
---|
519 | (not yet supported).
|
---|
520 |
|
---|
521 | `-s'
|
---|
522 | `--sum'
|
---|
523 | The `-s' option causes `gprof' to summarize the information in the
|
---|
524 | profile data files it read in, and write out a profile data file
|
---|
525 | called `gmon.sum', which contains all the information from the
|
---|
526 | profile data files that `gprof' read in. The file `gmon.sum' may
|
---|
527 | be one of the specified input files; the effect of this is to
|
---|
528 | merge the data in the other input files into `gmon.sum'.
|
---|
529 |
|
---|
530 | Eventually you can run `gprof' again without `-s' to analyze the
|
---|
531 | cumulative data in the file `gmon.sum'.
|
---|
532 |
|
---|
533 | `-v'
|
---|
534 | `--version'
|
---|
535 | The `-v' flag causes `gprof' to print the current version number,
|
---|
536 | and then exit.
|
---|
537 |
|
---|
538 |
|
---|
539 | File: gprof.info, Node: Deprecated Options, Next: Symspecs, Prev: Miscellaneous Options, Up: Invoking
|
---|
540 |
|
---|
541 | Deprecated Options
|
---|
542 | ==================
|
---|
543 |
|
---|
544 | These options have been replaced with newer versions that use
|
---|
545 | symspecs.
|
---|
546 |
|
---|
547 | `-e FUNCTION_NAME'
|
---|
548 | The `-e FUNCTION' option tells `gprof' to not print information
|
---|
549 | about the function FUNCTION_NAME (and its children...) in the call
|
---|
550 | graph. The function will still be listed as a child of any
|
---|
551 | functions that call it, but its index number will be shown as
|
---|
552 | `[not printed]'. More than one `-e' option may be given; only one
|
---|
553 | FUNCTION_NAME may be indicated with each `-e' option.
|
---|
554 |
|
---|
555 | `-E FUNCTION_NAME'
|
---|
556 | The `-E FUNCTION' option works like the `-e' option, but time
|
---|
557 | spent in the function (and children who were not called from
|
---|
558 | anywhere else), will not be used to compute the
|
---|
559 | percentages-of-time for the call graph. More than one `-E' option
|
---|
560 | may be given; only one FUNCTION_NAME may be indicated with each
|
---|
561 | `-E' option.
|
---|
562 |
|
---|
563 | `-f FUNCTION_NAME'
|
---|
564 | The `-f FUNCTION' option causes `gprof' to limit the call graph to
|
---|
565 | the function FUNCTION_NAME and its children (and their
|
---|
566 | children...). More than one `-f' option may be given; only one
|
---|
567 | FUNCTION_NAME may be indicated with each `-f' option.
|
---|
568 |
|
---|
569 | `-F FUNCTION_NAME'
|
---|
570 | The `-F FUNCTION' option works like the `-f' option, but only time
|
---|
571 | spent in the function and its children (and their children...)
|
---|
572 | will be used to determine total-time and percentages-of-time for
|
---|
573 | the call graph. More than one `-F' option may be given; only one
|
---|
574 | FUNCTION_NAME may be indicated with each `-F' option. The `-F'
|
---|
575 | option overrides the `-E' option.
|
---|
576 |
|
---|
577 | Note that only one function can be specified with each `-e', `-E',
|
---|
578 | `-f' or `-F' option. To specify more than one function, use multiple
|
---|
579 | options. For example, this command:
|
---|
580 |
|
---|
581 | gprof -e boring -f foo -f bar myprogram > gprof.output
|
---|
582 |
|
---|
583 | lists in the call graph all functions that were reached from either
|
---|
584 | `foo' or `bar' and were not reachable from `boring'.
|
---|
585 |
|
---|
586 |
|
---|
587 | File: gprof.info, Node: Symspecs, Prev: Deprecated Options, Up: Invoking
|
---|
588 |
|
---|
589 | Symspecs
|
---|
590 | ========
|
---|
591 |
|
---|
592 | Many of the output options allow functions to be included or excluded
|
---|
593 | using "symspecs" (symbol specifications), which observe the following
|
---|
594 | syntax:
|
---|
595 |
|
---|
596 | filename_containing_a_dot
|
---|
597 | | funcname_not_containing_a_dot
|
---|
598 | | linenumber
|
---|
599 | | ( [ any_filename ] `:' ( any_funcname | linenumber ) )
|
---|
600 |
|
---|
601 | Here are some sample symspecs:
|
---|
602 |
|
---|
603 | `main.c'
|
---|
604 | Selects everything in file `main.c'--the dot in the string tells
|
---|
605 | `gprof' to interpret the string as a filename, rather than as a
|
---|
606 | function name. To select a file whose name does not contain a
|
---|
607 | dot, a trailing colon should be specified. For example, `odd:' is
|
---|
608 | interpreted as the file named `odd'.
|
---|
609 |
|
---|
610 | `main'
|
---|
611 | Selects all functions named `main'.
|
---|
612 |
|
---|
613 | Note that there may be multiple instances of the same function name
|
---|
614 | because some of the definitions may be local (i.e., static).
|
---|
615 | Unless a function name is unique in a program, you must use the
|
---|
616 | colon notation explained below to specify a function from a
|
---|
617 | specific source file.
|
---|
618 |
|
---|
619 | Sometimes, function names contain dots. In such cases, it is
|
---|
620 | necessary to add a leading colon to the name. For example,
|
---|
621 | `:.mul' selects function `.mul'.
|
---|
622 |
|
---|
623 | In some object file formats, symbols have a leading underscore.
|
---|
624 | `gprof' will normally not print these underscores. When you name a
|
---|
625 | symbol in a symspec, you should type it exactly as `gprof' prints
|
---|
626 | it in its output. For example, if the compiler produces a symbol
|
---|
627 | `_main' from your `main' function, `gprof' still prints it as
|
---|
628 | `main' in its output, so you should use `main' in symspecs.
|
---|
629 |
|
---|
630 | `main.c:main'
|
---|
631 | Selects function `main' in file `main.c'.
|
---|
632 |
|
---|
633 | `main.c:134'
|
---|
634 | Selects line 134 in file `main.c'.
|
---|
635 |
|
---|
636 |
|
---|
637 | File: gprof.info, Node: Output, Next: Inaccuracy, Prev: Invoking, Up: Top
|
---|
638 |
|
---|
639 | Interpreting `gprof''s Output
|
---|
640 | *****************************
|
---|
641 |
|
---|
642 | `gprof' can produce several different output styles, the most
|
---|
643 | important of which are described below. The simplest output styles
|
---|
644 | (file information, execution count, and function and file ordering) are
|
---|
645 | not described here, but are documented with the respective options that
|
---|
646 | trigger them. *Note Output Options::.
|
---|
647 |
|
---|
648 | * Menu:
|
---|
649 |
|
---|
650 | * Flat Profile:: The flat profile shows how much time was spent
|
---|
651 | executing directly in each function.
|
---|
652 | * Call Graph:: The call graph shows which functions called which
|
---|
653 | others, and how much time each function used
|
---|
654 | when its subroutine calls are included.
|
---|
655 | * Line-by-line:: `gprof' can analyze individual source code lines
|
---|
656 | * Annotated Source:: The annotated source listing displays source code
|
---|
657 | labeled with execution counts
|
---|
658 |
|
---|
659 |
|
---|
660 | File: gprof.info, Node: Flat Profile, Next: Call Graph, Up: Output
|
---|
661 |
|
---|
662 | The Flat Profile
|
---|
663 | ================
|
---|
664 |
|
---|
665 | The "flat profile" shows the total amount of time your program spent
|
---|
666 | executing each function. Unless the `-z' option is given, functions
|
---|
667 | with no apparent time spent in them, and no apparent calls to them, are
|
---|
668 | not mentioned. Note that if a function was not compiled for profiling,
|
---|
669 | and didn't run long enough to show up on the program counter histogram,
|
---|
670 | it will be indistinguishable from a function that was never called.
|
---|
671 |
|
---|
672 | This is part of a flat profile for a small program:
|
---|
673 |
|
---|
674 | Flat profile:
|
---|
675 |
|
---|
676 | Each sample counts as 0.01 seconds.
|
---|
677 | % cumulative self self total
|
---|
678 | time seconds seconds calls ms/call ms/call name
|
---|
679 | 33.34 0.02 0.02 7208 0.00 0.00 open
|
---|
680 | 16.67 0.03 0.01 244 0.04 0.12 offtime
|
---|
681 | 16.67 0.04 0.01 8 1.25 1.25 memccpy
|
---|
682 | 16.67 0.05 0.01 7 1.43 1.43 write
|
---|
683 | 16.67 0.06 0.01 mcount
|
---|
684 | 0.00 0.06 0.00 236 0.00 0.00 tzset
|
---|
685 | 0.00 0.06 0.00 192 0.00 0.00 tolower
|
---|
686 | 0.00 0.06 0.00 47 0.00 0.00 strlen
|
---|
687 | 0.00 0.06 0.00 45 0.00 0.00 strchr
|
---|
688 | 0.00 0.06 0.00 1 0.00 50.00 main
|
---|
689 | 0.00 0.06 0.00 1 0.00 0.00 memcpy
|
---|
690 | 0.00 0.06 0.00 1 0.00 10.11 print
|
---|
691 | 0.00 0.06 0.00 1 0.00 0.00 profil
|
---|
692 | 0.00 0.06 0.00 1 0.00 50.00 report
|
---|
693 | ...
|
---|
694 |
|
---|
695 | The functions are sorted by first by decreasing run-time spent in them,
|
---|
696 | then by decreasing number of calls, then alphabetically by name. The
|
---|
697 | functions `mcount' and `profil' are part of the profiling apparatus and
|
---|
698 | appear in every flat profile; their time gives a measure of the amount
|
---|
699 | of overhead due to profiling.
|
---|
700 |
|
---|
701 | Just before the column headers, a statement appears indicating how
|
---|
702 | much time each sample counted as. This "sampling period" estimates the
|
---|
703 | margin of error in each of the time figures. A time figure that is not
|
---|
704 | much larger than this is not reliable. In this example, each sample
|
---|
705 | counted as 0.01 seconds, suggesting a 100 Hz sampling rate. The
|
---|
706 | program's total execution time was 0.06 seconds, as indicated by the
|
---|
707 | `cumulative seconds' field. Since each sample counted for 0.01
|
---|
708 | seconds, this means only six samples were taken during the run. Two of
|
---|
709 | the samples occurred while the program was in the `open' function, as
|
---|
710 | indicated by the `self seconds' field. Each of the other four samples
|
---|
711 | occurred one each in `offtime', `memccpy', `write', and `mcount'.
|
---|
712 | Since only six samples were taken, none of these values can be regarded
|
---|
713 | as particularly reliable. In another run, the `self seconds' field for
|
---|
714 | `mcount' might well be `0.00' or `0.02'. *Note Sampling Error::, for a
|
---|
715 | complete discussion.
|
---|
716 |
|
---|
717 | The remaining functions in the listing (those whose `self seconds'
|
---|
718 | field is `0.00') didn't appear in the histogram samples at all.
|
---|
719 | However, the call graph indicated that they were called, so therefore
|
---|
720 | they are listed, sorted in decreasing order by the `calls' field.
|
---|
721 | Clearly some time was spent executing these functions, but the paucity
|
---|
722 | of histogram samples prevents any determination of how much time each
|
---|
723 | took.
|
---|
724 |
|
---|
725 | Here is what the fields in each line mean:
|
---|
726 |
|
---|
727 | `% time'
|
---|
728 | This is the percentage of the total execution time your program
|
---|
729 | spent in this function. These should all add up to 100%.
|
---|
730 |
|
---|
731 | `cumulative seconds'
|
---|
732 | This is the cumulative total number of seconds the computer spent
|
---|
733 | executing this functions, plus the time spent in all the functions
|
---|
734 | above this one in this table.
|
---|
735 |
|
---|
736 | `self seconds'
|
---|
737 | This is the number of seconds accounted for by this function alone.
|
---|
738 | The flat profile listing is sorted first by this number.
|
---|
739 |
|
---|
740 | `calls'
|
---|
741 | This is the total number of times the function was called. If the
|
---|
742 | function was never called, or the number of times it was called
|
---|
743 | cannot be determined (probably because the function was not
|
---|
744 | compiled with profiling enabled), the "calls" field is blank.
|
---|
745 |
|
---|
746 | `self ms/call'
|
---|
747 | This represents the average number of milliseconds spent in this
|
---|
748 | function per call, if this function is profiled. Otherwise, this
|
---|
749 | field is blank for this function.
|
---|
750 |
|
---|
751 | `total ms/call'
|
---|
752 | This represents the average number of milliseconds spent in this
|
---|
753 | function and its descendants per call, if this function is
|
---|
754 | profiled. Otherwise, this field is blank for this function. This
|
---|
755 | is the only field in the flat profile that uses call graph
|
---|
756 | analysis.
|
---|
757 |
|
---|
758 | `name'
|
---|
759 | This is the name of the function. The flat profile is sorted by
|
---|
760 | this field alphabetically after the "self seconds" and "calls"
|
---|
761 | fields are sorted.
|
---|
762 |
|
---|
763 |
|
---|
764 | File: gprof.info, Node: Call Graph, Next: Line-by-line, Prev: Flat Profile, Up: Output
|
---|
765 |
|
---|
766 | The Call Graph
|
---|
767 | ==============
|
---|
768 |
|
---|
769 | The "call graph" shows how much time was spent in each function and
|
---|
770 | its children. From this information, you can find functions that,
|
---|
771 | while they themselves may not have used much time, called other
|
---|
772 | functions that did use unusual amounts of time.
|
---|
773 |
|
---|
774 | Here is a sample call from a small program. This call came from the
|
---|
775 | same `gprof' run as the flat profile example in the previous chapter.
|
---|
776 |
|
---|
777 | granularity: each sample hit covers 2 byte(s) for 20.00% of 0.05 seconds
|
---|
778 |
|
---|
779 | index % time self children called name
|
---|
780 | <spontaneous>
|
---|
781 | [1] 100.0 0.00 0.05 start [1]
|
---|
782 | 0.00 0.05 1/1 main [2]
|
---|
783 | 0.00 0.00 1/2 on_exit [28]
|
---|
784 | 0.00 0.00 1/1 exit [59]
|
---|
785 | -----------------------------------------------
|
---|
786 | 0.00 0.05 1/1 start [1]
|
---|
787 | [2] 100.0 0.00 0.05 1 main [2]
|
---|
788 | 0.00 0.05 1/1 report [3]
|
---|
789 | -----------------------------------------------
|
---|
790 | 0.00 0.05 1/1 main [2]
|
---|
791 | [3] 100.0 0.00 0.05 1 report [3]
|
---|
792 | 0.00 0.03 8/8 timelocal [6]
|
---|
793 | 0.00 0.01 1/1 print [9]
|
---|
794 | 0.00 0.01 9/9 fgets [12]
|
---|
795 | 0.00 0.00 12/34 strncmp <cycle 1> [40]
|
---|
796 | 0.00 0.00 8/8 lookup [20]
|
---|
797 | 0.00 0.00 1/1 fopen [21]
|
---|
798 | 0.00 0.00 8/8 chewtime [24]
|
---|
799 | 0.00 0.00 8/16 skipspace [44]
|
---|
800 | -----------------------------------------------
|
---|
801 | [4] 59.8 0.01 0.02 8+472 <cycle 2 as a whole> [4]
|
---|
802 | 0.01 0.02 244+260 offtime <cycle 2> [7]
|
---|
803 | 0.00 0.00 236+1 tzset <cycle 2> [26]
|
---|
804 | -----------------------------------------------
|
---|
805 |
|
---|
806 | The lines full of dashes divide this table into "entries", one for
|
---|
807 | each function. Each entry has one or more lines.
|
---|
808 |
|
---|
809 | In each entry, the primary line is the one that starts with an index
|
---|
810 | number in square brackets. The end of this line says which function
|
---|
811 | the entry is for. The preceding lines in the entry describe the
|
---|
812 | callers of this function and the following lines describe its
|
---|
813 | subroutines (also called "children" when we speak of the call graph).
|
---|
814 |
|
---|
815 | The entries are sorted by time spent in the function and its
|
---|
816 | subroutines.
|
---|
817 |
|
---|
818 | The internal profiling function `mcount' (*note Flat Profile::) is
|
---|
819 | never mentioned in the call graph.
|
---|
820 |
|
---|
821 | * Menu:
|
---|
822 |
|
---|
823 | * Primary:: Details of the primary line's contents.
|
---|
824 | * Callers:: Details of caller-lines' contents.
|
---|
825 | * Subroutines:: Details of subroutine-lines' contents.
|
---|
826 | * Cycles:: When there are cycles of recursion,
|
---|
827 | such as `a' calls `b' calls `a'...
|
---|
828 |
|
---|
829 |
|
---|
830 | File: gprof.info, Node: Primary, Next: Callers, Up: Call Graph
|
---|
831 |
|
---|
832 | The Primary Line
|
---|
833 | ----------------
|
---|
834 |
|
---|
835 | The "primary line" in a call graph entry is the line that describes
|
---|
836 | the function which the entry is about and gives the overall statistics
|
---|
837 | for this function.
|
---|
838 |
|
---|
839 | For reference, we repeat the primary line from the entry for function
|
---|
840 | `report' in our main example, together with the heading line that shows
|
---|
841 | the names of the fields:
|
---|
842 |
|
---|
843 | index % time self children called name
|
---|
844 | ...
|
---|
845 | [3] 100.0 0.00 0.05 1 report [3]
|
---|
846 |
|
---|
847 | Here is what the fields in the primary line mean:
|
---|
848 |
|
---|
849 | `index'
|
---|
850 | Entries are numbered with consecutive integers. Each function
|
---|
851 | therefore has an index number, which appears at the beginning of
|
---|
852 | its primary line.
|
---|
853 |
|
---|
854 | Each cross-reference to a function, as a caller or subroutine of
|
---|
855 | another, gives its index number as well as its name. The index
|
---|
856 | number guides you if you wish to look for the entry for that
|
---|
857 | function.
|
---|
858 |
|
---|
859 | `% time'
|
---|
860 | This is the percentage of the total time that was spent in this
|
---|
861 | function, including time spent in subroutines called from this
|
---|
862 | function.
|
---|
863 |
|
---|
864 | The time spent in this function is counted again for the callers of
|
---|
865 | this function. Therefore, adding up these percentages is
|
---|
866 | meaningless.
|
---|
867 |
|
---|
868 | `self'
|
---|
869 | This is the total amount of time spent in this function. This
|
---|
870 | should be identical to the number printed in the `seconds' field
|
---|
871 | for this function in the flat profile.
|
---|
872 |
|
---|
873 | `children'
|
---|
874 | This is the total amount of time spent in the subroutine calls
|
---|
875 | made by this function. This should be equal to the sum of all the
|
---|
876 | `self' and `children' entries of the children listed directly
|
---|
877 | below this function.
|
---|
878 |
|
---|
879 | `called'
|
---|
880 | This is the number of times the function was called.
|
---|
881 |
|
---|
882 | If the function called itself recursively, there are two numbers,
|
---|
883 | separated by a `+'. The first number counts non-recursive calls,
|
---|
884 | and the second counts recursive calls.
|
---|
885 |
|
---|
886 | In the example above, the function `report' was called once from
|
---|
887 | `main'.
|
---|
888 |
|
---|
889 | `name'
|
---|
890 | This is the name of the current function. The index number is
|
---|
891 | repeated after it.
|
---|
892 |
|
---|
893 | If the function is part of a cycle of recursion, the cycle number
|
---|
894 | is printed between the function's name and the index number (*note
|
---|
895 | Cycles::). For example, if function `gnurr' is part of cycle
|
---|
896 | number one, and has index number twelve, its primary line would be
|
---|
897 | end like this:
|
---|
898 |
|
---|
899 | gnurr <cycle 1> [12]
|
---|
900 |
|
---|
901 |
|
---|
902 | File: gprof.info, Node: Callers, Next: Subroutines, Prev: Primary, Up: Call Graph
|
---|
903 |
|
---|
904 | Lines for a Function's Callers
|
---|
905 | ------------------------------
|
---|
906 |
|
---|
907 | A function's entry has a line for each function it was called by.
|
---|
908 | These lines' fields correspond to the fields of the primary line, but
|
---|
909 | their meanings are different because of the difference in context.
|
---|
910 |
|
---|
911 | For reference, we repeat two lines from the entry for the function
|
---|
912 | `report', the primary line and one caller-line preceding it, together
|
---|
913 | with the heading line that shows the names of the fields:
|
---|
914 |
|
---|
915 | index % time self children called name
|
---|
916 | ...
|
---|
917 | 0.00 0.05 1/1 main [2]
|
---|
918 | [3] 100.0 0.00 0.05 1 report [3]
|
---|
919 |
|
---|
920 | Here are the meanings of the fields in the caller-line for `report'
|
---|
921 | called from `main':
|
---|
922 |
|
---|
923 | `self'
|
---|
924 | An estimate of the amount of time spent in `report' itself when it
|
---|
925 | was called from `main'.
|
---|
926 |
|
---|
927 | `children'
|
---|
928 | An estimate of the amount of time spent in subroutines of `report'
|
---|
929 | when `report' was called from `main'.
|
---|
930 |
|
---|
931 | The sum of the `self' and `children' fields is an estimate of the
|
---|
932 | amount of time spent within calls to `report' from `main'.
|
---|
933 |
|
---|
934 | `called'
|
---|
935 | Two numbers: the number of times `report' was called from `main',
|
---|
936 | followed by the total number of non-recursive calls to `report'
|
---|
937 | from all its callers.
|
---|
938 |
|
---|
939 | `name and index number'
|
---|
940 | The name of the caller of `report' to which this line applies,
|
---|
941 | followed by the caller's index number.
|
---|
942 |
|
---|
943 | Not all functions have entries in the call graph; some options to
|
---|
944 | `gprof' request the omission of certain functions. When a caller
|
---|
945 | has no entry of its own, it still has caller-lines in the entries
|
---|
946 | of the functions it calls.
|
---|
947 |
|
---|
948 | If the caller is part of a recursion cycle, the cycle number is
|
---|
949 | printed between the name and the index number.
|
---|
950 |
|
---|
951 | If the identity of the callers of a function cannot be determined, a
|
---|
952 | dummy caller-line is printed which has `<spontaneous>' as the "caller's
|
---|
953 | name" and all other fields blank. This can happen for signal handlers.
|
---|
954 |
|
---|
955 |
|
---|
956 | File: gprof.info, Node: Subroutines, Next: Cycles, Prev: Callers, Up: Call Graph
|
---|
957 |
|
---|
958 | Lines for a Function's Subroutines
|
---|
959 | ----------------------------------
|
---|
960 |
|
---|
961 | A function's entry has a line for each of its subroutines--in other
|
---|
962 | words, a line for each other function that it called. These lines'
|
---|
963 | fields correspond to the fields of the primary line, but their meanings
|
---|
964 | are different because of the difference in context.
|
---|
965 |
|
---|
966 | For reference, we repeat two lines from the entry for the function
|
---|
967 | `main', the primary line and a line for a subroutine, together with the
|
---|
968 | heading line that shows the names of the fields:
|
---|
969 |
|
---|
970 | index % time self children called name
|
---|
971 | ...
|
---|
972 | [2] 100.0 0.00 0.05 1 main [2]
|
---|
973 | 0.00 0.05 1/1 report [3]
|
---|
974 |
|
---|
975 | Here are the meanings of the fields in the subroutine-line for `main'
|
---|
976 | calling `report':
|
---|
977 |
|
---|
978 | `self'
|
---|
979 | An estimate of the amount of time spent directly within `report'
|
---|
980 | when `report' was called from `main'.
|
---|
981 |
|
---|
982 | `children'
|
---|
983 | An estimate of the amount of time spent in subroutines of `report'
|
---|
984 | when `report' was called from `main'.
|
---|
985 |
|
---|
986 | The sum of the `self' and `children' fields is an estimate of the
|
---|
987 | total time spent in calls to `report' from `main'.
|
---|
988 |
|
---|
989 | `called'
|
---|
990 | Two numbers, the number of calls to `report' from `main' followed
|
---|
991 | by the total number of non-recursive calls to `report'. This
|
---|
992 | ratio is used to determine how much of `report''s `self' and
|
---|
993 | `children' time gets credited to `main'. *Note Assumptions::.
|
---|
994 |
|
---|
995 | `name'
|
---|
996 | The name of the subroutine of `main' to which this line applies,
|
---|
997 | followed by the subroutine's index number.
|
---|
998 |
|
---|
999 | If the caller is part of a recursion cycle, the cycle number is
|
---|
1000 | printed between the name and the index number.
|
---|
1001 |
|
---|
1002 |
|
---|
1003 | File: gprof.info, Node: Cycles, Prev: Subroutines, Up: Call Graph
|
---|
1004 |
|
---|
1005 | How Mutually Recursive Functions Are Described
|
---|
1006 | ----------------------------------------------
|
---|
1007 |
|
---|
1008 | The graph may be complicated by the presence of "cycles of
|
---|
1009 | recursion" in the call graph. A cycle exists if a function calls
|
---|
1010 | another function that (directly or indirectly) calls (or appears to
|
---|
1011 | call) the original function. For example: if `a' calls `b', and `b'
|
---|
1012 | calls `a', then `a' and `b' form a cycle.
|
---|
1013 |
|
---|
1014 | Whenever there are call paths both ways between a pair of functions,
|
---|
1015 | they belong to the same cycle. If `a' and `b' call each other and `b'
|
---|
1016 | and `c' call each other, all three make one cycle. Note that even if
|
---|
1017 | `b' only calls `a' if it was not called from `a', `gprof' cannot
|
---|
1018 | determine this, so `a' and `b' are still considered a cycle.
|
---|
1019 |
|
---|
1020 | The cycles are numbered with consecutive integers. When a function
|
---|
1021 | belongs to a cycle, each time the function name appears in the call
|
---|
1022 | graph it is followed by `<cycle NUMBER>'.
|
---|
1023 |
|
---|
1024 | The reason cycles matter is that they make the time values in the
|
---|
1025 | call graph paradoxical. The "time spent in children" of `a' should
|
---|
1026 | include the time spent in its subroutine `b' and in `b''s
|
---|
1027 | subroutines--but one of `b''s subroutines is `a'! How much of `a''s
|
---|
1028 | time should be included in the children of `a', when `a' is indirectly
|
---|
1029 | recursive?
|
---|
1030 |
|
---|
1031 | The way `gprof' resolves this paradox is by creating a single entry
|
---|
1032 | for the cycle as a whole. The primary line of this entry describes the
|
---|
1033 | total time spent directly in the functions of the cycle. The
|
---|
1034 | "subroutines" of the cycle are the individual functions of the cycle,
|
---|
1035 | and all other functions that were called directly by them. The
|
---|
1036 | "callers" of the cycle are the functions, outside the cycle, that
|
---|
1037 | called functions in the cycle.
|
---|
1038 |
|
---|
1039 | Here is an example portion of a call graph which shows a cycle
|
---|
1040 | containing functions `a' and `b'. The cycle was entered by a call to
|
---|
1041 | `a' from `main'; both `a' and `b' called `c'.
|
---|
1042 |
|
---|
1043 | index % time self children called name
|
---|
1044 | ----------------------------------------
|
---|
1045 | 1.77 0 1/1 main [2]
|
---|
1046 | [3] 91.71 1.77 0 1+5 <cycle 1 as a whole> [3]
|
---|
1047 | 1.02 0 3 b <cycle 1> [4]
|
---|
1048 | 0.75 0 2 a <cycle 1> [5]
|
---|
1049 | ----------------------------------------
|
---|
1050 | 3 a <cycle 1> [5]
|
---|
1051 | [4] 52.85 1.02 0 0 b <cycle 1> [4]
|
---|
1052 | 2 a <cycle 1> [5]
|
---|
1053 | 0 0 3/6 c [6]
|
---|
1054 | ----------------------------------------
|
---|
1055 | 1.77 0 1/1 main [2]
|
---|
1056 | 2 b <cycle 1> [4]
|
---|
1057 | [5] 38.86 0.75 0 1 a <cycle 1> [5]
|
---|
1058 | 3 b <cycle 1> [4]
|
---|
1059 | 0 0 3/6 c [6]
|
---|
1060 | ----------------------------------------
|
---|
1061 |
|
---|
1062 | (The entire call graph for this program contains in addition an entry
|
---|
1063 | for `main', which calls `a', and an entry for `c', with callers `a' and
|
---|
1064 | `b'.)
|
---|
1065 |
|
---|
1066 | index % time self children called name
|
---|
1067 | <spontaneous>
|
---|
1068 | [1] 100.00 0 1.93 0 start [1]
|
---|
1069 | 0.16 1.77 1/1 main [2]
|
---|
1070 | ----------------------------------------
|
---|
1071 | 0.16 1.77 1/1 start [1]
|
---|
1072 | [2] 100.00 0.16 1.77 1 main [2]
|
---|
1073 | 1.77 0 1/1 a <cycle 1> [5]
|
---|
1074 | ----------------------------------------
|
---|
1075 | 1.77 0 1/1 main [2]
|
---|
1076 | [3] 91.71 1.77 0 1+5 <cycle 1 as a whole> [3]
|
---|
1077 | 1.02 0 3 b <cycle 1> [4]
|
---|
1078 | 0.75 0 2 a <cycle 1> [5]
|
---|
1079 | 0 0 6/6 c [6]
|
---|
1080 | ----------------------------------------
|
---|
1081 | 3 a <cycle 1> [5]
|
---|
1082 | [4] 52.85 1.02 0 0 b <cycle 1> [4]
|
---|
1083 | 2 a <cycle 1> [5]
|
---|
1084 | 0 0 3/6 c [6]
|
---|
1085 | ----------------------------------------
|
---|
1086 | 1.77 0 1/1 main [2]
|
---|
1087 | 2 b <cycle 1> [4]
|
---|
1088 | [5] 38.86 0.75 0 1 a <cycle 1> [5]
|
---|
1089 | 3 b <cycle 1> [4]
|
---|
1090 | 0 0 3/6 c [6]
|
---|
1091 | ----------------------------------------
|
---|
1092 | 0 0 3/6 b <cycle 1> [4]
|
---|
1093 | 0 0 3/6 a <cycle 1> [5]
|
---|
1094 | [6] 0.00 0 0 6 c [6]
|
---|
1095 | ----------------------------------------
|
---|
1096 |
|
---|
1097 | The `self' field of the cycle's primary line is the total time spent
|
---|
1098 | in all the functions of the cycle. It equals the sum of the `self'
|
---|
1099 | fields for the individual functions in the cycle, found in the entry in
|
---|
1100 | the subroutine lines for these functions.
|
---|
1101 |
|
---|
1102 | The `children' fields of the cycle's primary line and subroutine
|
---|
1103 | lines count only subroutines outside the cycle. Even though `a' calls
|
---|
1104 | `b', the time spent in those calls to `b' is not counted in `a''s
|
---|
1105 | `children' time. Thus, we do not encounter the problem of what to do
|
---|
1106 | when the time in those calls to `b' includes indirect recursive calls
|
---|
1107 | back to `a'.
|
---|
1108 |
|
---|
1109 | The `children' field of a caller-line in the cycle's entry estimates
|
---|
1110 | the amount of time spent _in the whole cycle_, and its other
|
---|
1111 | subroutines, on the times when that caller called a function in the
|
---|
1112 | cycle.
|
---|
1113 |
|
---|
1114 | The `calls' field in the primary line for the cycle has two numbers:
|
---|
1115 | first, the number of times functions in the cycle were called by
|
---|
1116 | functions outside the cycle; second, the number of times they were
|
---|
1117 | called by functions in the cycle (including times when a function in
|
---|
1118 | the cycle calls itself). This is a generalization of the usual split
|
---|
1119 | into non-recursive and recursive calls.
|
---|
1120 |
|
---|
1121 | The `calls' field of a subroutine-line for a cycle member in the
|
---|
1122 | cycle's entry says how many time that function was called from
|
---|
1123 | functions in the cycle. The total of all these is the second number in
|
---|
1124 | the primary line's `calls' field.
|
---|
1125 |
|
---|
1126 | In the individual entry for a function in a cycle, the other
|
---|
1127 | functions in the same cycle can appear as subroutines and as callers.
|
---|
1128 | These lines show how many times each function in the cycle called or
|
---|
1129 | was called from each other function in the cycle. The `self' and
|
---|
1130 | `children' fields in these lines are blank because of the difficulty of
|
---|
1131 | defining meanings for them when recursion is going on.
|
---|
1132 |
|
---|