2001-05-28 Philip Blundell <philb@gnu.org>
[binutils.git] / gprof / gprof.info-1
blobf3d2de93dfa93fc45f2605863cd0bc95e114ad68
1 This is gprof.info, produced by makeinfo version 4.0 from gprof.texi.
3 START-INFO-DIR-ENTRY
4 * gprof: (gprof).                Profiling your program's execution
5 END-INFO-DIR-ENTRY
7    This file documents the gprof profiler of the GNU system.
9    Copyright (C) 1988, 92, 97, 98, 99, 2000 Free Software Foundation,
10 Inc.
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".
19 \x1f
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".
34 * Menu:
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
50 \x1f
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
70 feature.
72    Profiling has several steps:
74    * You must compile and link your program with profiling enabled.
75      *Note Compiling::.
77    * You must execute your program to generate a profile data file.
78      *Note Executing::.
80    * You must run `gprof' to analyze the profile data.  *Note
81      Invoking::.
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::.
105 \x1f
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
116 use.)
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
127 links:
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.
164 \x1f
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
189 overwritten.
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'.
210 \x1f
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
231 printed.
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.
239 * Menu:
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
248 \x1f
249 File: gprof.info,  Node: Output Options,  Next: Analysis Options,  Up: Invoking
251 Output Options
252 ==============
254    These options specify which of several output formats `gprof' should
255 produce.
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.
265 `-A[SYMSPEC]'
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::.
271 `-b'
272 `--brief'
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.
278 `-C[SYMSPEC]'
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.
288 `-i'
289 `--file-info'
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.
294 `-I DIRS'
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
299      output.
301 `-J[SYMSPEC]'
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.
307 `-L'
308 `--print-path'
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.
315 `-p[SYMSPEC]'
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::.
321 `-P[SYMSPEC]'
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.
327 `-q[SYMSPEC]'
328 `--graph[=SYMSPEC]'
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::.
333 `-Q[SYMSPEC]'
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
337      matching symbols.
339 `-y'
340 `--separate-files'
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').
350 `-Z[SYMSPEC]'
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
365      manual.
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
387           ...
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'.
392 `-T'
393 `--traditional'
394      The `-T' option causes `gprof' to print its output in
395      "traditional" BSD style.
397 `-w WIDTH'
398 `--width=WIDTH'
399      Sets width of output lines to WIDTH.  Currently only used when
400      printing the function index at the bottom of the call graph.
402 `-x'
403 `--all-lines'
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'.
410 `--demangle[=STYLE]'
411 `--no-demangle'
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.
419 \x1f
420 File: gprof.info,  Node: Analysis Options,  Next: Miscellaneous Options,  Prev: Output Options,  Up: Invoking
422 Analysis Options
423 ================
425 `-a'
426 `--no-static'
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
434      and the call graph.
436 `-c'
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'.
450 `-D'
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
455      example).
457 `-k FROM/TO'
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.
461 `-l'
462 `--line'
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
471      Sampling Error::.
473 `-m NUM'
474 `--min-count=NUM'
475      This option affects execution count output only.  Symbols that are
476      executed less than NUM times are suppressed.
478 `-n[SYMSPEC]'
479 `--time[=SYMSPEC]'
480      The `-n' option causes `gprof', in its call graph analysis, to
481      only propagate times for symbols matching SYMSPEC.
483 `-N[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.
488 `-z'
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.
495 \x1f
496 File: gprof.info,  Node: Miscellaneous Options,  Next: Deprecated Options,  Prev: Analysis Options,  Up: Invoking
498 Miscellaneous Options
499 =====================
501 `-d[NUM]'
502 `--debug[=NUM]'
503      The `-d NUM' option specifies debugging options.  If NUM is not
504      specified, enable all debugging.  *Note Debugging::.
506 `-ONAME'
507 `--file-format=NAME'
508      Selects the format of the profile data files.  Recognized formats
509      are `auto' (the default), `bsd', `4.4bsd', `magic', and `prof'
510      (not yet supported).
512 `-s'
513 `--sum'
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'.
524 `-v'
525 `--version'
526      The `-v' flag causes `gprof' to print the current version number,
527      and then exit.
529 \x1f
530 File: gprof.info,  Node: Deprecated Options,  Next: Symspecs,  Prev: Miscellaneous Options,  Up: Invoking
532 Deprecated Options
533 ==================
535      These options have been replaced with newer versions that use
536      symspecs.
538 `-e FUNCTION_NAME'
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.
546 `-E FUNCTION_NAME'
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
552      `-E' option.
554 `-f FUNCTION_NAME'
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.
560 `-F FUNCTION_NAME'
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'.
577 \x1f
578 File: gprof.info,  Node: Symspecs,  Prev: Deprecated Options,  Up: Invoking
580 Symspecs
581 ========
583    Many of the output options allow functions to be included or excluded
584 using "symspecs" (symbol specifications), which observe the following
585 syntax:
587        filename_containing_a_dot
588      | funcname_not_containing_a_dot
589      | linenumber
590      | ( [ any_filename ] `:' ( any_funcname | linenumber ) )
592    Here are some sample symspecs:
594 `main.c'
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'.
601 `main'
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.
621 `main.c:main'
622      Selects function `main' in file `main.c'.
624 `main.c:134'
625      Selects line 134 in file `main.c'.
627 \x1f
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::.
639 * Menu:
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
650 \x1f
651 File: gprof.info,  Node: Flat Profile,  Next: Call Graph,  Up: Output
653 The Flat Profile
654 ================
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:
665      Flat profile:
666      
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
684      ...
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
706 complete discussion.
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
714 took.
716    Here is what the fields in each line mean:
718 `% time'
719      This is the percentage of the total execution time your program
720      spent in this function.  These should all add up to 100%.
722 `cumulative seconds'
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.
727 `self seconds'
728      This is the number of seconds accounted for by this function alone.
729      The flat profile listing is sorted first by this number.
731 `calls'
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.
737 `self ms/call'
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.
742 `total ms/call'
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
747      analysis.
749 `name'
750      This is the name of the function.   The flat profile is sorted by
751      this field alphabetically after the "self seconds" and "calls"
752      fields are sorted.
754 \x1f
755 File: gprof.info,  Node: Call Graph,  Next: Line-by-line,  Prev: Flat Profile,  Up: Output
757 The Call Graph
758 ==============
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
769      
770      index % time    self  children    called     name
771                                                       <spontaneous>
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
807 subroutines.
809    The internal profiling function `mcount' (*note Flat Profile::) is
810 never mentioned in the call graph.
812 * Menu:
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'...
820 \x1f
821 File: gprof.info,  Node: Primary,  Next: Callers,  Up: Call Graph
823 The Primary Line
824 ----------------
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
828 for this function.
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
835      ...
836      [3]    100.0    0.00    0.05       1         report [3]
838    Here is what the fields in the primary line mean:
840 `index'
841      Entries are numbered with consecutive integers.  Each function
842      therefore has an index number, which appears at the beginning of
843      its primary line.
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
848      function.
850 `% time'
851      This is the percentage of the total time that was spent in this
852      function, including time spent in subroutines called from this
853      function.
855      The time spent in this function is counted again for the callers of
856      this function.  Therefore, adding up these percentages is
857      meaningless.
859 `self'
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.
864 `children'
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
868      below this function.
870 `called'
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
878      `main'.
880 `name'
881      This is the name of the current function.  The index number is
882      repeated after it.
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
888      end like this:
890           gnurr <cycle 1> [12]
892 \x1f
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
907      ...
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'
912 called from `main':
914 `self'
915      An estimate of the amount of time spent in `report' itself when it
916      was called from `main'.
918 `children'
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'.
925 `called'
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.
946 \x1f
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
962      ...
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'
967 calling `report':
969 `self'
970      An estimate of the amount of time spent directly within `report'
971      when `report' was called from `main'.
973 `children'
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'.
980 `called'
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::.
986 `name'
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.
993 \x1f
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
1020 recursive?
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      ----------------------------------------
1036                       1.77        0    1/1        main [2]
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      ----------------------------------------
1041                                        3          a <cycle 1> [5]
1042      [4]     52.85    1.02        0    0      b <cycle 1> [4]
1043                                        2          a <cycle 1> [5]
1044                          0        0    3/6        c [6]
1045      ----------------------------------------
1046                       1.77        0    1/1        main [2]
1047                                        2          b <cycle 1> [4]
1048      [5]     38.86    0.75        0    1      a <cycle 1> [5]
1049                                        3          b <cycle 1> [4]
1050                          0        0    3/6        c [6]
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
1055 `b'.)
1057      index  % time    self  children called     name
1058                                                   <spontaneous>
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      ----------------------------------------
1066                       1.77        0    1/1        main [2]
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]
1070                          0        0    6/6        c [6]
1071      ----------------------------------------
1072                                        3          a <cycle 1> [5]
1073      [4]     52.85    1.02        0    0      b <cycle 1> [4]
1074                                        2          a <cycle 1> [5]
1075                          0        0    3/6        c [6]
1076      ----------------------------------------
1077                       1.77        0    1/1        main [2]
1078                                        2          b <cycle 1> [4]
1079      [5]     38.86    0.75        0    1      a <cycle 1> [5]
1080                                        3          b <cycle 1> [4]
1081                          0        0    3/6        c [6]
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
1098 back to `a'.
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
1103 cycle.
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.