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