| 1 | This is gprof.info, produced by makeinfo version 4.0 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 Free Software Foundation,
|
|---|
| 10 | 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
|
|---|
| 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".
|
|---|
| 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'.
|
|---|
| 209 |
|
|---|
| 210 |
|
|---|
| 211 | File: gprof.info, Node: Invoking, Next: Output, Prev: Executing, Up: Top
|
|---|
| 212 |
|
|---|
| 213 | `gprof' Command Summary
|
|---|
| 214 | ***********************
|
|---|
| 215 |
|
|---|
| 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 `>'.
|
|---|
| 220 |
|
|---|
| 221 | You run `gprof' like this:
|
|---|
| 222 |
|
|---|
| 223 | gprof OPTIONS [EXECUTABLE-FILE [PROFILE-DATA-FILES...]] [> OUTFILE]
|
|---|
| 224 |
|
|---|
| 225 | Here square-brackets indicate optional arguments.
|
|---|
| 226 |
|
|---|
| 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.
|
|---|
| 232 |
|
|---|
| 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.
|
|---|
| 236 |
|
|---|
| 237 | The order of these options does not matter.
|
|---|
| 238 |
|
|---|
| 239 | * Menu:
|
|---|
| 240 |
|
|---|
| 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
|
|---|
| 247 |
|
|---|
| 248 |
|
|---|
| 249 | File: gprof.info, Node: Output Options, Next: Analysis Options, Up: Invoking
|
|---|
| 250 |
|
|---|
| 251 | Output Options
|
|---|
| 252 | ==============
|
|---|
| 253 |
|
|---|
| 254 | These options specify which of several output formats `gprof' should
|
|---|
| 255 | produce.
|
|---|
| 256 |
|
|---|
| 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::.
|
|---|
| 261 |
|
|---|
| 262 | Specifying any of these options overrides the default (`-p -q'),
|
|---|
| 263 | which prints a flat profile and call graph analysis for all functions.
|
|---|
| 264 |
|
|---|
| 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::.
|
|---|
| 270 |
|
|---|
| 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.
|
|---|
| 277 |
|
|---|
| 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.
|
|---|
| 283 |
|
|---|
| 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.
|
|---|
| 287 |
|
|---|
| 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.
|
|---|
| 293 |
|
|---|
| 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.
|
|---|
| 300 |
|
|---|
| 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.
|
|---|
| 306 |
|
|---|
| 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.
|
|---|
| 314 |
|
|---|
| 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::.
|
|---|
| 320 |
|
|---|
| 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.
|
|---|
| 326 |
|
|---|
| 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::.
|
|---|
| 332 |
|
|---|
| 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.
|
|---|
| 338 |
|
|---|
| 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').
|
|---|
| 349 |
|
|---|
| 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.
|
|---|
| 355 |
|
|---|
| 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.
|
|---|
| 362 |
|
|---|
| 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.
|
|---|
| 366 |
|
|---|
| 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.
|
|---|
| 373 |
|
|---|
| 374 | Use of the `-a' argument is highly recommended with this option.
|
|---|
| 375 |
|
|---|
| 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'.
|
|---|
| 379 |
|
|---|
| 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 | ...
|
|---|
| 388 |
|
|---|
| 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'.
|
|---|
| 391 |
|
|---|
| 392 | `-T'
|
|---|
| 393 | `--traditional'
|
|---|
| 394 | The `-T' option causes `gprof' to print its output in
|
|---|
| 395 | "traditional" BSD style.
|
|---|
| 396 |
|
|---|
| 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.
|
|---|
| 401 |
|
|---|
| 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'.
|
|---|
| 409 |
|
|---|
| 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.
|
|---|
| 418 |
|
|---|
| 419 |
|
|---|
| 420 | File: gprof.info, Node: Analysis Options, Next: Miscellaneous Options, Prev: Output Options, Up: Invoking
|
|---|
| 421 |
|
|---|
| 422 | Analysis Options
|
|---|
| 423 | ================
|
|---|
| 424 |
|
|---|
| 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.
|
|---|
| 435 |
|
|---|
| 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'.
|
|---|
| 449 |
|
|---|
| 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).
|
|---|
| 456 |
|
|---|
| 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.
|
|---|
| 460 |
|
|---|
| 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::.
|
|---|
| 472 |
|
|---|
| 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.
|
|---|
| 477 |
|
|---|
| 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.
|
|---|
| 482 |
|
|---|
| 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.
|
|---|
| 487 |
|
|---|
| 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.
|
|---|
| 494 |
|
|---|
| 495 |
|
|---|
| 496 | File: gprof.info, Node: Miscellaneous Options, Next: Deprecated Options, Prev: Analysis Options, Up: Invoking
|
|---|
| 497 |
|
|---|
| 498 | Miscellaneous Options
|
|---|
| 499 | =====================
|
|---|
| 500 |
|
|---|
| 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::.
|
|---|
| 505 |
|
|---|
| 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).
|
|---|
| 511 |
|
|---|
| 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'.
|
|---|
| 520 |
|
|---|
| 521 | Eventually you can run `gprof' again without `-s' to analyze the
|
|---|
| 522 | cumulative data in the file `gmon.sum'.
|
|---|
| 523 |
|
|---|
| 524 | `-v'
|
|---|
| 525 | `--version'
|
|---|
| 526 | The `-v' flag causes `gprof' to print the current version number,
|
|---|
| 527 | and then exit.
|
|---|
| 528 |
|
|---|
| 529 |
|
|---|
| 530 | File: gprof.info, Node: Deprecated Options, Next: Symspecs, Prev: Miscellaneous Options, Up: Invoking
|
|---|
| 531 |
|
|---|
| 532 | Deprecated Options
|
|---|
| 533 | ==================
|
|---|
| 534 |
|
|---|
| 535 | These options have been replaced with newer versions that use
|
|---|
| 536 | symspecs.
|
|---|
| 537 |
|
|---|
| 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.
|
|---|
| 545 |
|
|---|
| 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.
|
|---|
| 553 |
|
|---|
| 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.
|
|---|
| 559 |
|
|---|
| 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.
|
|---|
| 567 |
|
|---|
| 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:
|
|---|
| 571 |
|
|---|
| 572 | gprof -e boring -f foo -f bar myprogram > gprof.output
|
|---|
| 573 |
|
|---|
| 574 | lists in the call graph all functions that were reached from either
|
|---|
| 575 | `foo' or `bar' and were not reachable from `boring'.
|
|---|
| 576 |
|
|---|
| 577 |
|
|---|
| 578 | File: gprof.info, Node: Symspecs, Prev: Deprecated Options, Up: Invoking
|
|---|
| 579 |
|
|---|
| 580 | Symspecs
|
|---|
| 581 | ========
|
|---|
| 582 |
|
|---|
| 583 | Many of the output options allow functions to be included or excluded
|
|---|
| 584 | using "symspecs" (symbol specifications), which observe the following
|
|---|
| 585 | syntax:
|
|---|
| 586 |
|
|---|
| 587 | filename_containing_a_dot
|
|---|
| 588 | | funcname_not_containing_a_dot
|
|---|
| 589 | | linenumber
|
|---|
| 590 | | ( [ any_filename ] `:' ( any_funcname | linenumber ) )
|
|---|
| 591 |
|
|---|
| 592 | Here are some sample symspecs:
|
|---|
| 593 |
|
|---|
| 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'.
|
|---|
| 600 |
|
|---|
| 601 | `main'
|
|---|
| 602 | Selects all functions named `main'.
|
|---|
| 603 |
|
|---|
| 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.
|
|---|
| 609 |
|
|---|
| 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'.
|
|---|
| 613 |
|
|---|
| 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.
|
|---|
| 620 |
|
|---|
| 621 | `main.c:main'
|
|---|
| 622 | Selects function `main' in file `main.c'.
|
|---|
| 623 |
|
|---|
| 624 | `main.c:134'
|
|---|
| 625 | Selects line 134 in file `main.c'.
|
|---|
| 626 |
|
|---|
| 627 |
|
|---|
| 628 | File: gprof.info, Node: Output, Next: Inaccuracy, Prev: Invoking, Up: Top
|
|---|
| 629 |
|
|---|
| 630 | Interpreting `gprof''s Output
|
|---|
| 631 | *****************************
|
|---|
| 632 |
|
|---|
| 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::.
|
|---|
| 638 |
|
|---|
| 639 | * Menu:
|
|---|
| 640 |
|
|---|
| 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
|
|---|
| 649 |
|
|---|
| 650 |
|
|---|
| 651 | File: gprof.info, Node: Flat Profile, Next: Call Graph, Up: Output
|
|---|
| 652 |
|
|---|
| 653 | The Flat Profile
|
|---|
| 654 | ================
|
|---|
| 655 |
|
|---|
| 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.
|
|---|
| 662 |
|
|---|
| 663 | This is part of a flat profile for a small program:
|
|---|
| 664 |
|
|---|
| 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 | ...
|
|---|
| 685 |
|
|---|
| 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.
|
|---|
| 691 |
|
|---|
| 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.
|
|---|
| 707 |
|
|---|
| 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.
|
|---|
| 715 |
|
|---|
| 716 | Here is what the fields in each line mean:
|
|---|
| 717 |
|
|---|
| 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%.
|
|---|
| 721 |
|
|---|
| 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.
|
|---|
| 726 |
|
|---|
| 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.
|
|---|
| 730 |
|
|---|
| 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.
|
|---|
| 736 |
|
|---|
| 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.
|
|---|
| 741 |
|
|---|
| 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.
|
|---|
| 748 |
|
|---|
| 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.
|
|---|
| 753 |
|
|---|
| 754 |
|
|---|
| 755 | File: gprof.info, Node: Call Graph, Next: Line-by-line, Prev: Flat Profile, Up: Output
|
|---|
| 756 |
|
|---|
| 757 | The Call Graph
|
|---|
| 758 | ==============
|
|---|
| 759 |
|
|---|
| 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.
|
|---|
| 764 |
|
|---|
| 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.
|
|---|
| 767 |
|
|---|
| 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 | -----------------------------------------------
|
|---|
| 796 |
|
|---|
| 797 | The lines full of dashes divide this table into "entries", one for
|
|---|
| 798 | each function. Each entry has one or more lines.
|
|---|
| 799 |
|
|---|
| 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).
|
|---|
| 805 |
|
|---|
| 806 | The entries are sorted by time spent in the function and its
|
|---|
| 807 | subroutines.
|
|---|
| 808 |
|
|---|
| 809 | The internal profiling function `mcount' (*note Flat Profile::) is
|
|---|
| 810 | never mentioned in the call graph.
|
|---|
| 811 |
|
|---|
| 812 | * Menu:
|
|---|
| 813 |
|
|---|
| 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'...
|
|---|
| 819 |
|
|---|
| 820 |
|
|---|
| 821 | File: gprof.info, Node: Primary, Next: Callers, Up: Call Graph
|
|---|
| 822 |
|
|---|
| 823 | The Primary Line
|
|---|
| 824 | ----------------
|
|---|
| 825 |
|
|---|
| 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.
|
|---|
| 829 |
|
|---|
| 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:
|
|---|
| 833 |
|
|---|
| 834 | index % time self children called name
|
|---|
| 835 | ...
|
|---|
| 836 | [3] 100.0 0.00 0.05 1 report [3]
|
|---|
| 837 |
|
|---|
| 838 | Here is what the fields in the primary line mean:
|
|---|
| 839 |
|
|---|
| 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.
|
|---|
| 844 |
|
|---|
| 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.
|
|---|
| 849 |
|
|---|
| 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.
|
|---|
| 854 |
|
|---|
| 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.
|
|---|
| 858 |
|
|---|
| 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.
|
|---|
| 863 |
|
|---|
| 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.
|
|---|
| 869 |
|
|---|
| 870 | `called'
|
|---|
| 871 | This is the number of times the function was called.
|
|---|
| 872 |
|
|---|
| 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.
|
|---|
| 876 |
|
|---|
| 877 | In the example above, the function `report' was called once from
|
|---|
| 878 | `main'.
|
|---|
| 879 |
|
|---|
| 880 | `name'
|
|---|
| 881 | This is the name of the current function. The index number is
|
|---|
| 882 | repeated after it.
|
|---|
| 883 |
|
|---|
| 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:
|
|---|
| 889 |
|
|---|
| 890 | gnurr <cycle 1> [12]
|
|---|
| 891 |
|
|---|
| 892 |
|
|---|
| 893 | File: gprof.info, Node: Callers, Next: Subroutines, Prev: Primary, Up: Call Graph
|
|---|
| 894 |
|
|---|
| 895 | Lines for a Function's Callers
|
|---|
| 896 | ------------------------------
|
|---|
| 897 |
|
|---|
| 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.
|
|---|
| 901 |
|
|---|
| 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:
|
|---|
| 905 |
|
|---|
| 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]
|
|---|
| 910 |
|
|---|
| 911 | Here are the meanings of the fields in the caller-line for `report'
|
|---|
| 912 | called from `main':
|
|---|
| 913 |
|
|---|
| 914 | `self'
|
|---|
| 915 | An estimate of the amount of time spent in `report' itself when it
|
|---|
| 916 | was called from `main'.
|
|---|
| 917 |
|
|---|
| 918 | `children'
|
|---|
| 919 | An estimate of the amount of time spent in subroutines of `report'
|
|---|
| 920 | when `report' was called from `main'.
|
|---|
| 921 |
|
|---|
| 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'.
|
|---|
| 924 |
|
|---|
| 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.
|
|---|
| 929 |
|
|---|
| 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.
|
|---|
| 933 |
|
|---|
| 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.
|
|---|
| 938 |
|
|---|
| 939 | If the caller is part of a recursion cycle, the cycle number is
|
|---|
| 940 | printed between the name and the index number.
|
|---|
| 941 |
|
|---|
| 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.
|
|---|
| 945 |
|
|---|
| 946 |
|
|---|
| 947 | File: gprof.info, Node: Subroutines, Next: Cycles, Prev: Callers, Up: Call Graph
|
|---|
| 948 |
|
|---|
| 949 | Lines for a Function's Subroutines
|
|---|
| 950 | ----------------------------------
|
|---|
| 951 |
|
|---|
| 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.
|
|---|
| 956 |
|
|---|
| 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:
|
|---|
| 960 |
|
|---|
| 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]
|
|---|
| 965 |
|
|---|
| 966 | Here are the meanings of the fields in the subroutine-line for `main'
|
|---|
| 967 | calling `report':
|
|---|
| 968 |
|
|---|
| 969 | `self'
|
|---|
| 970 | An estimate of the amount of time spent directly within `report'
|
|---|
| 971 | when `report' was called from `main'.
|
|---|
| 972 |
|
|---|
| 973 | `children'
|
|---|
| 974 | An estimate of the amount of time spent in subroutines of `report'
|
|---|
| 975 | when `report' was called from `main'.
|
|---|
| 976 |
|
|---|
| 977 | The sum of the `self' and `children' fields is an estimate of the
|
|---|
| 978 | total time spent in calls to `report' from `main'.
|
|---|
| 979 |
|
|---|
| 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::.
|
|---|
| 985 |
|
|---|
| 986 | `name'
|
|---|
| 987 | The name of the subroutine of `main' to which this line applies,
|
|---|
| 988 | followed by the subroutine's index number.
|
|---|
| 989 |
|
|---|
| 990 | If the caller is part of a recursion cycle, the cycle number is
|
|---|
| 991 | printed between the name and the index number.
|
|---|
| 992 |
|
|---|
| 993 |
|
|---|
| 994 | File: gprof.info, Node: Cycles, Prev: Subroutines, Up: Call Graph
|
|---|
| 995 |
|
|---|
| 996 | How Mutually Recursive Functions Are Described
|
|---|
| 997 | ----------------------------------------------
|
|---|
| 998 |
|
|---|
| 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.
|
|---|
| 1004 |
|
|---|
| 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.
|
|---|
| 1010 |
|
|---|
| 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>'.
|
|---|
| 1014 |
|
|---|
| 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?
|
|---|
| 1021 |
|
|---|
| 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.
|
|---|
| 1029 |
|
|---|
| 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'.
|
|---|
| 1033 |
|
|---|
| 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 | ----------------------------------------
|
|---|
| 1052 |
|
|---|
| 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'.)
|
|---|
| 1056 |
|
|---|
| 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 | ----------------------------------------
|
|---|
| 1087 |
|
|---|
| 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.
|
|---|
| 1092 |
|
|---|
| 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'.
|
|---|
| 1099 |
|
|---|
| 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.
|
|---|
| 1104 |
|
|---|
| 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.
|
|---|
| 1111 |
|
|---|
| 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.
|
|---|
| 1116 |
|
|---|
| 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.
|
|---|
| 1123 |
|
|---|
