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