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