CODEWITHSUNDEEP
ctime
fips197
fips197

Reputation: 137

Inconsistency in program running time measurement

I was doing simple test to measure the execution time of my program. So I wrote a simple program with 2 loops each iterates N times and 2N times. I expected the second loop takes about twice as long but result is contrary when N=1000000.

I've tested it several times and got same result on another machine. Why does it happen?

My code

#include <stdio.h>
#include <stdlib.h>
#include <sys/time.h>

long long sum;

int main(int argc, char **argv)
{
    int i;
    long elapsed;
    struct timeval start, end;

    i = atoi(argv[1]);
    sum = 0;
    gettimeofday(&start, NULL);
    while (i--)
        sum += i;
    gettimeofday(&end, NULL);

    elapsed = (end.tv_sec - start.tv_sec) * 1000000;
    elapsed += (end.tv_usec - start.tv_usec);
    printf("1st loop : %ld\n", elapsed);

    i = 2 * atoi(argv[1]);
    sum = 0;
    gettimeofday(&start, NULL);
    while (i--)
        sum += i;
    gettimeofday(&end, NULL);

    elapsed= (end.tv_sec - start.tv_sec) * 1000000;
    elapsed+= (end.tv_usec - start.tv_usec);
    printf("2nd loop : %ld\n", elapsed);
    return 0;
}

Some test results

[arch:test] $ ./a.out 10
1st loop : 0
2nd loop : 0
[arch:test] $ ./a.out 100
1st loop : 1
2nd loop : 1
[arch:test] $ ./a.out 1000
1st loop : 7
2nd loop : 14
[arch:test] $ ./a.out 10000
1st loop : 73
2nd loop : 146
[arch:test] $ ./a.out 100000
1st loop : 725
2nd loop : 1448
[arch:test] $ ./a.out 1000000
1st loop : 5369   <-- always greater than 2nd loop
2nd loop : 3536
[arch:test] $ ./a.out 10000000
1st loop : 20203
2nd loop : 34434
[arch:test] $ ./a.out 100000000
1st loop : 174058
2nd loop : 339812
[arch:test] $ ./a.out 1000000000
1st loop : 1709652
2nd loop : 3392287

Test environment gcc 8.2.1, compile option -O0 same result on ubuntu or arch linux but not on windows 10 with cygwin

Upvotes: 1

Views: 198

Answers (1)

Petr Skocik
Petr Skocik

Reputation: 60058

You're probably just hitting the 1st or 2nd reschedule and the half running the first loop is taking the brunt of it. gettimeofday should be using the realtime clock, so times spent on context switches do count. When you next run 10 times more iterations, the number of context switches should be approx 10 times more, so if one half takes one more context switch than the other, it's not going to make that much of a difference on average.

I wasn't able to reproduce your results so well, but if I run the executable with time -v so the # of context switches is shown, then the timings of the 1st and 2nd loops are the nearest when the number of context switches is 2 (2nd context switch).

Upvotes: 1

Related Questions