5.1 The Flat Profile

The flat profile shows the total amount of time your program spent executing each function. Unless the ‘-z’ option is given, functions with no apparent time spent in them, and no apparent calls to them, are not mentioned. Note that if a function was not compiled for profiling, and didn’t run long enough to show up on the program counter histogram, it will be indistinguishable from a function that was never called.

This is part of a flat profile for a small program:

Flat profile:
Each sample counts as 0.01 seconds.
  %   cumulative   self              self     total
 time   seconds   seconds    calls  ms/call  ms/call  name
 33.34      0.02     0.02     7208     0.00     0.00  open
 16.67      0.03     0.01      244     0.04     0.12  offtime
 16.67      0.04     0.01        8     1.25     1.25  memccpy
 16.67      0.05     0.01        7     1.43     1.43  write
 16.67      0.06     0.01                             mcount
  0.00      0.06     0.00      236     0.00     0.00  tzset
  0.00      0.06     0.00      192     0.00     0.00  tolower
  0.00      0.06     0.00       47     0.00     0.00  strlen
  0.00      0.06     0.00       45     0.00     0.00  strchr
  0.00      0.06     0.00        1     0.00    50.00  main
  0.00      0.06     0.00        1     0.00     0.00  memcpy
  0.00      0.06     0.00        1     0.00    10.11  print
  0.00      0.06     0.00        1     0.00     0.00  profil
  0.00      0.06     0.00        1     0.00    50.00  report
…

The functions are sorted first by decreasing run-time spent in them, then by decreasing number of calls, then alphabetically by name. The functions ‘mcount’ and ‘profil’ are part of the profiling apparatus and appear in every flat profile; their time gives a measure of the amount of overhead due to profiling.

Just before the column headers, a statement appears indicating how much time each sample counted as. This sampling period estimates the margin of error in each of the time figures. A time figure that is not much larger than this is not reliable. In this example, each sample counted as 0.01 seconds, suggesting a 100 Hz sampling rate. The program’s total execution time was 0.06 seconds, as indicated by the ‘cumulative seconds’ field. Since each sample counted for 0.01 seconds, this means only six samples were taken during the run. Two of the samples occurred while the program was in the ‘open’ function, as indicated by the ‘self seconds’ field. Each of the other four samples occurred one each in ‘offtime’, ‘memccpy’, ‘write’, and ‘mcount’. Since only six samples were taken, none of these values can be regarded as particularly reliable. In another run, the ‘self seconds’ field for ‘mcount’ might well be ‘0.00’ or ‘0.02’. See Statistical Sampling Error, for a complete discussion.

The remaining functions in the listing (those whose ‘self seconds’ field is ‘0.00’) didn’t appear in the histogram samples at all. However, the call graph indicated that they were called, so therefore they are listed, sorted in decreasing order by the ‘calls’ field. Clearly some time was spent executing these functions, but the paucity of histogram samples prevents any determination of how much time each took.

Here is what the fields in each line mean:

% time

This is the percentage of the total execution time your program spent in this function. These should all add up to 100%.

cumulative seconds

This is the cumulative total number of seconds the computer spent executing this functions, plus the time spent in all the functions above this one in this table.

self seconds

This is the number of seconds accounted for by this function alone. The flat profile listing is sorted first by this number.

calls

This is the total number of times the function was called. If the function was never called, or the number of times it was called cannot be determined (probably because the function was not compiled with profiling enabled), the calls field is blank.

self ms/call

This represents the average number of milliseconds spent in this function per call, if this function is profiled. Otherwise, this field is blank for this function.

total ms/call

This represents the average number of milliseconds spent in this function and its descendants per call, if this function is profiled. Otherwise, this field is blank for this function. This is the only field in the flat profile that uses call graph analysis.

name

This is the name of the function. The flat profile is sorted by this field alphabetically after the self seconds and calls fields are sorted.