problem with the output in my C program (gives unexpected output)

Question

What is the problem with this program it is supposed to calculate the elapsed time of each function call but to my surprise, the elapsed time is always ZERO because the begin and end are exactly the same. Does anyone have an explanation for this?

This is the output I get:

TIMING TEST: 10000000 calls to rand()

   2113   6249  23817  12054   7060   9945  26819
  13831   6820  14149  13035  30858  13924  26467
   4268  11314  28400   5239   4496  27757  21452
  10878  25064   9049   6508  29612  11373  29913
  10234  31769  16167  24553   1875  23992  30606
   2606  19539   2184  14832  27089  27474  23310
, .. , ,

End time: 1610034404
Begin time: 1610034404
Elapsed time: 0
Time for each call:,10f

Here is the code:

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

#define NCALLS 10000000
#define NCOLS  7
#define NLINES 7

int main(void) {
    int i, val;
    long begin, diff, end;

    begin = time(NULL);
    srand(time(NULL));
    printf("\nTIMING TEST: %d calls to rand()\n\n", NCALLS);
    for (i = 1; i <= NCALLS; ++i) {
        val = rand();
        if (i <= NCOLS * NLINES) {
            printf("%7d", val);
            if (i % NCOLS == 0)
                putchar('\n');
        } else
        if (i == NCOLS * NLINES + 1)
            printf("%7s\n\n", ", .. , ,");
    }
    end = time(NULL);
    diff = end - begin;
    printf("%s%ld\n%s%ld\n%s%ld\n%s%,10f\n\n",
           "End time: ", end,
           "Begin time: ", begin,
           "Elapsed time: ", diff,
           "Time for each call:", (double)diff / NCALLS);
    return 0;
}

Isn't it because the process only takes a few milliseconds (too short for the time to change)? — MikeCAT, Jan 07 '21 at 15:55
`time()` returns whole seconds, you probably want something like `clock_gettime()` or `gettimeofday()`. — Cheatah, Jan 07 '21 at 15:57
Your `for` loop effectively does nothing when `i > 50`, and a good compiler will spot that and optimize out the loops after the 50th. — Adrian Mole, Jan 07 '21 at 16:01
@AdrianMole Assuming it can determine that the state of the PRNG isn't used after the loop. That's possible, but not that likely. — David Schwartz, Jan 07 '21 at 16:10
@DavidSchwartz Yeah. I tried OP's code but with a `sum += val` added in the loop - and it still showed zero seconds. — Adrian Mole, Jan 07 '21 at 16:11

Kanony · Answer 1 · 2021-01-08T07:53:50.667

4

instead of time(NULL) you can use clock()

time_t t1 = clock();

// your code

time_t t2 = clock();

printf("%f", (double)(t2 - t1) / CLOCKS_PER_SEC); // you have to divide it to CLOCKS_PER_SEC (1 000 000) if you want time in seconds

time() measures in seconds, so if your program doesn't take 1 second you won't see difference

Someone in stackoverflow has already answered difference between them time() vs clock()

edited Jan 08 '21 at 07:53

answered Jan 07 '21 at 16:07

Kanony

509
2
12

2

Note that `clock` measures processor time while `time` measures wall time. – David Schwartz Jan 07 '21 at 16:14
1

You might introduce your proposal with an explanation for the OP's observation: `time()` has a 1 second resolution, which is too large to measure the program execution time. – chqrlie Jan 07 '21 at 21:10

score 1 · Answer 2 · answered Jan 07 '21 at 18:44

Changing your code just to spend some random time inside the loop using a system call a few times, using

        struct stat file_stat;
        for( int j = 0; j < rand()%(1000); j+=1) stat(".", &file_stat);

and we get on a very old machine (for 10,000 and not 10,000,000 cycles as in your code)

toninho@DSK-2009:/mnt/c/Users/toninho/projects/um$ gcc -std=c17 -Wall tlim.c
toninho@DSK-2009:/mnt/c/Users/toninho/projects/um$ ./a.out

TIMING TEST: 10000 calls to rand()

   953019096   822572575   552766679  1101222688   890440097
   348966778  1483436091  1936203136  1060888701   936990601
   524198868   554412390  1109472424    51262334   723194231
   353522463  1808580291   673860068   818332399   350403991
   442567054  1054917195   229398907   420744931   620127925
  1975661852   812007818  1400791797  1471940068  1739247840
  1364643097   529639947  1569398779    20035674    92849903
  1060567289  1126157009  2111376669   324165122   338724259
   719809477   977786583   510114270   981390269  2029486195
  1551025212  1112929616  2091082251  1066603801  1722106156
, .. , ,

End time: 1610044947
Begin time: 1610044942
Elapsed time: 5
Time for each call:500.000000

Using

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

#define NCALLS 10 * 1000 
#define NCOLS 5
#define NLINES 10

int main(void)
{
    int i, val;
    long begin, diff, end;

    begin = time(NULL);
    srand(210701);
    printf("\nTIMING TEST: %d calls to rand()\n\n", NCALLS);
    for (i = 1; i <= NCALLS; ++i)
    {
        val = rand();
        // spend some time
        struct stat file_stat;
        for( int j = 0; j < rand()%(1000); j+=1) stat(".", &file_stat);

        if (i <= NCOLS * NLINES)
        {
            printf("%12d", val);
            if (i % NCOLS == 0)
                putchar('\n');
        }
        else if (i == NCOLS * NLINES + 1)
            printf("%7s\n\n", ", .. , ,");

        //printf("%7d:  ", i);
        //fgetc(stdin);
    };  // for
    end = time(NULL);
    diff = end - begin;
    printf("%s%ld\n%s%ld\n%s%ld\n%s%10f\n\n", // %
           "End time: ", end,
           "Begin time: ", begin,
           "Elapsed time: ", diff,
           "Time for each call:", (double)diff / NCALLS);
    return 0;
}

You may want to use `(double)diff / (NCALLS)` because of how you've defined NCALLS as 10 * 1000, or else you will get an incorrect answer for avg time per call. — Ankur Agarwal, Jun 13 '21 at 00:27

problem with the output in my C program (gives unexpected output)

2 Answers2