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