Quantcast

Strange gprof results

classic Classic list List threaded Threaded
8 messages Options
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Strange gprof results

Anton Shepelev
Hello, all

I am learning gprof in MinGW and cannot seem to make
it report correct execution times.  I  am  profiling
the follwing simple code:

   #include "test.h"
   #include <stdlib.h>
   #include <stdio.h>

   void genwait( unsigned t )
   {    unsigned i;
        char line[3];
        for( i = 0; i < t; i++ )
        {    sprintf(line, "a");  }
   }

   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:

   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 complete.
I am compiling this  code  with  optimizations  off:
-O0.   My  full setup including the Makefile is here
on Google Drive:

         http://preview.tinyurl.com/hda7sez

Beware my dangerous 'clean' target which will delete
all executables in the current directory and below.

If  it  be a blunder of mine rather than a MinGW-re-
lated problem, please accept my apologies.

--
()  ascii ribbon campaign - against html e-mail
/\  http://preview.tinyurl.com/qcy6mjc [archived]


------------------------------------------------------------------------------
_______________________________________________
MinGW-users mailing list
[hidden email]

This list observes the Etiquette found at
http://www.mingw.org/Mailing_Lists.
We ask that you be polite and do the same.  Disregard for the list etiquette may cause your account to be moderated.

_______________________________________________
You may change your MinGW Account Options or unsubscribe at:
https://lists.sourceforge.net/lists/listinfo/mingw-users
Also: mailto:[hidden email]?subject=unsubscribe
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: Strange gprof results

Manolo-15
>    void genwait( unsigned t )
>    {    unsigned i;
>         char line[3];
>         for( i = 0; i < t; i++ )
>         {    sprintf(line, "a");  }
>    }

I guess the linker optimized (despite of -O0 flag) this function.
I'd try with a for loop that really uses 'i' and 't'.

> while they clearly take different times to complete.

How do you know this? Have you measured times?

Regards,
Manolo

------------------------------------------------------------------------------
_______________________________________________
MinGW-users mailing list
[hidden email]

This list observes the Etiquette found at
http://www.mingw.org/Mailing_Lists.
We ask that you be polite and do the same.  Disregard for the list etiquette may cause your account to be moderated.

_______________________________________________
You may change your MinGW Account Options or unsubscribe at:
https://lists.sourceforge.net/lists/listinfo/mingw-users
Also: mailto:[hidden email]?subject=unsubscribe
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: Strange gprof results

Anton Shepelev
Manolo to Anton Shepelev:

>>while  they  clearly  take different times to com-
>>plete.
>
>How do you know this? Have you measured times?

I measured the times manually, but here I do  it  in
the 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.\n", t, time_sec );
   }

   void wait1()
   {    genwait(100000000);  }

   void wait2()
   {    genwait(800000000);  }

   void wait3()
   {    genwait(1600000000);  }

   void WorkHard()
   {    int i=0;
        wait1();
        wait2();
        wait3();
   }

And the program outputs different execution times:

   100000000 cycles took 0.344 seconds.
   800000000 cycles took 2.86 seconds.
   1600000000 cycles took 5.7 seconds.

The modified test sample is here:

         http://preview.tinyurl.com/jdtecwk

but  gprof still shows the average time of about 2.7
seconds for each test run.


------------------------------------------------------------------------------
_______________________________________________
MinGW-users mailing list
[hidden email]

This list observes the Etiquette found at
http://www.mingw.org/Mailing_Lists.
We ask that you be polite and do the same.  Disregard for the list etiquette may cause your account to be moderated.

_______________________________________________
You may change your MinGW Account Options or unsubscribe at:
https://lists.sourceforge.net/lists/listinfo/mingw-users
Also: mailto:[hidden email]?subject=unsubscribe
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: Strange gprof results

DAVENPORT, MARC

I haven't been able to get gprof to output results that make any sense for some time now. I'd be interested if you actually get it to work.

Marc


On Sep 14, 2016 11:34 AM, "Anton Shepelev" <[hidden email]> wrote:
Manolo to Anton Shepelev:

>>while  they  clearly  take different times to com-
>>plete.
>
>How do you know this? Have you measured times?

I measured the times manually, but here I do  it  in
the 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.\n", t, time_sec );
   }

   void wait1()
   {    genwait(100000000);  }

   void wait2()
   {    genwait(800000000);  }

   void wait3()
   {    genwait(1600000000);  }

   void WorkHard()
   {    int i=0;
        wait1();
        wait2();
        wait3();
   }

And the program outputs different execution times:

   100000000 cycles took 0.344 seconds.
   800000000 cycles took 2.86 seconds.
   1600000000 cycles took 5.7 seconds.

The modified test sample is here:

         http://preview.tinyurl.com/jdtecwk

