Coverage Measurement and Profiling

Here is the output from running this simple Fibonacci program:

[zfrey@warthog prof]$ time ./fib
fibonnaci(0) = 0
fibonnaci(1) = 1
fibonnaci(2) = 1
fibonnaci(3) = 2
fibonnaci(4) = 3
...
fibonnaci(40) = 102334155
fibonnaci(41) = 165580141
fibonnaci(42) = 267914296

real    3m12.580s
user    3m10.566s
sys     0m0.127s
[zfrey@warthog prof]$

Now, we can look at the profiling data:

[zfrey@warthog prof]$ gprof -b ./fib gmon.out
Flat profile:

Each sample counts as 0.00195312 seconds.

 %   cumulative   self              self     total
time   seconds   seconds    calls  ms/call  ms/call  name
95.13     16.34    16.34       43   380.02   380.02  fibonacci
 4.87     17.18     0.84                             main

                        Call graph

index % time    self  children    called     name

[1]    100.0    0.84   16.34                 main [1]
               16.34    0.00      43/43      fibonacci [2]
-----------------------------------------------
                             2269806252      fibonacci [2]
               16.34    0.00      43/43      main [1]
[2]     95.1   16.34    0.00   43+2269806252 fibonacci [2]
                             2269806252      fibonacci [2]
-----------------------------------------------

Index by function name

   [2] fibonacci               [1] main

It's obvious where this program's bottleneck is—the fibonnaci() function itself. That fact should be evident from reading the source. What our profiling tells us that is not obvious from the source is the number of recursion calls that our calculation takes. Although fibonacci() is called directly from main() only 43 times, we are making approximately 2.3 billion calls as part of the recursion.

Fortunately, there's another way. Checking our reference on Fibonacci numbers, we find that there is a formula to calculate the nth Fibonacci number directly from n:

F(n) = round(Phiⁿ / sqrt(5))

I am not going to explain the mathematics behind the derivation of this formula, for the simple reason that I don't understand them myself. With this improved algorithm, however, once again I can rebuild, run and profile (Listing 4).

#define PHI   1.6180339887498948

int fibonacci(int n)
{
   return (int) rint(pow(PHI, n) / sqrt(5));
}

Let's see what gprof tells us this time:

                        Call graph

granularity: each sample hit covers 4 byte(s) no time propagated

index % time    self  children    called     name
                0.00    0.00      43/43          main [8]
[1]      0.0    0.00    0.00      43         fibonacci [1]
-----------------------------------------------

Index by function name

   [1] fibonacci

Our program is now so much faster that the sampling process failed to register any time spent. Although this is a good result in a way, it's not so good if we want to see if any more performance improvements can be made.

A standard technique from the gprof manual is to run the program many times and summarize the results, like so:

[zfrey@warthog prof]$ mkdir runfib2; cd runfib2
[zfrey@warthog runfib2]$ for i in `seq 1 1000` ; \
do ../fib2 > /dev/null; mv gmon.out gmon.out.$i; done
[zfrey@warthog runfib2]$ gprof -s ../fib2 gmon.out.*

The results, though, still show the time spent as 0.00. Clearly, a different approach is called for. I now create fib3.c, with two changes. First, I enclose the 0–42 loop with an additional 0–1000 loop, to increase our runtime. Second, I add a local variable to the fibonacci() function and break the calculation apart to one operation per line for line-by-line profiling. This gives us enough runtime that gprof has something to report:

#include <stdio.h>
#include <math.h>

int fibonacci(int n);

int main (int argc, char **argv)
{
   int fib;
   int n;
   int i;

   for (i = 0; i < 1000; i++) {
      for (n = 0; n <= 42; n++) {
         fib = fibonacci(n);
         printf("fibonnaci(%d) = %d\n", n, fib);
      }
   }

   return 0;
}

#define PHI   1.6180339887498948

int fibonacci(int n)
{
   double temp;

   temp = pow(PHI,n);
   temp = temp / sqrt(5);
   return (int) rint(temp);
}

Before doing a line-by-line report, though, I create a multirun summary, as before.

Now, let's look at the line-by-line report (trimmed to fit):

[zfrey@warthog runfib3]$ gprof -b -l -p ../fib3 gmon.sum
Flat profile:

Each sample counts as 0.00195312 seconds.
 %   cumulative   self             self     total
time   seconds   seconds   calls  ps/call  ps/call  name
38.25      1.12     1.12                            fibonacci (fib3.c:31)
27.97      1.94     0.82                            fibonacci (fib3.c:30)
14.49      2.36     0.42                            fibonacci (fib3.c:29)
 5.91      2.53     0.17                            main (fib3.c:16)
 4.64      2.67     0.14                            main (fib3.c:15)
 3.14      2.76     0.09                            fibonacci (fib3.c:32)
 1.87      2.82     0.05                            main (fib3.c:14)
 1.54      2.86     0.04                            main (fib3.c:14)
 0.83      2.89     0.02 43000000   567.77   567.77 fibonacci (fib3.c:26)
 0.77      2.91     0.02                            main (fib3.c:21)
 0.53      2.92     0.02                            main (fib3.c:13)
 0.07      2.93     0.00                            main (fib3.c:20)

The highest percentage of time is spent on line 31, followed by line 30. There is nothing we can do about line 31, because the printf() call and the function return are essential operations. However, on line 30, notice that we are calculating the square root of 5 every time. Because this result never changes, the next optimization should be to replace it with a constant. This cuts the execution time from 136 milliseconds to 22 milliseconds.