GNU gprof: Line-by-line

Next: , Previous: , Up: Output   [Contents]

5.3 Line-by-line Profiling

gprof’s ‘-l’ option causes the program to perform line-by-line profiling. In this mode, histogram samples are assigned not to functions, but to individual lines of source code. This only works with programs compiled with older versions of the gcc compiler. Newer versions of gcc use a different program - gcov - to display line-by-line profiling information.

With the older versions of gcc the program usually has to be compiled with a ‘-g’ option, in addition to ‘-pg’, in order to generate debugging symbols for tracking source code lines. Note, in much older versions of gcc the program had to be compiled with the ‘-a’ command line option as well.

The flat profile is the most useful output table in line-by-line mode. The call graph isn’t as useful as normal, since the current version of gprof does not propagate call graph arcs from source code lines to the enclosing function. The call graph does, however, show each line of code that called each function, along with a count.

Here is a section of gprof’s output, without line-by-line profiling. Note that ct_init accounted for four histogram hits, and 13327 calls to init_block. 

Flat profile:
Each sample counts as 0.01 seconds.
  %   cumulative   self              self     total
 time   seconds   seconds    calls  us/call  us/call  name
 30.77      0.13     0.04     6335     6.31     6.31  ct_init
		     Call graph (explanation follows)
granularity: each sample hit covers 4 byte(s) for 7.69% of 0.13 seconds
index % time    self  children    called     name
                0.00    0.00       1/13496       name_too_long
                0.00    0.00      40/13496       deflate
                0.00    0.00     128/13496       deflate_fast
                0.00    0.00   13327/13496       ct_init
[7]      0.0    0.00    0.00   13496         init_block

Now let’s look at some of gprof’s output from the same program run, this time with line-by-line profiling enabled. Note that ct_init’s four histogram hits are broken down into four lines of source code—one hit occurred on each of lines 349, 351, 382 and 385. In the call graph, note how ct_init’s 13327 calls to init_block are broken down into one call from line 396, 3071 calls from line 384, 3730 calls from line 385, and 6525 calls from 387. 

Flat profile:
Each sample counts as 0.01 seconds.
  %   cumulative   self
 time   seconds   seconds    calls  name
  7.69      0.10     0.01           ct_init (trees.c:349)
  7.69      0.11     0.01           ct_init (trees.c:351)
  7.69      0.12     0.01           ct_init (trees.c:382)
  7.69      0.13     0.01           ct_init (trees.c:385)
		     Call graph (explanation follows)
granularity: each sample hit covers 4 byte(s) for 7.69% of 0.13 seconds
  % time    self  children    called     name
            0.00    0.00       1/13496       name_too_long (gzip.c:1440)
            0.00    0.00       1/13496       deflate (deflate.c:763)
            0.00    0.00       1/13496       ct_init (trees.c:396)
            0.00    0.00       2/13496       deflate (deflate.c:727)
            0.00    0.00       4/13496       deflate (deflate.c:686)
            0.00    0.00       5/13496       deflate (deflate.c:675)
            0.00    0.00      12/13496       deflate (deflate.c:679)
            0.00    0.00      16/13496       deflate (deflate.c:730)
            0.00    0.00     128/13496       deflate_fast (deflate.c:654)
            0.00    0.00    3071/13496       ct_init (trees.c:384)
            0.00    0.00    3730/13496       ct_init (trees.c:385)
            0.00    0.00    6525/13496       ct_init (trees.c:387)
[6]  0.0    0.00    0.00   13496         init_block (trees.c:408)

Next: , Previous: , Up: Output   [Contents]