gprof Example
Here is some hypothetical gprof output from the example code. It shows
the basic "flat" profile, which details the time spent per subroutine call based on sampling.
| Percent time | cumulative sec | self sec | calls | self ms/call | total ms/call | name |
|---|---|---|---|---|---|---|
| 86.21 | 145.6 | 145.6 | 42 | 3468 | 3468 | subz_ |
| 8.18 | 159.4 | 13.8 | 2 | 6910 | 76262 | subaa_ |
| 4.10 | 166.5 | 6.9 | 2 | 3465 | 6933 | subcc_ |
| 0.72 | 167.6 | 1.2 | 2 | 610 | 76872 | suba_ |
| 0.52 | 168.5 | 0.88 | 2 | 440 | 7372 | subc_ |
| 0.26 | 168.9 | 0.44 | 2 | 440 | 168930 | main |
| 0.01 | 168.9 | 0.01 | 1 | write |
Each function in the program is reported in a list sorted by the percentage of total execution time they account for ("Percent time"). The second column, "cumulative sec," is the total execution time for the listed function added to the total execution time for all functions listed above it. This column is very useful in targeting optimization efforts. The third column, "self sec," lists the total execution time spent in the listed function in seconds. This includes every invocation of the function. The fourth column, "calls," is the total number of times the listed function was called during the profiling run.
The fifth column, "self ms/call," is the average number of milliseconds spent in each invocation of the function. The sixth column, "total ms/call," is the average number of milliseconds spent in each invocation of the function including all other functions called by the listed function. The seventh and last column gives the function name. Fortran function names are often followed by an underscore based on the behavior of the linker.
In this example, the vast majority of the execution time, 86.21 percent, is spent in the subz function, called 42 times in the execution of the
program. Therefore, subz is the obvious choice for further investigation.