![[BACK]](/cvsweb/icons/back.gif){kind=icon}
Return to gprof.texinfo CVS log ![[TXT]](/cvsweb/icons/text.gif){kind=icon}
![[DIR]](/cvsweb/icons/dir.gif){kind=icon}
Up to [Early binutils] / binutils|
Return to gprof.texinfo CVS log | Up to [Early binutils] / binutils |
1.1 ! root 1: \input texinfo @c -*-texinfo-*- ! 2: @setfilename gprof ! 3: @settitle gprof ! 4: @ifinfo ! 5: This file documents the gprof profiler of the GNU system. ! 6: ! 7: Copyright (C) 1988 Free Software Foundation, Inc. ! 8: ! 9: Permission is granted to make and distribute verbatim copies of ! 10: this manual provided the copyright notice and this permission notice ! 11: are preserved on all copies. ! 12: ! 13: @ignore ! 14: Permission is granted to process this file through Tex and print the ! 15: results, provided the printed document carries copying permission ! 16: notice identical to this one except for the removal of this paragraph ! 17: (this paragraph not being relevant to the printed manual). ! 18: ! 19: @end ignore ! 20: Permission is granted to copy and distribute modified versions of this ! 21: manual under the conditions for verbatim copying, provided that the entire ! 22: resulting derived work is distributed under the terms of a permission ! 23: notice identical to this one. ! 24: ! 25: Permission is granted to copy and distribute translations of this manual ! 26: into another language, under the above conditions for modified versions. ! 27: @end ifinfo ! 28: ! 29: @titlepage ! 30: @center @titlefont{gprof} ! 31: @sp 1 ! 32: @center The GNU Profiler ! 33: @sp 2 ! 34: @center Jay Fenlason and Richard Stallman ! 35: @sp 4 ! 36: This manual describes the GNU profiler, @code{gprof}, and how you can use ! 37: it to determine which parts of a program are taking most of the execution ! 38: time. We assume that you know how to write, compile, and execute programs. ! 39: GNU @code{gprof} was written by Jay Fenlason. ! 40: @sp 8 ! 41: Copyright @copyright{} 1988 Free Software Foundation, Inc. ! 42: ! 43: Permission is granted to make and distribute verbatim copies of ! 44: this manual provided the copyright notice and this permission notice ! 45: are preserved on all copies. ! 46: ! 47: @ignore ! 48: Permission is granted to process this file through Tex and print the ! 49: results, provided the printed document carries copying permission ! 50: notice identical to this one except for the removal of this paragraph ! 51: (this paragraph not being relevant to the printed manual). ! 52: ! 53: @end ignore ! 54: Permission is granted to copy and distribute modified versions of this ! 55: manual under the conditions for verbatim copying, provided that the entire ! 56: resulting derived work is distributed under the terms of a permission ! 57: notice identical to this one. ! 58: ! 59: Permission is granted to copy and distribute translations of this manual ! 60: into another language, under the same conditions as for modified versions. ! 61: ! 62: @end titlepage ! 63: ! 64: @ifinfo ! 65: @node Top, Why, Top, (dir) ! 66: @ichapter Profiling a Program: Where Does It Spend Its Time? ! 67: ! 68: This manual describes the GNU profiler @code{gprof}, and how you can use it ! 69: to determine which parts of a program are taking most of the execution ! 70: time. We assume that you know how to write, compile, and execute programs. ! 71: GNU @code{gprof} was written by Jay Fenlason. ! 72: ! 73: @menu ! 74: * Why:: What profiling means, and why it is useful. ! 75: * Compiling:: How to compile your program for profiling. ! 76: * Executing:: How to execute your program to generate the ! 77: profile data file @file{gmon.out}. ! 78: * Analyzing:: How to run @code{gprof}, and how to specify ! 79: options for it. ! 80: ! 81: * Flat Profile:: The flat profile shows how much time was spent ! 82: executing directly in each function. ! 83: * Call Graph:: The call graph shows which functions called which ! 84: others, and how much time each function used ! 85: when its subroutine calls are included. ! 86: ! 87: * Implementation:: How the profile data is recorded and written. ! 88: * Sampling Error:: Statistical margins of error. ! 89: How to accumulate data from several runs ! 90: to make it more accurate. ! 91: ! 92: * Assumptions:: Some of @code{gprof}'s measurements are based ! 93: on assumptions about your program ! 94: that could be very wrong. ! 95: ! 96: * Incompatibilities:: (between GNU @code{gprof} and Unix @code{gprof}.) ! 97: @end menu ! 98: @end ifinfo ! 99: ! 100: @node Why, Compiling, Top, Top ! 101: @chapter Why Profile ! 102: ! 103: Profiling allows you to learn where your program spent its time and which ! 104: functions called which other functions while it was executing. This ! 105: information can show you which pieces of your program are slower than you ! 106: expected, and might be candidates for rewriting to make your program ! 107: execute faster. It can also tell you which functions are being called more ! 108: or less often than you expected. This may help you spot bugs that had ! 109: otherwise been unnoticed. ! 110: ! 111: Since the profiler uses information collected during the actual execution ! 112: of your program, it can be used on programs that are too large or too ! 113: complex to analyze by reading the source. However, how your program is run ! 114: will affect the information that shows up in the profile data. If you ! 115: don't use some feature of your program while it is being profiled, no ! 116: profile information will be generated for that feature. ! 117: ! 118: Profiling has several steps: ! 119: ! 120: @itemize @bullet ! 121: @item ! 122: You must compile and link your program with profiling enabled. ! 123: @xref{Compiling}. ! 124: ! 125: @item ! 126: You must execute your program to generate a profile data file. ! 127: @xref{Executing}. ! 128: ! 129: @item ! 130: You must run @code{gprof} to analyze the profile data. ! 131: @xref{Analyzing}. ! 132: @end itemize ! 133: ! 134: The next three chapters explain these steps in greater detail. ! 135: ! 136: The result of the analysis is a file containing two tables, the ! 137: @dfn{flat profile} and the @dfn{call graph} (plus blurbs which briefly ! 138: explain the contents of these tables). ! 139: ! 140: The flat profile shows how much time your program spent in each function, ! 141: and how many times that function was called. If you simply want to know ! 142: which functions burn most of the cycles, it is stated concisely here. ! 143: @xref{Flat Profile}. ! 144: ! 145: The call graph, shows, for each function, which functions called it, which ! 146: other functions it called, and how many times. There is also an estimate ! 147: of how much time was spent in the subroutines of each function. This can ! 148: suggest places where you might try to eliminate function calls that use a ! 149: lot of time. @xref{Call Graph}. ! 150: ! 151: @node Compiling, Executing, Why, Top ! 152: @chapter Compiling a Program for Profiling ! 153: ! 154: The first step in generating profile information for your program is ! 155: to compile and link it with profiling enabled. ! 156: ! 157: To compile a source file for profiling, specify the @samp{-pg} option when ! 158: you run the compiler. (This is in addition to the options you normally ! 159: use.) ! 160: ! 161: To link the program for profiling, if you use a compiler such as @code{cc} ! 162: to do the linking, simply specify @samp{-pg} in addition to your usual ! 163: options. The same option, @samp{-pg}, alters either compilation or linking ! 164: to do what is necessary for profiling. Here are examples: ! 165: ! 166: @example ! 167: cc -g myprog.c utils.c -pg ! 168: cc -o myprog myprog.o utils.o -pg ! 169: @end example ! 170: ! 171: The @samp{-pg} option also works with a command that both compiles and links: ! 172: ! 173: @example ! 174: cc -o myprog myprog.c utils.c -g -pg ! 175: @end example ! 176: ! 177: If you run the linker @code{ld} directly instead of through a compiler such ! 178: as @code{cc}, you must specify the profiling startup file ! 179: @file{/lib/gcrt0.o} as the first input file instead of the usual startup ! 180: file @file{/lib/crt0.o}. In addition, you would probably want to specify ! 181: the profiling C library, @file{/usr/lib/libc_p.a}, by writing @samp{-lc_p} ! 182: instead of the usual @samp{-lc}. This is not absolutely necessary, but doing ! 183: this gives you number-of-calls information for standard library functions such ! 184: as @code{read} and @code{open}. For example: ! 185: ! 186: @example ! 187: ld -o myprog /lib/gcrt0.o myprog.o utils.o -lc_p ! 188: @end example ! 189: ! 190: If you compile only some of the modules of the program with @samp{-pg}, you ! 191: can still profile the program, but you won't get complete information about ! 192: the modules that were compiled without @samp{-pg}. The only information ! 193: you get for the functions in those modules is the total time spent in them; ! 194: there is no record of how many times they were called, or from where. This ! 195: will not affect the flat profile (except that the @code{calls} field for ! 196: the functions will be blank), but will greatly reduce the usefulness of the ! 197: call graph. ! 198: ! 199: So far GNU @code{gprof} has been tested only with C programs, but it ought ! 200: to work with any language in which programs are compiled and linked to form ! 201: executable files. If it does not, please let us know. ! 202: ! 203: @node Executing, Analyzing, Compiling, Top ! 204: @chapter Executing the Program to Generate Profile Data ! 205: ! 206: Once the program is compiled for profiling, you must run it in order to ! 207: generate the information that @code{gprof} needs. Simply run the program ! 208: as usual, using the normal arguments, file names, etc. The program should ! 209: run normally, producing the same output as usual. It will, however, run ! 210: somewhat slower than normal because of the time spent collecting and the ! 211: writing the profile data. ! 212: ! 213: The way you run the program---the arguments and input that you give ! 214: it---may have a dramatic effect on what the profile information shows. The ! 215: profile data will describe the parts of the program that were activated for ! 216: the particular input you use. For example, if the first command you give ! 217: to your program is to quit, the profile data will show the time used in ! 218: initialization and in cleanup, but not much else. ! 219: ! 220: You program will write the profile data into a file called @file{gmon.out} ! 221: just before exiting. If there is already a file called @file{gmon.out}, ! 222: its contents are overwritten. There is currently no way to tell the ! 223: program to write the profile data under a different name, but you can rename ! 224: the file afterward if you are concerned that it may be overwritten. ! 225: ! 226: In order to write the @file{gmon.out} file properly, your program must exit ! 227: normally: by returning from @code{main} or by calling @code{exit}. Calling ! 228: the low-level function @code{_exit} does not write the profile data, and ! 229: neither does abnormal termination due to an unhandled signal. ! 230: ! 231: The @file{gmon.out} file is written in the program's @emph{current working ! 232: directory} at the time it exits. This means that if your program calls ! 233: @code{chdir}, the @file{gmon.out} file will be left in the last directory ! 234: your program @code{chdir}'d to. If you don't have permission to write in ! 235: this directory, the file is not written. You may get a confusing error ! 236: message if this happens. (We have not yet replaced the part of Unix ! 237: responsible for this; when we do, we will make the error message ! 238: comprehensible.) ! 239: ! 240: @node Analyzing, Flat Profile, Executing, Top ! 241: @chapter Analyzing the Profile Data: @code{gprof} Command Summary ! 242: ! 243: After you have a profile data file @file{gmon.out}, you can run @code{gprof} ! 244: to interpret the information in it. The @code{gprof} program prints a ! 245: flat profile and a call graph on standard output. Typically you would ! 246: redirect the output of @code{gprof} into a file with @samp{>}. ! 247: ! 248: You run @code{gprof} like this: ! 249: ! 250: @example ! 251: gprof @var{options} [@var{executable-file} [@var{profile-data-files}@dots{}]] [> @var{outfile}] ! 252: @end example ! 253: ! 254: @noindent ! 255: Here square-brackets indicate optional arguments. ! 256: ! 257: If you omit the executable file name, the file @file{a.out} is used. If ! 258: you give no profile data file name, the file @file{gmon.out} is used. If ! 259: any file is not in the proper format, or if the profile data file does not ! 260: appear to belong to the executable file, an error message is printed. ! 261: ! 262: You can give more than one profile data file by entering all their names ! 263: after the executable file name; then the statistics in all the data files ! 264: are summed together. ! 265: ! 266: The following options may be used to selectively include or exclude ! 267: functions in the output: ! 268: ! 269: @table @code ! 270: @item -a ! 271: The @code{-a} option causes @code{gprof} to ignore static (private) ! 272: functions. (These are functions whose names are not listed as global, ! 273: and which are not visible outside the file/function/block where they ! 274: were defined.) Time spent in these functions, calls to/from them, ! 275: etc, will all be attributed to the function that was loaded directly ! 276: before it in the executable file. This is compatible with Unix ! 277: @code{gprof}, but a bad idea. This option affects both the flat ! 278: profile and the call graph. ! 279: ! 280: @item -e @var{function_name} ! 281: The @code{-e @var{function}} option tells @code{gprof} to not print ! 282: information about the function (and its children@dots{}) in the call ! 283: graph. The function will still be listed as a child of any functions ! 284: that call it, but its index number will be shown as @samp{[not ! 285: printed]}. ! 286: ! 287: @item -E @var{function_name} ! 288: The @code{-E @var{function}} option works like the @code{-e} option, ! 289: but time spent in the function (and children who were not called from ! 290: anywhere else), will not be used to compute the percentages-of-time ! 291: for the call graph. ! 292: ! 293: @item -f @var{function_name} ! 294: The @code{-f @var{function}} option causes @code{gprof} to limit the ! 295: call graph to the function and its children (and their ! 296: children@dots{}). ! 297: ! 298: @item -F @var{function_name} ! 299: The @code{-F @var{function}} option works like the @code{-f} option, ! 300: but only time spent in the function and its children (and their ! 301: children@dots{}) will be used to determine total-time and ! 302: percentages-of-time for the call graph. ! 303: ! 304: @item -z ! 305: If you give the @code{-z} option, @code{gprof} will mention all ! 306: functions in the flat profile, even those that were never called, and ! 307: that had no time spent in them. ! 308: @end table ! 309: ! 310: The order of these options does not matter. ! 311: ! 312: Note that only one function can be specified with each @code{-e}, ! 313: @code{-E}, @code{-f} or @code{-F} option. To specify more than one ! 314: function, use multiple options. For example, this command: ! 315: ! 316: @example ! 317: gprof -e boring -f foo -f bar myprogram > gprof.output ! 318: @end example ! 319: ! 320: @noindent ! 321: lists in the call graph all functions that were reached from either ! 322: @code{foo} or @code{bar} and were not reachable from @code{boring}. ! 323: ! 324: There are two other useful @code{gprof} options: ! 325: ! 326: @table @code ! 327: @item -b ! 328: If the @code{-b} option is given, @code{gprof} doesn't print the ! 329: verbose blurbs that try to explain the meaning of all of the fields in ! 330: the tables. This is useful if you intend to print out the output, or ! 331: are tired of seeing the blurbs. ! 332: ! 333: @item -s ! 334: The @code{-s} option causes @code{gprof} to summarize the information ! 335: in the profile data files it read in, and write out a profile data ! 336: file called @file{gmon.sum}, which contains all the information from ! 337: the profile data files that @code{gprof} read in. The file @file{gmon.sum} ! 338: may be one of the specified input files; the effect of this is to ! 339: merge the data in the other input files into @file{gmon.sum}. ! 340: @xref{Sampling Error}. ! 341: ! 342: Eventually you can run @code{gprof} again without @samp{-s} to analyze the ! 343: cumulative data in the file @file{gmon.sum}. ! 344: @end table ! 345: ! 346: @node Flat Profile, Call Graph, Analyzing, Top ! 347: @chapter How to Understand the Flat Profile ! 348: @cindex flat profile ! 349: ! 350: The @dfn{flat profile} shows the total amount of time your program ! 351: spent executing each function. Unless the @samp{-z} option is given, ! 352: functions with no apparent time spent in them, and no apparent calls ! 353: to them, are not mentioned. Note that if a function was not compiled ! 354: for profiling, and didn't run long enough to show up on the program ! 355: counter histogram, it will be indistinguishable from a function that ! 356: was never called. ! 357: @c??? ! 358: ! 359: Here is a sample flat profile for a small program: ! 360: ! 361: @example ! 362: Each sample counts as 0.01 seconds. ! 363: ! 364: % time seconds cumsec calls function ! 365: 79.17 0.19 0.19 6 a ! 366: 16.67 0.04 0.23 1 main ! 367: 4.17 0.01 0.24 mcount ! 368: 0.00 0 0.24 1 profil ! 369: @end example ! 370: ! 371: @noindent ! 372: The functions are sorted by decreasing run-time spent in them. The ! 373: functions @code{mcount} and @code{profil} are part of the profiling ! 374: aparatus and appear in every flat profile; their time gives a measure of ! 375: the amount of overhead due to profiling. (These internal functions are ! 376: omitted from the call graph.) ! 377: ! 378: The sampling period estimates the margin of error in each of the time ! 379: figures. A time figure that is not much larger than this is not reliable. ! 380: In this example, the @code{seconds} field for @code{mcount} might well be 0 ! 381: or 0.02 in another run. @xref{Sampling Error}, for a complete discussion. ! 382: ! 383: Here is what the fields in each line mean: ! 384: ! 385: @table @code ! 386: @item % time ! 387: This is the percentage of the total execution time your program spent ! 388: in this function. These should all add up to 100%. ! 389: ! 390: @item seconds ! 391: This is the total number of seconds the computer spent executing the ! 392: user code of this function. ! 393: ! 394: @item cumsec ! 395: This is the cumulative total number of seconds the computer spent ! 396: executing this functions, plus the time spent in all the functions ! 397: above this one in this table. ! 398: ! 399: @item calls ! 400: This is the total number of times the function was called. If the ! 401: function was never called, or the number of times it was called cannot ! 402: be determined (probably because the function was not compiled with ! 403: profiling enabled), the @dfn{calls} field is blank. ! 404: ! 405: @item function ! 406: This is the name of the function. ! 407: @end table ! 408: ! 409: @node Call Graph, Implementation, Flat Profile, Top ! 410: @chapter How to Read the Call Graph ! 411: ! 412: @cindex call graph ! 413: The @dfn{call graph} shows how much time was spent in each function ! 414: and its children. From this information, you can find functions that, ! 415: while they themselves may not have used much time, called other ! 416: functions that did use unusual amounts of time. ! 417: ! 418: Here is a sample call from a small program. This call came from the ! 419: same @code{gprof} run as the flat profile example in the previous ! 420: chapter. ! 421: ! 422: @example ! 423: index % time self children called name ! 424: <spontaneous> ! 425: [1] 100.00 0 0.23 0 start [1] ! 426: 0.04 0.19 1/1 main [2] ! 427: ---------------------------------------- ! 428: 0.04 0.19 1/1 start [1] ! 429: [2] 100.00 0.04 0.19 1 main [2] ! 430: 0.19 0 1/1 a [3] ! 431: ---------------------------------------- ! 432: 0.19 0 1/1 main [2] ! 433: [3] 82.61 0.19 0 1+5 a [3] ! 434: ---------------------------------------- ! 435: @end example ! 436: ! 437: The lines full of dashes divide this table into @dfn{entries}, one for each ! 438: function. Each entry has one or more lines. ! 439: ! 440: In each entry, the primary line is the one that starts with an index number ! 441: in square brackets. The end of this line says which function the entry is ! 442: for. The preceding lines in the entry describe the callers of this ! 443: function and the following lines describe its subroutines (also called ! 444: @dfn{children} when we speak of the call graph). ! 445: ! 446: The entries are sorted by time spent in the function and its subroutines. ! 447: ! 448: The internal profiling functions @code{mcount} and @code{profil} ! 449: (@pxref{Flat Profile}) are never mentioned in the call graph. ! 450: ! 451: @menu ! 452: * Primary:: Details of the primary line's contents. ! 453: * Callers:: Details of caller-lines' contents. ! 454: * Subroutines:: Details of subroutine-lines' contents. ! 455: * Cycles:: When there are cycles of recursion, ! 456: such as @code{a} calls @code{b} calls @code{a}@dots{} ! 457: @end menu ! 458: ! 459: @node Primary, Callers, Call Graph, Call Graph ! 460: @section The Primary Line ! 461: ! 462: The @dfn{primary line} in a call graph entry is the line that ! 463: describes the function which the entry is about and gives the overall ! 464: statistics for this function. ! 465: ! 466: For reference, we repeat the primary line from the entry for function ! 467: @code{a} in our main example, together with the heading line that shows the ! 468: names of the fields: ! 469: ! 470: @example ! 471: index % time self children called name ! 472: @dots{} ! 473: [3] 82.61 0.19 0 1+5 a [3] ! 474: @end example ! 475: ! 476: Here is what the fields in the primary line mean: ! 477: ! 478: @table @code ! 479: @item index ! 480: Entries are numbered with consecutive integers. Each function ! 481: therefore has an index number, which appears at the beginning of its ! 482: primary line. ! 483: ! 484: Each cross-reference to a function, as a caller or subroutine of ! 485: another, gives its index number as well as its name. The index number ! 486: guides you if you wish to look for the entry for that function. ! 487: ! 488: @item % time ! 489: This is the percentage of the total time that was spent in this ! 490: function, including time spent in subroutines called from this ! 491: function. ! 492: ! 493: The time spent in this function is counted again for the callers of ! 494: this function. Therefore, adding up these percentages is meaningless. ! 495: ! 496: @item self ! 497: This is the total amount of time spent in this function. This ! 498: should be identical to the number printed in the @code{seconds} field ! 499: for this function in the flat profile. ! 500: ! 501: @item children ! 502: This is the total amount of time spent in the subroutine calls made by ! 503: this function. This should be equal to the sum of all the @code{self} ! 504: and @code{children} entries of the children listed directly below this ! 505: function. ! 506: ! 507: @item called ! 508: This is the number of times the function was called. ! 509: ! 510: If the function called itself recursively, there are two numbers, ! 511: separated by a @samp{+}. The first number counts non-recursive calls, ! 512: and the second counts recursive calls. ! 513: ! 514: In the example above, the function @code{a} called itself five times, ! 515: and was called once from @code{main}. ! 516: ! 517: @item name ! 518: This is the name of the current function. The index number is ! 519: repeated after it. ! 520: ! 521: If the function is part of a cycle of recursion, the cycle number is ! 522: printed between the function's name and the index number ! 523: (@pxref{Cycles}). For example, if function @code{gnurr} is part of ! 524: cycle number one, and has index number twelve, its primary line would ! 525: be end like this: ! 526: ! 527: @example ! 528: gnurr <cycle 1> [12] ! 529: @end example ! 530: @end table ! 531: ! 532: @node Callers, Subroutines, Primary, Call Graph ! 533: @section Lines for a Function's Callers ! 534: ! 535: A function's entry has a line for each function it was called by. ! 536: These lines' fields correspond to the fields of the primary line, but ! 537: their meanings are different because of the difference in context. ! 538: ! 539: For reference, we repeat two lines from the entry for the function ! 540: @code{a}, the primary line and one caller-line preceding it, together ! 541: with the heading line that shows the names of the fields: ! 542: ! 543: @example ! 544: index % time self children called name ! 545: @dots{} ! 546: 0.19 0 1/1 main [2] ! 547: [3] 82.61 0.19 0 1+5 a [3] ! 548: @end example ! 549: ! 550: Here are the meanings of the fields in the caller-line for @code{a} ! 551: called from @code{main}: ! 552: ! 553: @table @code ! 554: @item self ! 555: An estimate of the amount of time spent in @code{a} itself when it was ! 556: called from @code{main}. ! 557: ! 558: @item children ! 559: An estimate of the amount of time spent in @code{a}'s subroutines when ! 560: @code{a} was called from @code{main}. ! 561: ! 562: The sum of the @code{self} and @code{children} fields is an estimate ! 563: of the amount of time spent within calls to @code{a} from @code{main}. ! 564: ! 565: @item called ! 566: Two numbers: the number of times @code{a} was called from @code{main}, ! 567: followed by the total number of nonrecursive calls to @code{a} from ! 568: all its callers. ! 569: ! 570: @item name and index number ! 571: The name of the caller of @code{a} to which this line applies, ! 572: followed by the caller's index number. ! 573: ! 574: Not all functions have entries in the call graph; some ! 575: options to @code{gprof} request the omission of certain functions. ! 576: When a caller has no entry of its own, it still has caller-lines ! 577: in the entries of the functions it calls. Since this caller ! 578: has no index number, the string @samp{[not printed]} is used ! 579: instead of one. ! 580: ! 581: If the caller is part of a recursion cycle, the cycle number is ! 582: printed between the name and the index number. ! 583: @end table ! 584: ! 585: If the identity of the callers of a function cannot be determined, a ! 586: dummy caller-line is printed which has @samp{<spontaneous>} as the ! 587: ``caller's name'' and all other fields blank. This can happen for ! 588: signal handlers. ! 589: @c What if some calls have determinable callers' names but not all? ! 590: ! 591: @node Subroutines, Cycles, Callers, Call Graph ! 592: @section Lines for a Function's Subroutines ! 593: ! 594: A function's entry has a line for each of its subroutines---in other ! 595: words, a line for each other function that it called. These lines' ! 596: fields correspond to the fields of the primary line, but their meanings ! 597: are different because of the difference in context. ! 598: ! 599: For reference, we repeat two lines from the entry for the function ! 600: @code{main}, the primary line and a line for a subroutine, together ! 601: with the heading line that shows the names of the fields: ! 602: ! 603: @example ! 604: index % time self children called name ! 605: @dots{} ! 606: [2] 100.00 0.04 0.19 1 main [2] ! 607: 0.19 0 1/1 a [3] ! 608: @end example ! 609: ! 610: Here are the meanings of the fields in the subroutine-line for @code{main} ! 611: calling @code{a}: ! 612: ! 613: @table @code ! 614: @item self ! 615: An estimate of the amount of time spent directly within @code{a} ! 616: when @code{a} was called from @code{main}. ! 617: ! 618: @item children ! 619: An estimate of the amount of time spent in subroutines of @code{a} ! 620: when @code{a} was called from @code{main}. ! 621: ! 622: The sum of the @code{self} and @code{children} fields is an estimate ! 623: of the total time spent in calls to @code{a} from @code{main}. ! 624: ! 625: @item called ! 626: Two numbers, the number of calls to @code{a} from @code{main} ! 627: followed by the total number of nonrecursive calls to @code{a}. ! 628: ! 629: @item name ! 630: The name of the subroutine of @code{a} to which this line applies, ! 631: followed by the subroutine's index number. If the subroutine is ! 632: a function omitted from the call graph, it has no index number, ! 633: so @samp{[not printed]} appears instead. ! 634: ! 635: If the caller is part of a recursion cycle, the cycle number is ! 636: printed between the name and the index number. ! 637: @end table ! 638: ! 639: @node Cycles,, Subroutines, Call Graph ! 640: @section How Mutually Recursive Functions Are Described ! 641: @cindex cycle ! 642: @cindex recursion cycle ! 643: ! 644: The graph may be complicated by the presence of @dfn{cycles of ! 645: recursion} in the call graph. A cycle exists if a function calls ! 646: another function that (directly or indirectly) calls (or appears to ! 647: call) the original function. For example: if @code{a} calls @code{b}, ! 648: and @code{b} calls @code{a}, then @code{a} and @code{b} form a cycle. ! 649: ! 650: Whenever there are call-paths both ways between a pair of functions, they ! 651: belong to the same cycle. If @code{a} and @code{b} call each other and ! 652: @code{b} and @code{c} call each other, all three make one cycle. Note that ! 653: even if @code{b} only calls @code{a} if it was not called from @code{a}, ! 654: @code{gprof} cannot determine this, so @code{a} and @code{b} are still ! 655: considered a cycle. ! 656: ! 657: The cycles are numbered with consecutive integers. When a function ! 658: belongs to a cycle, each time the function name appears in the call graph ! 659: it is followed by @samp{<cycle @var{number}>}. ! 660: ! 661: The reason cycles matter is that they make the time values in the call ! 662: graph paradoxical. The ``time spent in children'' of @code{a} should ! 663: include the time spent in its subroutine @code{b} and in @code{b}'s ! 664: subroutines---but one of @code{b}'s subroutines is @code{a}! How much of ! 665: @code{a}'s time should be included in the children of @code{a}, when ! 666: @code{a} is indirectly recursive? ! 667: ! 668: The way @code{gprof} resolves this paradox is by creating a single entry ! 669: for the cycle as a whole. The primary line of this entry describes the ! 670: total time spent directly in the functions of the cycle. The ! 671: ``subroutines'' of the cycle are the individual functions of the cycle, and ! 672: all other functions that were called directly by them. The ``callers'' of ! 673: the cycle are the functions, outside the cycle, that called functions in ! 674: the cycle. ! 675: ! 676: Here is a portion of the call graph which shows a cycle containing ! 677: functions @code{a} and @code{b}. The cycle was entered by a call to ! 678: @code{a} from @code{main}; both @code{a} and @code{b} called @code{c}.@refill ! 679: ! 680: @example ! 681: index % time self children called name ! 682: ---------------------------------------- ! 683: 1.77 0 1/1 main [2] ! 684: [3] 91.71 1.77 0 1+5 <cycle 1 as a whole> [3] ! 685: 1.02 0 3 b <cycle 1> [4] ! 686: 0.75 0 2 a <cycle 1> [5] ! 687: ---------------------------------------- ! 688: 3 a <cycle 1> [5] ! 689: [4] 52.85 1.02 0 0 b <cycle 1> [4] ! 690: 2 a <cycle 1> [5] ! 691: 0 0 3/6 c [6] ! 692: ---------------------------------------- ! 693: 1.77 0 1/1 main [2] ! 694: 2 b <cycle 1> [4] ! 695: [5] 38.86 0.75 0 1 a <cycle 1> [5] ! 696: 3 b <cycle 1> [4] ! 697: 0 0 3/6 c [6] ! 698: ---------------------------------------- ! 699: @end example ! 700: ! 701: @noindent ! 702: (The entire call graph for this program contains in addition an entry for ! 703: @code{main}, which calls @code{a}, and an entry for @code{c}, with callers ! 704: @code{a} and @code{b}.) ! 705: ! 706: @example ! 707: index % time self children called name ! 708: <spontaneous> ! 709: [1] 100.00 0 1.93 0 start [1] ! 710: 0.16 1.77 1/1 main [2] ! 711: ---------------------------------------- ! 712: 0.16 1.77 1/1 start [1] ! 713: [2] 100.00 0.16 1.77 1 main [2] ! 714: 1.77 0 1/1 a <cycle 1> [5] ! 715: ---------------------------------------- ! 716: 1.77 0 1/1 main [2] ! 717: [3] 91.71 1.77 0 1+5 <cycle 1 as a whole> [3] ! 718: 1.02 0 3 b <cycle 1> [4] ! 719: 0.75 0 2 a <cycle 1> [5] ! 720: 0 0 6/6 c [6] ! 721: ---------------------------------------- ! 722: 3 a <cycle 1> [5] ! 723: [4] 52.85 1.02 0 0 b <cycle 1> [4] ! 724: 2 a <cycle 1> [5] ! 725: 0 0 3/6 c [6] ! 726: ---------------------------------------- ! 727: 1.77 0 1/1 main [2] ! 728: 2 b <cycle 1> [4] ! 729: [5] 38.86 0.75 0 1 a <cycle 1> [5] ! 730: 3 b <cycle 1> [4] ! 731: 0 0 3/6 c [6] ! 732: ---------------------------------------- ! 733: 0 0 3/6 b <cycle 1> [4] ! 734: 0 0 3/6 a <cycle 1> [5] ! 735: [6] 0.00 0 0 6 c [6] ! 736: ---------------------------------------- ! 737: @end example ! 738: ! 739: The @code{self} field of the cycle's primary line is the total time ! 740: spent in all the functions of the cycle. It equals the sum of the ! 741: @code{self} fields for the individual functions in the cycle, found ! 742: in the entry in the subroutine lines for these functions. ! 743: ! 744: The @code{children} fields of the cycle's primary line and subroutine lines ! 745: count only subroutines outside the cycle. Even though @code{a} calls ! 746: @code{b}, the time spent in those calls to @code{b} is not counted in ! 747: @code{a}'s @code{children} time. Thus, we do not encounter the problem of ! 748: what to do when the time in those calls to @code{b} includes indirect ! 749: recursive calls back to @code{a}. ! 750: ! 751: The @code{children} field of a caller-line in the cycle's entry estimates ! 752: the amount of time spent @emph{in the whole cycle}, and its other ! 753: subroutines, on the times when that caller called a function in the cycle. ! 754: ! 755: The @code{calls} field in the primary line for the cycle has two numbers: ! 756: first, the number of times functions in the cycle were called by functions ! 757: outside the cycle; second, the number of times they were called by ! 758: functions in the cycle (including times when a function in the cycle calls ! 759: itself). This is a generalization of the usual split into nonrecursive and ! 760: recursive calls. ! 761: ! 762: The @code{calls} field of a subroutine-line for a cycle member in the ! 763: cycle's entry says how many time that function was called from functions in ! 764: the cycle. The total of all these is the second number in the primary line's ! 765: @code{calls} field. ! 766: ! 767: In the individual entry for a function in a cycle, the other functions in ! 768: the same cycle can appear as subroutines and as callers. These lines show ! 769: how many times each function in the cycle called or was called from each other ! 770: function in the cycle. The @code{self} and @code{children} fields in these ! 771: lines are blank because of the difficulty of defining meanings for them ! 772: when recursion is going on. ! 773: ! 774: @node Implementation, Sampling Error, Call Graph, Top ! 775: @chapter Implementation of Profiling ! 776: ! 777: Profiling works by changing how every function in your program is compiled ! 778: so that when it is called, it will stash away some information about where ! 779: it was called from. From this, the profiler can figure out what function ! 780: called it, and can count how many times it was called. This change is made ! 781: by the compiler when your program is compiled with the @samp{-pg} option. ! 782: ! 783: Profiling also involves watching your program as it runs, and keeping a ! 784: histogram of where the program counter happens to be every now and then. ! 785: Typically the program counter is looked at around 100 times per second of ! 786: run time, but the exact frequency may vary from system to system. ! 787: ! 788: A special startup routine allocates memory for the histogram and sets up a ! 789: clock signal handler to make entries in it. Use of this special startup ! 790: routine is one of the effects of using @samp{cc -pg} to link. The startup ! 791: file also includes an @code{exit} function which is responsible for writing ! 792: the file @file{gmon.out}. ! 793: ! 794: Number-of-calls information for library routines is collected by using a ! 795: special version of the C library. The programs in it are the same as in ! 796: the usual C library, but they were compiled with @samp{-pg}. If you link ! 797: your program with @samp{cc -pg}, it automatically uses the profiling ! 798: version of the library. ! 799: ! 800: The output @code{gprof} gives no indication of parts of your program that ! 801: are limited by I/O or swapping bandwidth. This is because samples of the ! 802: program counter are taken at fixed intervals of run time. Therefore, the ! 803: time measurements in @code{gprof} output say nothing about time that your ! 804: program was not running. For example, a part of the program that creates ! 805: so much data that it cannot all fit in physical memory at once may run very ! 806: slowly due to thrashing, but @code{gprof} will say it uses little time. On ! 807: the other hand, sampling by run time has the advantage that the amount of ! 808: load due to other users won't directly affect the output you get. ! 809: ! 810: @node Sampling Error, Assumptions, Implementation, Top ! 811: @chapter Statistical Inaccuracy of @code{gprof} Output ! 812: ! 813: The run-time figures that @code{gprof} gives you are based on a sampling ! 814: process, so they are subject to statistical inaccuracy. If a function runs ! 815: only a small amount of time, so that on the average the sampling process ! 816: ought to catch that function in the act only once, there is a pretty good ! 817: chance it will actually find that function zero times, or twice. ! 818: ! 819: By contrast, the number-of-calls figures are derived by counting, not ! 820: sampling. They are completely accurate and will not vary from run to run ! 821: if your program is deterministic. ! 822: ! 823: The @dfn{sampling period} that is printed at the beginning of the flat ! 824: profile says how often samples are taken. The rule of thumb is that a ! 825: run-time figure is accurate if it is considerably bigger than the sampling ! 826: period. ! 827: ! 828: The actual amount of error is usually more than one sampling period. In ! 829: fact, if a value is @var{n} times the sampling period, the @emph{expected} ! 830: error in it is the square-root of @var{n} sampling periods. If the ! 831: sampling period is 0.01 seconds and @code{foo}'s run-time is 1 second, the ! 832: expected error in @code{foo}'s run-time is 0.1 seconds. It is likely to ! 833: vary this much @emph{on the average} from one profiling run to the next. ! 834: (@emph{Sometimes} it will vary more.) ! 835: ! 836: This does not mean that a small run-time figure is devoid of information. ! 837: If the program's @emph{total} run-time is large, a small run-time for one ! 838: function does tell you that that function used an insignificant fraction of ! 839: the whole program's time. Usually this means it is not worth optimizing. ! 840: ! 841: One way to get more accuracy is to give your program more (but similar) ! 842: input data so it will take longer. Another way is to combine the data from ! 843: several runs, using the @samp{-s} option of @code{gprof}. Here is how: ! 844: ! 845: @enumerate ! 846: @item ! 847: Run your program once. ! 848: ! 849: @item ! 850: Issue the command @samp{mv gmon.out gmon.sum}. ! 851: ! 852: @item ! 853: Run your program again, the same as before. ! 854: ! 855: @item ! 856: Merge the new data in @file{gmon.out} into @file{gmon.sum} with this command: ! 857: ! 858: @example ! 859: gprof -s @var{executable-file} gmon.out gmon.sum ! 860: @end example ! 861: ! 862: @item ! 863: Repeat the last two steps as often as you wish. ! 864: ! 865: @item ! 866: Analyze the cumulative data using this command: ! 867: ! 868: @example ! 869: gprof @var{executable-file} gmon.sum > @var{output-file} ! 870: @end example ! 871: @end enumerate ! 872: ! 873: @node Assumptions, Incompatibilities, Sampling Error, Top ! 874: @chapter Estimating @code{children} Times Uses an Assumption ! 875: ! 876: Some of the figures in the call graph are estimates---for example, the ! 877: @code{children} time values and all the the time figures in caller and ! 878: subroutine lines. ! 879: ! 880: There is no direct information about these measurements in the profile ! 881: data itself. Instead, @code{gprof} estimates them by making an assumption ! 882: about your program that might or might not be true. ! 883: ! 884: The assumption made is that the average time spent in each call to any ! 885: function @code{foo} is not correlated with who called @code{foo}. If ! 886: @code{foo} used 5 seconds in all, and 2/5 of the calls to @code{foo} came ! 887: from @code{a}, then @code{foo} contributes 2 seconds to @code{a}'s ! 888: @code{children} time, by assumption. ! 889: ! 890: This assumption is usually true enough, but for some programs it is far ! 891: from true. Suppose that @code{foo} returns very quickly when its argument ! 892: is zero; suppose that @code{a} always passes zero as an argument, while ! 893: other callers of @code{foo} pass other arguments. In this program, all the ! 894: time spent in @code{foo} is in the calls from callers other than @code{a}. ! 895: But @code{gprof} has no way of knowing this; it will blindly and ! 896: incorrectly charge 2 seconds of time in @code{foo} to the children of ! 897: @code{a}. ! 898: ! 899: We hope some day to put more complete data into @file{gmon.out}, so that ! 900: this assumption is no longer needed, if we can figure out how. For the ! 901: nonce, the estimated figures are usually more useful than misleading. ! 902: ! 903: @node Incompatibilities, , Assumptions, Top ! 904: @chapter Incompatibilities with Unix @code{gprof} ! 905: ! 906: GNU @code{gprof} and Berkeley Unix @code{gprof} use the same data file ! 907: @file{gmon.out}, and provide essentially the same information. But there a ! 908: few differences.@refill ! 909: ! 910: GNU @code{gprof} does not support the @samp{-c} option which prints a ! 911: static call graph based on reading the machine language of your ! 912: program. We think that program cross-references ought to be based on ! 913: the source files, which can be analyzed in a machine-independent ! 914: fashion.@refill ! 915: ! 916: For a recursive function, Unix @code{gprof} lists the function as a parent ! 917: and as a child, with a @code{calls} field that lists the number of ! 918: recursive calls. GNU @code{gprof} omits these lines and puts the number of ! 919: recursive calls in the primary line. ! 920: ! 921: When a function is suppressed from the call graph with @samp{-e}, GNU ! 922: @code{gprof} still lists it as a subroutine of functions that call it. ! 923: ! 924: The function names printed in GNU @code{gprof} output do not include ! 925: the leading underscores that are added internally to the front of all ! 926: C identifiers on many operating systems. ! 927: ! 928: The blurbs, field widths, and output formats are different. GNU ! 929: @code{gprof} prints blurbs after the tables, so that you can see the ! 930: tables without skipping the blurbs. ! 931: ! 932: @contents ! 933: @bye
This archive runs on limited infrastructure. Preserving old code on modern bandwidth. Automated agents are requested to crawl responsibly.