1 This is gprof.info, produced by makeinfo version 4.0 from gprof.texi.
4 * gprof: (gprof). Profiling your program's execution
7 This file documents the gprof profiler of the GNU system.
9 Copyright (C) 1988, 92, 97, 98, 99, 2000 Free Software Foundation,
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
14 or any later version published by the Free Software Foundation;
15 with no Invariant Sections, with no Front-Cover Texts, and with no
16 Back-Cover Texts. A copy of the license is included in the
17 section entitled "GNU Free Documentation License".
20 File: gprof.info, Node: Top, Next: Introduction, Up: (dir)
22 Profiling a Program: Where Does It Spend Its Time?
23 **************************************************
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.
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".
36 * Introduction:: What profiling means, and why it is useful.
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
42 * Output:: Interpreting `gprof''s output
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
51 File: gprof.info, Node: Introduction, Next: Compiling, Prev: Top, Up: Top
53 Introduction to Profiling
54 *************************
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.
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
72 Profiling has several steps:
74 * You must compile and link your program with profiling enabled.
77 * You must execute your program to generate a profile data file.
80 * You must run `gprof' to analyze the profile data. *Note
83 The next three chapters explain these steps in greater detail.
85 Several forms of output are available from the analysis.
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::.
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::.
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::.
102 To better understand how profiling works, you may wish to read a
103 description of its implementation. *Note Implementation::.
106 File: gprof.info, Node: Compiling, Next: Executing, Prev: Introduction, Up: Top
108 Compiling a Program for Profiling
109 *********************************
111 The first step in generating profile information for your program is
112 to compile and link it with profiling enabled.
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
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:
123 cc -g -c myprog.c utils.c -pg
124 cc -o myprog myprog.o utils.o -pg
126 The `-pg' option also works with a command that both compiles and
129 cc -o myprog myprog.c utils.c -g -pg
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:
140 ld -o myprog /lib/gcrt0.o myprog.o utils.o -lc_p
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.
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::.
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.
165 File: gprof.info, Node: Executing, Next: Invoking, Prev: Compiling, Up: Top
167 Executing the Program
168 *********************
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.
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.
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
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.
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.
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'.
211 File: gprof.info, Node: Invoking, Next: Output, Prev: Executing, Up: Top
213 `gprof' Command Summary
214 ***********************
216 After you have a profile data file `gmon.out', you can run `gprof'
217 to interpret the information in it. The `gprof' program prints a flat
218 profile and a call graph on standard output. Typically you would
219 redirect the output of `gprof' into a file with `>'.
221 You run `gprof' like this:
223 gprof OPTIONS [EXECUTABLE-FILE [PROFILE-DATA-FILES...]] [> OUTFILE]
225 Here square-brackets indicate optional arguments.
227 If you omit the executable file name, the file `a.out' is used. If
228 you give no profile data file name, the file `gmon.out' is used. If
229 any file is not in the proper format, or if the profile data file does
230 not appear to belong to the executable file, an error message is
233 You can give more than one profile data file by entering all their
234 names after the executable file name; then the statistics in all the
235 data files are summed together.
237 The order of these options does not matter.
241 * Output Options:: Controlling `gprof''s output style
242 * Analysis Options:: Controlling how `gprof' analyses its data
243 * Miscellaneous Options::
244 * Deprecated Options:: Options you no longer need to use, but which
245 have been retained for compatibility
246 * Symspecs:: Specifying functions to include or exclude
249 File: gprof.info, Node: Output Options, Next: Analysis Options, Up: Invoking
254 These options specify which of several output formats `gprof' should
257 Many of these options take an optional "symspec" to specify
258 functions to be included or excluded. These options can be specified
259 multiple times, with different symspecs, to include or exclude sets of
260 symbols. *Note Symspecs::.
262 Specifying any of these options overrides the default (`-p -q'),
263 which prints a flat profile and call graph analysis for all functions.
266 `--annotated-source[=SYMSPEC]'
267 The `-A' option causes `gprof' to print annotated source code. If
268 SYMSPEC is specified, print output only for matching symbols.
269 *Note Annotated Source::.
273 If the `-b' option is given, `gprof' doesn't print the verbose
274 blurbs that try to explain the meaning of all of the fields in the
275 tables. This is useful if you intend to print out the output, or
276 are tired of seeing the blurbs.
279 `--exec-counts[=SYMSPEC]'
280 The `-C' option causes `gprof' to print a tally of functions and
281 the number of times each was called. If SYMSPEC is specified,
282 print tally only for matching symbols.
284 If the profile data file contains basic-block count records,
285 specifying the `-l' option, along with `-C', will cause basic-block
286 execution counts to be tallied and displayed.
290 The `-i' option causes `gprof' to display summary information
291 about the profile data file(s) and then exit. The number of
292 histogram, call graph, and basic-block count records is displayed.
295 `--directory-path=DIRS'
296 The `-I' option specifies a list of search directories in which to
297 find source files. Environment variable GPROF_PATH can also be
298 used to convey this information. Used mostly for annotated source
302 `--no-annotated-source[=SYMSPEC]'
303 The `-J' option causes `gprof' not to print annotated source code.
304 If SYMSPEC is specified, `gprof' prints annotated source, but
305 excludes matching symbols.
309 Normally, source filenames are printed with the path component
310 suppressed. The `-L' option causes `gprof' to print the full
311 pathname of source filenames, which is determined from symbolic
312 debugging information in the image file and is relative to the
313 directory in which the compiler was invoked.
316 `--flat-profile[=SYMSPEC]'
317 The `-p' option causes `gprof' to print a flat profile. If
318 SYMSPEC is specified, print flat profile only for matching symbols.
319 *Note Flat Profile::.
322 `--no-flat-profile[=SYMSPEC]'
323 The `-P' option causes `gprof' to suppress printing a flat profile.
324 If SYMSPEC is specified, `gprof' prints a flat profile, but
325 excludes matching symbols.
329 The `-q' option causes `gprof' to print the call graph analysis.
330 If SYMSPEC is specified, print call graph only for matching symbols
331 and their children. *Note Call Graph::.
334 `--no-graph[=SYMSPEC]'
335 The `-Q' option causes `gprof' to suppress printing the call graph.
336 If SYMSPEC is specified, `gprof' prints a call graph, but excludes
341 This option affects annotated source output only. Normally,
342 `gprof' prints annotated source files to standard-output. If this
343 option is specified, annotated source for a file named
344 `path/FILENAME' is generated in the file `FILENAME-ann'. If the
345 underlying filesystem would truncate `FILENAME-ann' so that it
346 overwrites the original `FILENAME', `gprof' generates annotated
347 source in the file `FILENAME.ann' instead (if the original file
348 name has an extension, that extension is _replaced_ with `.ann').
351 `--no-exec-counts[=SYMSPEC]'
352 The `-Z' option causes `gprof' not to print a tally of functions
353 and the number of times each was called. If SYMSPEC is specified,
354 print tally, but exclude matching symbols.
356 `--function-ordering'
357 The `--function-ordering' option causes `gprof' to print a
358 suggested function ordering for the program based on profiling
359 data. This option suggests an ordering which may improve paging,
360 tlb and cache behavior for the program on systems which support
361 arbitrary ordering of functions in an executable.
363 The exact details of how to force the linker to place functions in
364 a particular order is system dependent and out of the scope of this
367 `--file-ordering MAP_FILE'
368 The `--file-ordering' option causes `gprof' to print a suggested
369 .o link line ordering for the program based on profiling data.
370 This option suggests an ordering which may improve paging, tlb and
371 cache behavior for the program on systems which do not support
372 arbitrary ordering of functions in an executable.
374 Use of the `-a' argument is highly recommended with this option.
376 The MAP_FILE argument is a pathname to a file which provides
377 function name to object file mappings. The format of the file is
378 similar to the output of the program `nm'.
380 c-parse.o:00000000 T yyparse
381 c-parse.o:00000004 C yyerrflag
382 c-lang.o:00000000 T maybe_objc_method_name
383 c-lang.o:00000000 T print_lang_statistics
384 c-lang.o:00000000 T recognize_objc_keyword
385 c-decl.o:00000000 T print_lang_identifier
386 c-decl.o:00000000 T print_lang_type
389 To create a MAP_FILE with GNU `nm', type a command like `nm
390 --extern-only --defined-only -v --print-file-name program-name'.
394 The `-T' option causes `gprof' to print its output in
395 "traditional" BSD style.
399 Sets width of output lines to WIDTH. Currently only used when
400 printing the function index at the bottom of the call graph.
404 This option affects annotated source output only. By default,
405 only the lines at the beginning of a basic-block are annotated.
406 If this option is specified, every line in a basic-block is
407 annotated by repeating the annotation for the first line. This
408 behavior is similar to `tcov''s `-a'.
412 These options control whether C++ symbol names should be demangled
413 when printing output. The default is to demangle symbols. The
414 `--no-demangle' option may be used to turn off demangling.
415 Different compilers have different mangling styles. The optional
416 demangling style argument can be used to choose an appropriate
417 demangling style for your compiler.
420 File: gprof.info, Node: Analysis Options, Next: Miscellaneous Options, Prev: Output Options, Up: Invoking
427 The `-a' option causes `gprof' to suppress the printing of
428 statically declared (private) functions. (These are functions
429 whose names are not listed as global, and which are not visible
430 outside the file/function/block where they were defined.) Time
431 spent in these functions, calls to/from them, etc, will all be
432 attributed to the function that was loaded directly before it in
433 the executable file. This option affects both the flat profile
437 `--static-call-graph'
438 The `-c' option causes the call graph of the program to be
439 augmented by a heuristic which examines the text space of the
440 object file and identifies function calls in the binary machine
441 code. Since normal call graph records are only generated when
442 functions are entered, this option identifies children that could
443 have been called, but never were. Calls to functions that were
444 not compiled with profiling enabled are also identified, but only
445 if symbol table entries are present for them. Calls to dynamic
446 library routines are typically _not_ found by this option.
447 Parents or children identified via this heuristic are indicated in
448 the call graph with call counts of `0'.
451 `--ignore-non-functions'
452 The `-D' option causes `gprof' to ignore symbols which are not
453 known to be functions. This option will give more accurate
454 profile data on systems where it is supported (Solaris and HPUX for
458 The `-k' option allows you to delete from the call graph any arcs
459 from symbols matching symspec FROM to those matching symspec TO.
463 The `-l' option enables line-by-line profiling, which causes
464 histogram hits to be charged to individual source code lines,
465 instead of functions. If the program was compiled with
466 basic-block counting enabled, this option will also identify how
467 many times each line of code was executed. While line-by-line
468 profiling can help isolate where in a large function a program is
469 spending its time, it also significantly increases the running
470 time of `gprof', and magnifies statistical inaccuracies. *Note
475 This option affects execution count output only. Symbols that are
476 executed less than NUM times are suppressed.
480 The `-n' option causes `gprof', in its call graph analysis, to
481 only propagate times for symbols matching SYMSPEC.
484 `--no-time[=SYMSPEC]'
485 The `-n' option causes `gprof', in its call graph analysis, not to
486 propagate times for symbols matching SYMSPEC.
489 `--display-unused-functions'
490 If you give the `-z' option, `gprof' will mention all functions in
491 the flat profile, even those that were never called, and that had
492 no time spent in them. This is useful in conjunction with the
493 `-c' option for discovering which routines were never called.
496 File: gprof.info, Node: Miscellaneous Options, Next: Deprecated Options, Prev: Analysis Options, Up: Invoking
498 Miscellaneous Options
499 =====================
503 The `-d NUM' option specifies debugging options. If NUM is not
504 specified, enable all debugging. *Note Debugging::.
508 Selects the format of the profile data files. Recognized formats
509 are `auto' (the default), `bsd', `4.4bsd', `magic', and `prof'
514 The `-s' option causes `gprof' to summarize the information in the
515 profile data files it read in, and write out a profile data file
516 called `gmon.sum', which contains all the information from the
517 profile data files that `gprof' read in. The file `gmon.sum' may
518 be one of the specified input files; the effect of this is to
519 merge the data in the other input files into `gmon.sum'.
521 Eventually you can run `gprof' again without `-s' to analyze the
522 cumulative data in the file `gmon.sum'.
526 The `-v' flag causes `gprof' to print the current version number,
530 File: gprof.info, Node: Deprecated Options, Next: Symspecs, Prev: Miscellaneous Options, Up: Invoking
535 These options have been replaced with newer versions that use
539 The `-e FUNCTION' option tells `gprof' to not print information
540 about the function FUNCTION_NAME (and its children...) in the call
541 graph. The function will still be listed as a child of any
542 functions that call it, but its index number will be shown as
543 `[not printed]'. More than one `-e' option may be given; only one
544 FUNCTION_NAME may be indicated with each `-e' option.
547 The `-E FUNCTION' option works like the `-e' option, but time
548 spent in the function (and children who were not called from
549 anywhere else), will not be used to compute the
550 percentages-of-time for the call graph. More than one `-E' option
551 may be given; only one FUNCTION_NAME may be indicated with each
555 The `-f FUNCTION' option causes `gprof' to limit the call graph to
556 the function FUNCTION_NAME and its children (and their
557 children...). More than one `-f' option may be given; only one
558 FUNCTION_NAME may be indicated with each `-f' option.
561 The `-F FUNCTION' option works like the `-f' option, but only time
562 spent in the function and its children (and their children...)
563 will be used to determine total-time and percentages-of-time for
564 the call graph. More than one `-F' option may be given; only one
565 FUNCTION_NAME may be indicated with each `-F' option. The `-F'
566 option overrides the `-E' option.
568 Note that only one function can be specified with each `-e', `-E',
569 `-f' or `-F' option. To specify more than one function, use multiple
570 options. For example, this command:
572 gprof -e boring -f foo -f bar myprogram > gprof.output
574 lists in the call graph all functions that were reached from either
575 `foo' or `bar' and were not reachable from `boring'.
578 File: gprof.info, Node: Symspecs, Prev: Deprecated Options, Up: Invoking
583 Many of the output options allow functions to be included or excluded
584 using "symspecs" (symbol specifications), which observe the following
587 filename_containing_a_dot
588 | funcname_not_containing_a_dot
590 | ( [ any_filename ] `:' ( any_funcname | linenumber ) )
592 Here are some sample symspecs:
595 Selects everything in file `main.c'--the dot in the string tells
596 `gprof' to interpret the string as a filename, rather than as a
597 function name. To select a file whose name does not contain a
598 dot, a trailing colon should be specified. For example, `odd:' is
599 interpreted as the file named `odd'.
602 Selects all functions named `main'.
604 Note that there may be multiple instances of the same function name
605 because some of the definitions may be local (i.e., static).
606 Unless a function name is unique in a program, you must use the
607 colon notation explained below to specify a function from a
608 specific source file.
610 Sometimes, function names contain dots. In such cases, it is
611 necessary to add a leading colon to the name. For example,
612 `:.mul' selects function `.mul'.
614 In some object file formats, symbols have a leading underscore.
615 `gprof' will normally not print these underscores. When you name a
616 symbol in a symspec, you should type it exactly as `gprof' prints
617 it in its output. For example, if the compiler produces a symbol
618 `_main' from your `main' function, `gprof' still prints it as
619 `main' in its output, so you should use `main' in symspecs.
622 Selects function `main' in file `main.c'.
625 Selects line 134 in file `main.c'.
628 File: gprof.info, Node: Output, Next: Inaccuracy, Prev: Invoking, Up: Top
630 Interpreting `gprof''s Output
631 *****************************
633 `gprof' can produce several different output styles, the most
634 important of which are described below. The simplest output styles
635 (file information, execution count, and function and file ordering) are
636 not described here, but are documented with the respective options that
637 trigger them. *Note Output Options::.
641 * Flat Profile:: The flat profile shows how much time was spent
642 executing directly in each function.
643 * Call Graph:: The call graph shows which functions called which
644 others, and how much time each function used
645 when its subroutine calls are included.
646 * Line-by-line:: `gprof' can analyze individual source code lines
647 * Annotated Source:: The annotated source listing displays source code
648 labeled with execution counts
651 File: gprof.info, Node: Flat Profile, Next: Call Graph, Up: Output
656 The "flat profile" shows the total amount of time your program spent
657 executing each function. Unless the `-z' option is given, functions
658 with no apparent time spent in them, and no apparent calls to them, are
659 not mentioned. Note that if a function was not compiled for profiling,
660 and didn't run long enough to show up on the program counter histogram,
661 it will be indistinguishable from a function that was never called.
663 This is part of a flat profile for a small program:
667 Each sample counts as 0.01 seconds.
668 % cumulative self self total
669 time seconds seconds calls ms/call ms/call name
670 33.34 0.02 0.02 7208 0.00 0.00 open
671 16.67 0.03 0.01 244 0.04 0.12 offtime
672 16.67 0.04 0.01 8 1.25 1.25 memccpy
673 16.67 0.05 0.01 7 1.43 1.43 write
674 16.67 0.06 0.01 mcount
675 0.00 0.06 0.00 236 0.00 0.00 tzset
676 0.00 0.06 0.00 192 0.00 0.00 tolower
677 0.00 0.06 0.00 47 0.00 0.00 strlen
678 0.00 0.06 0.00 45 0.00 0.00 strchr
679 0.00 0.06 0.00 1 0.00 50.00 main
680 0.00 0.06 0.00 1 0.00 0.00 memcpy
681 0.00 0.06 0.00 1 0.00 10.11 print
682 0.00 0.06 0.00 1 0.00 0.00 profil
683 0.00 0.06 0.00 1 0.00 50.00 report
686 The functions are sorted by first by decreasing run-time spent in them,
687 then by decreasing number of calls, then alphabetically by name. The
688 functions `mcount' and `profil' are part of the profiling apparatus and
689 appear in every flat profile; their time gives a measure of the amount
690 of overhead due to profiling.
692 Just before the column headers, a statement appears indicating how
693 much time each sample counted as. This "sampling period" estimates the
694 margin of error in each of the time figures. A time figure that is not
695 much larger than this is not reliable. In this example, each sample
696 counted as 0.01 seconds, suggesting a 100 Hz sampling rate. The
697 program's total execution time was 0.06 seconds, as indicated by the
698 `cumulative seconds' field. Since each sample counted for 0.01
699 seconds, this means only six samples were taken during the run. Two of
700 the samples occurred while the program was in the `open' function, as
701 indicated by the `self seconds' field. Each of the other four samples
702 occurred one each in `offtime', `memccpy', `write', and `mcount'.
703 Since only six samples were taken, none of these values can be regarded
704 as particularly reliable. In another run, the `self seconds' field for
705 `mcount' might well be `0.00' or `0.02'. *Note Sampling Error::, for a
708 The remaining functions in the listing (those whose `self seconds'
709 field is `0.00') didn't appear in the histogram samples at all.
710 However, the call graph indicated that they were called, so therefore
711 they are listed, sorted in decreasing order by the `calls' field.
712 Clearly some time was spent executing these functions, but the paucity
713 of histogram samples prevents any determination of how much time each
716 Here is what the fields in each line mean:
719 This is the percentage of the total execution time your program
720 spent in this function. These should all add up to 100%.
723 This is the cumulative total number of seconds the computer spent
724 executing this functions, plus the time spent in all the functions
725 above this one in this table.
728 This is the number of seconds accounted for by this function alone.
729 The flat profile listing is sorted first by this number.
732 This is the total number of times the function was called. If the
733 function was never called, or the number of times it was called
734 cannot be determined (probably because the function was not
735 compiled with profiling enabled), the "calls" field is blank.
738 This represents the average number of milliseconds spent in this
739 function per call, if this function is profiled. Otherwise, this
740 field is blank for this function.
743 This represents the average number of milliseconds spent in this
744 function and its descendants per call, if this function is
745 profiled. Otherwise, this field is blank for this function. This
746 is the only field in the flat profile that uses call graph
750 This is the name of the function. The flat profile is sorted by
751 this field alphabetically after the "self seconds" and "calls"
755 File: gprof.info, Node: Call Graph, Next: Line-by-line, Prev: Flat Profile, Up: Output
760 The "call graph" shows how much time was spent in each function and
761 its children. From this information, you can find functions that,
762 while they themselves may not have used much time, called other
763 functions that did use unusual amounts of time.
765 Here is a sample call from a small program. This call came from the
766 same `gprof' run as the flat profile example in the previous chapter.
768 granularity: each sample hit covers 2 byte(s) for 20.00% of 0.05 seconds
770 index % time self children called name
772 [1] 100.0 0.00 0.05 start [1]
773 0.00 0.05 1/1 main [2]
774 0.00 0.00 1/2 on_exit [28]
775 0.00 0.00 1/1 exit [59]
776 -----------------------------------------------
777 0.00 0.05 1/1 start [1]
778 [2] 100.0 0.00 0.05 1 main [2]
779 0.00 0.05 1/1 report [3]
780 -----------------------------------------------
781 0.00 0.05 1/1 main [2]
782 [3] 100.0 0.00 0.05 1 report [3]
783 0.00 0.03 8/8 timelocal [6]
784 0.00 0.01 1/1 print [9]
785 0.00 0.01 9/9 fgets [12]
786 0.00 0.00 12/34 strncmp <cycle 1> [40]
787 0.00 0.00 8/8 lookup [20]
788 0.00 0.00 1/1 fopen [21]
789 0.00 0.00 8/8 chewtime [24]
790 0.00 0.00 8/16 skipspace [44]
791 -----------------------------------------------
792 [4] 59.8 0.01 0.02 8+472 <cycle 2 as a whole> [4]
793 0.01 0.02 244+260 offtime <cycle 2> [7]
794 0.00 0.00 236+1 tzset <cycle 2> [26]
795 -----------------------------------------------
797 The lines full of dashes divide this table into "entries", one for
798 each function. Each entry has one or more lines.
800 In each entry, the primary line is the one that starts with an index
801 number in square brackets. The end of this line says which function
802 the entry is for. The preceding lines in the entry describe the
803 callers of this function and the following lines describe its
804 subroutines (also called "children" when we speak of the call graph).
806 The entries are sorted by time spent in the function and its
809 The internal profiling function `mcount' (*note Flat Profile::) is
810 never mentioned in the call graph.
814 * Primary:: Details of the primary line's contents.
815 * Callers:: Details of caller-lines' contents.
816 * Subroutines:: Details of subroutine-lines' contents.
817 * Cycles:: When there are cycles of recursion,
818 such as `a' calls `b' calls `a'...
821 File: gprof.info, Node: Primary, Next: Callers, Up: Call Graph
826 The "primary line" in a call graph entry is the line that describes
827 the function which the entry is about and gives the overall statistics
830 For reference, we repeat the primary line from the entry for function
831 `report' in our main example, together with the heading line that shows
832 the names of the fields:
834 index % time self children called name
836 [3] 100.0 0.00 0.05 1 report [3]
838 Here is what the fields in the primary line mean:
841 Entries are numbered with consecutive integers. Each function
842 therefore has an index number, which appears at the beginning of
845 Each cross-reference to a function, as a caller or subroutine of
846 another, gives its index number as well as its name. The index
847 number guides you if you wish to look for the entry for that
851 This is the percentage of the total time that was spent in this
852 function, including time spent in subroutines called from this
855 The time spent in this function is counted again for the callers of
856 this function. Therefore, adding up these percentages is
860 This is the total amount of time spent in this function. This
861 should be identical to the number printed in the `seconds' field
862 for this function in the flat profile.
865 This is the total amount of time spent in the subroutine calls
866 made by this function. This should be equal to the sum of all the
867 `self' and `children' entries of the children listed directly
871 This is the number of times the function was called.
873 If the function called itself recursively, there are two numbers,
874 separated by a `+'. The first number counts non-recursive calls,
875 and the second counts recursive calls.
877 In the example above, the function `report' was called once from
881 This is the name of the current function. The index number is
884 If the function is part of a cycle of recursion, the cycle number
885 is printed between the function's name and the index number (*note
886 Cycles::). For example, if function `gnurr' is part of cycle
887 number one, and has index number twelve, its primary line would be
893 File: gprof.info, Node: Callers, Next: Subroutines, Prev: Primary, Up: Call Graph
895 Lines for a Function's Callers
896 ------------------------------
898 A function's entry has a line for each function it was called by.
899 These lines' fields correspond to the fields of the primary line, but
900 their meanings are different because of the difference in context.
902 For reference, we repeat two lines from the entry for the function
903 `report', the primary line and one caller-line preceding it, together
904 with the heading line that shows the names of the fields:
906 index % time self children called name
908 0.00 0.05 1/1 main [2]
909 [3] 100.0 0.00 0.05 1 report [3]
911 Here are the meanings of the fields in the caller-line for `report'
915 An estimate of the amount of time spent in `report' itself when it
916 was called from `main'.
919 An estimate of the amount of time spent in subroutines of `report'
920 when `report' was called from `main'.
922 The sum of the `self' and `children' fields is an estimate of the
923 amount of time spent within calls to `report' from `main'.
926 Two numbers: the number of times `report' was called from `main',
927 followed by the total number of non-recursive calls to `report'
928 from all its callers.
930 `name and index number'
931 The name of the caller of `report' to which this line applies,
932 followed by the caller's index number.
934 Not all functions have entries in the call graph; some options to
935 `gprof' request the omission of certain functions. When a caller
936 has no entry of its own, it still has caller-lines in the entries
937 of the functions it calls.
939 If the caller is part of a recursion cycle, the cycle number is
940 printed between the name and the index number.
942 If the identity of the callers of a function cannot be determined, a
943 dummy caller-line is printed which has `<spontaneous>' as the "caller's
944 name" and all other fields blank. This can happen for signal handlers.
947 File: gprof.info, Node: Subroutines, Next: Cycles, Prev: Callers, Up: Call Graph
949 Lines for a Function's Subroutines
950 ----------------------------------
952 A function's entry has a line for each of its subroutines--in other
953 words, a line for each other function that it called. These lines'
954 fields correspond to the fields of the primary line, but their meanings
955 are different because of the difference in context.
957 For reference, we repeat two lines from the entry for the function
958 `main', the primary line and a line for a subroutine, together with the
959 heading line that shows the names of the fields:
961 index % time self children called name
963 [2] 100.0 0.00 0.05 1 main [2]
964 0.00 0.05 1/1 report [3]
966 Here are the meanings of the fields in the subroutine-line for `main'
970 An estimate of the amount of time spent directly within `report'
971 when `report' was called from `main'.
974 An estimate of the amount of time spent in subroutines of `report'
975 when `report' was called from `main'.
977 The sum of the `self' and `children' fields is an estimate of the
978 total time spent in calls to `report' from `main'.
981 Two numbers, the number of calls to `report' from `main' followed
982 by the total number of non-recursive calls to `report'. This
983 ratio is used to determine how much of `report''s `self' and
984 `children' time gets credited to `main'. *Note Assumptions::.
987 The name of the subroutine of `main' to which this line applies,
988 followed by the subroutine's index number.
990 If the caller is part of a recursion cycle, the cycle number is
991 printed between the name and the index number.
994 File: gprof.info, Node: Cycles, Prev: Subroutines, Up: Call Graph
996 How Mutually Recursive Functions Are Described
997 ----------------------------------------------
999 The graph may be complicated by the presence of "cycles of
1000 recursion" in the call graph. A cycle exists if a function calls
1001 another function that (directly or indirectly) calls (or appears to
1002 call) the original function. For example: if `a' calls `b', and `b'
1003 calls `a', then `a' and `b' form a cycle.
1005 Whenever there are call paths both ways between a pair of functions,
1006 they belong to the same cycle. If `a' and `b' call each other and `b'
1007 and `c' call each other, all three make one cycle. Note that even if
1008 `b' only calls `a' if it was not called from `a', `gprof' cannot
1009 determine this, so `a' and `b' are still considered a cycle.
1011 The cycles are numbered with consecutive integers. When a function
1012 belongs to a cycle, each time the function name appears in the call
1013 graph it is followed by `<cycle NUMBER>'.
1015 The reason cycles matter is that they make the time values in the
1016 call graph paradoxical. The "time spent in children" of `a' should
1017 include the time spent in its subroutine `b' and in `b''s
1018 subroutines--but one of `b''s subroutines is `a'! How much of `a''s
1019 time should be included in the children of `a', when `a' is indirectly
1022 The way `gprof' resolves this paradox is by creating a single entry
1023 for the cycle as a whole. The primary line of this entry describes the
1024 total time spent directly in the functions of the cycle. The
1025 "subroutines" of the cycle are the individual functions of the cycle,
1026 and all other functions that were called directly by them. The
1027 "callers" of the cycle are the functions, outside the cycle, that
1028 called functions in the cycle.
1030 Here is an example portion of a call graph which shows a cycle
1031 containing functions `a' and `b'. The cycle was entered by a call to
1032 `a' from `main'; both `a' and `b' called `c'.
1034 index % time self children called name
1035 ----------------------------------------
1037 [3] 91.71 1.77 0 1+5 <cycle 1 as a whole> [3]
1038 1.02 0 3 b <cycle 1> [4]
1039 0.75 0 2 a <cycle 1> [5]
1040 ----------------------------------------
1042 [4] 52.85 1.02 0 0 b <cycle 1> [4]
1045 ----------------------------------------
1048 [5] 38.86 0.75 0 1 a <cycle 1> [5]
1051 ----------------------------------------
1053 (The entire call graph for this program contains in addition an entry
1054 for `main', which calls `a', and an entry for `c', with callers `a' and
1057 index % time self children called name
1059 [1] 100.00 0 1.93 0 start [1]
1060 0.16 1.77 1/1 main [2]
1061 ----------------------------------------
1062 0.16 1.77 1/1 start [1]
1063 [2] 100.00 0.16 1.77 1 main [2]
1064 1.77 0 1/1 a <cycle 1> [5]
1065 ----------------------------------------
1067 [3] 91.71 1.77 0 1+5 <cycle 1 as a whole> [3]
1068 1.02 0 3 b <cycle 1> [4]
1069 0.75 0 2 a <cycle 1> [5]
1071 ----------------------------------------
1073 [4] 52.85 1.02 0 0 b <cycle 1> [4]
1076 ----------------------------------------
1079 [5] 38.86 0.75 0 1 a <cycle 1> [5]
1082 ----------------------------------------
1083 0 0 3/6 b <cycle 1> [4]
1084 0 0 3/6 a <cycle 1> [5]
1085 [6] 0.00 0 0 6 c [6]
1086 ----------------------------------------
1088 The `self' field of the cycle's primary line is the total time spent
1089 in all the functions of the cycle. It equals the sum of the `self'
1090 fields for the individual functions in the cycle, found in the entry in
1091 the subroutine lines for these functions.
1093 The `children' fields of the cycle's primary line and subroutine
1094 lines count only subroutines outside the cycle. Even though `a' calls
1095 `b', the time spent in those calls to `b' is not counted in `a''s
1096 `children' time. Thus, we do not encounter the problem of what to do
1097 when the time in those calls to `b' includes indirect recursive calls
1100 The `children' field of a caller-line in the cycle's entry estimates
1101 the amount of time spent _in the whole cycle_, and its other
1102 subroutines, on the times when that caller called a function in the
1105 The `calls' field in the primary line for the cycle has two numbers:
1106 first, the number of times functions in the cycle were called by
1107 functions outside the cycle; second, the number of times they were
1108 called by functions in the cycle (including times when a function in
1109 the cycle calls itself). This is a generalization of the usual split
1110 into non-recursive and recursive calls.
1112 The `calls' field of a subroutine-line for a cycle member in the
1113 cycle's entry says how many time that function was called from
1114 functions in the cycle. The total of all these is the second number in
1115 the primary line's `calls' field.
1117 In the individual entry for a function in a cycle, the other
1118 functions in the same cycle can appear as subroutines and as callers.
1119 These lines show how many times each function in the cycle called or
1120 was called from each other function in the cycle. The `self' and
1121 `children' fields in these lines are blank because of the difficulty of
1122 defining meanings for them when recursion is going on.