First cut not the deepest?

[Brian Gladman]

----- Original Message ----- 
From: "Jim White" <mathimagics at yahoo.co.uk>
To: <gmp-discuss at swox.com>
Sent: Friday, March 23, 2007 6:36 AM
Subject: First cut not the deepest?


>
> Does Windows cause brain damage?
>
> Runnng timing comparisons under Windows is always a
> trifle dodgy, but the anomaly I am seeing is
> particularly baffling.
>
> The test is simple enough. Repeat some non-trivial
> operation R times, report the time taken. Do that that
> N times.
>
> Using either a static or shared library built for a
> Pentium 4 under MinGW, I am consistently getting a
> series of times that increase fairly quickly, then
> seem to stabilise at just under twice the time taken
> for the first set.
>
> For example, here the test program is mpz_mul-ing two
> arguments of about 8K limbs, 1000 times a set:
>
>> test -p 8192 -r 1000 -n 10
> 16:48:38  start test, ops/set = 1000, nreps = 10
> 16:48:47  time =  8.625000
> 16:48:58  time = 11.672000
> 16:49:11  time = 12.734000
> 16:49:24  time = 13.282000
> 16:49:38  time = 13.734000
> 16:49:52  time = 14.109000
> 16:50:06  time = 14.250000
> 16:50:21  time = 14.453000
> 16:50:35  time = 14.500000
> 16:50:50  time = 14.579000
> 16:50:50  avg  = 13.193800
>
> The test program records the real-time clock as well
> as the calculated times, because I had to convince
> myself that the calculated times were right!
>
> This same trend is produced, regardless of whether I
> hammer mpz_mul, or mpf_div, or mpfr_cos.
>
> Has my obtuseness become acute (so to speak!), or is
> there something going on in there?
>
> Cheers
> Jim White
> ANU, Canberra
>
> -------------------------------------------
>> type test.c
>
> #include <stdio.h>
> #include <time.h>
> #include "gmp_static.h"
>
> mpz_t  X1, X2, Y;
> int    TSTART, TNOW;
>
> double GetClock() {return ((double)(TNOW -
> TSTART)/1000.0);}
> char   timenow[32];
> char  *dclock() {  // time-of-day ("hh:mm:ss")
>   time_t etime; time(&etime);
>   char *tnow = (char *) ctime(&etime);
>   strncpy (timenow, tnow, 20);
>   timenow[20] = 0;
>   return (&timenow[11]);
>   }
> //----------------------
>
> int main (int argc, char *argv[]) {
>    int i, p;
>    int k = 1;
>    int r = 1000;
>    int nreps = 1;
>
>    while (k < argc) {
>       if (strcmp(argv[k],"-p")  == 0) { k++;     p =
> atoi(argv[k]); }
>       if (strcmp(argv[k],"-r")  == 0) { k++;     r =
> atoi(argv[k]); }
>       if (strcmp(argv[k],"-n")  == 0) { k++; nreps =
> atoi(argv[k]); }
>       k++;
>       }
>    mpz_init2  (X1, 32*p);
>    mpz_init2  (X2, 32*p);
>    mpz_init2  (Y,  32*p);
>
>    double xtime, rtime;
>
>    // Set test operands
>
>    mpz_set_ui (X1, 3); mpz_set_ui (X2, 3);
>    while (X1->_mp_size < (p/2)) {
>       mpz_add_ui (X2, X2, 2);
>       mpz_mul    (X1, X1, X2);
>       }
>    mpz_mul    (X2, X1, X1);
>    mpz_add_ui (X1, X1,  1);
>
>    // Timing tests
>    rtime = 0.0;
>    printf ("%s start test, ops/set = %d, nreps =
> %d\n", dclock(), r, nreps);
>    for  (k = 0; k < nreps; k++) {
>          TSTART = clock();
>          for (i=0; i < r; i++) mpz_mul (Y, X1, X2);
>          TNOW   = clock();
>          xtime  = GetClock();
>          rtime += xtime;
>          printf ("%s time = %f\n", dclock(), xtime);
>          }
>    rtime /= nreps;
>    printf ("%s avg  = %f\n", dclock(), rtime);
>    }

I get consistent results on a 1.8GHz P4 machine running a Microsoft compiled 
32-bit version of GMP:

test -p 8192 -r 1000 -n 10
08:48:54  start test, ops/set = 1000, nreps = 10
08:49:06  time = 11.306000
08:49:17  time = 11.136000
08:49:28  time = 11.086000
08:49:39  time = 11.076000
08:49:50  time = 11.056000
08:50:01  time = 11.086000
08:50:12  time = 11.076000
08:50:23  time = 11.055000
08:50:34  time = 11.066000
08:50:46  time = 11.066000
08:50:46  avg  = 11.100900

     Brian Gladman