but  gprof still shows the average time of about 2.7
seconds for each test run.


------------------------------------------------------------------------------
_______________________________________________
MinGW-users mailing list
[hidden email]

This list observes the Etiquette found at
http://www.mingw.org/Mailing_Lists.
We ask that you be polite and do the same.  Disregard for the list etiquette may cause your account to be moderated.

_______________________________________________
You may change your MinGW Account Options or unsubscribe at:
https://lists.sourceforge.net/lists/listinfo/mingw-users
Also: mailto:[hidden email]?subject=unsubscribe

------------------------------------------------------------------------------

_______________________________________________
MinGW-users mailing list
[hidden email]

This list observes the Etiquette found at
http://www.mingw.org/Mailing_Lists.
We ask that you be polite and do the same.  Disregard for the list etiquette may cause your account to be moderated.

_______________________________________________
You may change your MinGW Account Options or unsubscribe at:
https://lists.sourceforge.net/lists/listinfo/mingw-users
Also: mailto:[hidden email]?subject=unsubscribe
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: Strange gprof results

Anton Shepelev
In reply to this post by Anton Shepelev
I wrote:

> The modified test sample is here:
> http://preview.tinyurl.com/jdtecwk

Archive updated:  http://preview.tinyurl.com/hya9ody

Whereas the problem exists outside MinGW, I will post
it on the GNU mailing list.


------------------------------------------------------------------------------
_______________________________________________
MinGW-users mailing list
[hidden email]

This list observes the Etiquette found at
http://www.mingw.org/Mailing_Lists.
We ask that you be polite and do the same.  Disregard for the list etiquette may cause your account to be moderated.

_______________________________________________
You may change your MinGW Account Options or unsubscribe at:
https://lists.sourceforge.net/lists/listinfo/mingw-users
Also: mailto:[hidden email]?subject=unsubscribe
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: Strange gprof results

Anton Shepelev
In reply to this post by Anton Shepelev
I wrote:

>and grpof reports that the wait<n> functions:
>
>   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.

This is correct, expected behavior  for  gprof,  for
according to the man page:

   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.

Does anyone know of another profiler with a  similar
CLI interface but without this averaging of the exe-
cution times of the chilren?


------------------------------------------------------------------------------
_______________________________________________
MinGW-users mailing list
[hidden email]

This list observes the Etiquette found at
http://www.mingw.org/Mailing_Lists.
We ask that you be polite and do the same.  Disregard for the list etiquette may cause your account to be moderated.

_______________________________________________
You may change your MinGW Account Options or unsubscribe at:
https://lists.sourceforge.net/lists/listinfo/mingw-users
Also: mailto:[hidden email]?subject=unsubscribe
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: Strange gprof results

Anton Shepelev
In reply to this post by DAVENPORT, MARC
Marc Davenport:

>I  haven't been able to get gprof to output results
>that make any sense for some time now. I'd  be  in-
>terested if you actually get it to work.

Now  that  my question is answered, I wonder in what
way grpof output was not senseful to you.


------------------------------------------------------------------------------
_______________________________________________
MinGW-users mailing list
[hidden email]

This list observes the Etiquette found at
http://www.mingw.org/Mailing_Lists.
We ask that you be polite and do the same.  Disregard for the list etiquette may cause your account to be moderated.

_______________________________________________
You may change your MinGW Account Options or unsubscribe at:
https://lists.sourceforge.net/lists/listinfo/mingw-users
Also: mailto:[hidden email]?subject=unsubscribe
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: Strange gprof results

Bostjan Mihoric
In reply to this post by DAVENPORT, MARC
On Wed, Sep 14, 2016 at 7:13 PM, DAVENPORT, MARC <[hidden email]> wrote:
> I haven't been able to get gprof to output results that make any sense for
> some time now. I'd be interested if you actually get it to work.
>
> Marc
>

Read this.
http://yosefk.com/blog/how-profilers-lie-the-cases-of-gprof-and-kcachegrind.html

Personally, I stay away from tools that perform statistics instead of
actual measurements. I prefer to profile manually.

Regards,
Bostjan

------------------------------------------------------------------------------
Check out the vibrant tech community on one of the world's most
engaging tech sites, SlashDot.org! http://sdm.link/slashdot
_______________________________________________
MinGW-users mailing list
[hidden email]

This list observes the Etiquette found at
http://www.mingw.org/Mailing_Lists.
We ask that you be polite and do the same.  Disregard for the list etiquette may cause your account to be moderated.

_______________________________________________
You may change your MinGW Account Options or unsubscribe at:
https://lists.sourceforge.net/lists/listinfo/mingw-users
Also: mailto:[hidden email]?subject=unsubscribe
Loading...