Re: gprof reports wrong execution times

[Anton Shepelev <anton dot txt at gmail dot com>]

I wrote:

>I  am learning gprof and cannot seem to make it re-
>port correct execution times.  I am  profiling  the
>follwing simple code:
>
>   #include "test.h"
>   #include <stdlib.h>
>   #include <stdio.h>
>   #include <time.h>
>
>   void genwait( unsigned t )
>   {    clock_t before, after;
>        unsigned i;
>        char line[3];
>        double time_sec;
>        before = clock();
>        for( i = 0; i < t; i++ )
>        {    sprintf(line, "a");  }
>        after = clock();
>        time_sec = ((double)(after - before)) / CLOCKS_PER_SEC;
>        printf( "%i cycles took %2.3g seconds.0, t, time_sec );
>   }
>
>   void wait1()
>   {    genwait(100000000);  }
>
>   void wait2()
>   {    genwait(800000000);  }
>
>   void wait3()
>   {    genwait(1600000000);  }
>
>   void WorkHard()
>   {    int i=0;
>        wait1();
>        wait2();
>        wait3();
>   }
>
>and  grpof  reports  that the wait<n> functions all
>take the same time:
>
>   index % time    self  children    called     name
>   -----------------------------------------------
>                   0.00    2.74       1/1           WorkHard [2]
>   [4]     33.3    0.00    2.74       1         wait1 [4]
>                   2.74    0.00       1/3           genwait [1]
>   -----------------------------------------------
>                   0.00    2.74       1/1           WorkHard [2]
>   [5]     33.3    0.00    2.74       1         wait2 [5]
>                   2.74    0.00       1/3           genwait [1]
>   -----------------------------------------------
>                   0.00    2.74       1/1           WorkHard [2]
>   [6]     33.3    0.00    2.74       1         wait3 [6]
>                   2.74    0.00       1/3           genwait [1]
>   -----------------------------------------------
>
>while they clearly take  different  times  to  com-
>plete, for my program writes:
>
>   100000000 cycles took 0.344 seconds.
>   800000000 cycles took 2.86 seconds.
>   1600000000 cycles took 5.7 seconds.
>

This  is  the correct and expected behavior, because
the man page says:

   The granularity of the sampling is  shown,  but  re-
   mains  statistical at best.  We assume that the time
   for each execution of a function can be expressed by
   the  total time for the function divided by the num-
   ber of times the function is called.  Thus the  time
   propagated  along  the  call graph arcs to the func-
   tion's parents is directly proportional to the  num-
   ber of times that arc is traversed.