clock_gettime() Vs. gettimeofday() for measuring OpenMP execution time

Question

I am working on some C code that is implementing a triple nested for loop to calculate matrix-matrix multiplication while parallelizing it using OpenMP. I am trying to accurately measure the amount of time it takes from when the for loop starts to when it ends. I have been using gettimeofday() so far but I noticed that sometimes it did not feel like it was accurately recording the amount of time it took for the for loop to execute. It seemed as if it was saying that it is took longer than it actually did.

Here is the original code:

struct timeval start end;
double elapsed;

gettimeofday(&start, NULL);
#pragma omp parallel for num_threads(threads) private(i, j, k)
for(...)
{
 ...
 for(...)
 {
  ...
  for(...)
  {
   ...
  }
 }
}

gettimeofday(&end, NULL);
elapsed = (end.tv_sec+1E-6*end.tv_usec) - (start.tv_sec+1E-6*start.tv_usec)

And here is the same code using clock_gettime():

 struct timespec start1, finish1;
 double elapsed1;

clock_gettime(CLOCK_MONOTONIC, &start1);

  #pragma omp parallel for num_threads(threads) private(i, j, k)
    for(...)
    {
     ...
     for(...)
     {
      ...
      for(...)
      {
       ...
      }
     }
    }

clock_gettime(CLOCK_MONOTONIC, &finish1);
elapsed1 = (finish1.tv_sec - start1.tv_sec);
elapsed1 += (finish1.tv_nsec - start1.tv_nsec)/1000000000.0;

The loop takes 3-4 seconds to complete and I tried using both time measurements at the same time and the result from using gettimeofday() was almost always longer than the result from clock_gettime() and sometimes was over a second longer than the result I was getting using clock_gettime():

struct timespec start1, finish1;
double elapsed1;

struct timeval start end;
double elapsed;

clock_gettime(CLOCK_MONOTONIC, &start1);
gettimeofday(&start, NULL);

  #pragma omp parallel for num_threads(threads) private(i, j, k)
    for(...)
    {
     ...
     for(...)
     {
      ...
      for(...)
      {
       ...
      }
     }
    }

gettimeofday(&end, NULL);
clock_gettime(CLOCK_MONOTONIC, &finish1);

elapsed = (end.tv_sec+1E-6*end.tv_usec) - (start.tv_sec+1E-6*start.tv_usec)

elapsed1 = (finish1.tv_sec - start1.tv_sec);
elapsed1 += (finish1.tv_nsec - start1.tv_nsec)/1000000000.0;

Is there a reason for this? What could be causing a difference when using these two functions? I'm trying to gain a better understanding of the nature of these two functions.

Answer 1

elapsed = (end.tv_sec+1E-6*end.tv_usec) - (start.tv_sec+1E-6*start.tv_usec) is prone to precision lost when subtracting like values that are both large.

1. Use elapsed = (end.tv_sec - start.tv_sec) - (start.tv_usec- end.tv_usec)/1E6. This is like OP's 2nd and 3rd code, but not first.

2. Be fair, get times in a consistent order to remove bias.

   clock_gettime(CLOCK_MONOTONIC, &start1);
   gettimeofday(&start, NULL);
   
   ...
   
   // gettimeofday(&end, NULL);
   // clock_gettime(CLOCK_MONOTONIC, &finish1);
   clock_gettime(CLOCK_MONOTONIC, &finish1);
   gettimeofday(&end, NULL);
   

3. Minor: A 3rd, though very subtle improvement that helps reduce inconsistency a little bit (0.5 usec), is to start the test on a tick change. But note @Dietrich Epp comment for an alternative improvement.

   gettimeofday(&t, NULL);
   do { 
     gettimeofday(&start, NULL);
   } while (start == t);
   

Alternatively, use wide integer math to avoid precision issues

long long elapsed_ns = (1LL*finish1.tv_sec - start1.tv_sec)*1000000000LL + 
    finish1.tv_nsec - start1.tv_nsec;