Strange results while measuring delta time on Linux

Question

Update: fixed delta calculations in code, still the issue remains

Folks, could you please explain why I'm getting very strange results from time to time using the following code:

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

int main()
{
  struct timeval start, end;
  long mtime1, mtime2, diff;

  while(1)
  {
    gettimeofday(&start, NULL);

    usleep(2000);

    gettimeofday(&end, NULL);

    mtime1 = (start.tv_sec * 1000 + start.tv_usec/1000.0);
    mtime2 = (end.tv_sec * 1000 + end.tv_usec/1000.0);

    diff = mtime2 - mtime1;
    if(diff > 10) 
        printf("WTF: %ld\n", diff);
  }

  return 0;
}

(You can compile and run it with: gcc test.c -o out -lrt && ./out)

What I'm experiencing is sporadic big values of diff variable almost every second or even more often, e.g:

$ gcc test.c -o out -lrt && ./out 
WTF: 14
WTF: 11
WTF: 11
WTF: 11
WTF: 14
WTF: 13
WTF: 13
WTF: 11
WTF: 16

How can this be possible? Is it OS to blame? Does it do too much context switching? But my box is idle( load average: 0.02, 0.02, 0.3).

Here is my Linux kernel version:

$ uname -a
Linux kurluka 2.6.31-21-generic #59-Ubuntu SMP Wed Mar 24 07:28:56 UTC 2010 i686 GNU/Linux

Answer 1

The sleep functions only make sure that you sleep AT LEAST a certain amount of time. As Linux is not a real time OS, you CAN NOT be sure that it will sleep ONLY the amount of time you want. It is a problem as you CAN NOT count on that value. As you have pointed out, it happens that the sleep time is really BIG.

The Linux scheduler can not guarantee that. With a real time OS you can get that.

Your formula is wrong in a way, but I think that can not be the reason why you have such big sleep time. I check the two formulae with this snippet, and I have the same result :

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

int main()
{
  struct timeval start, end;
  long mtime, mtime2, start_time, end_time, seconds, useconds;

  while(1)
  {
    gettimeofday(&start, NULL);

    usleep(2000);

    gettimeofday(&end, NULL);

    seconds  = end.tv_sec  - start.tv_sec;
    useconds = end.tv_usec - start.tv_usec;

    mtime = ((seconds) * 1000 + useconds/1000.0) + 0.5;

    start_time = ((start.tv_sec) * 1000 + start.tv_usec/1000.0) + 0.5;
    end_time = ((end.tv_sec) * 1000 + end.tv_usec/1000.0) + 0.5;

    mtime2 = end_time - start_time;

    if(mtime > 10 || mtime2 > 10)
    {
      printf("WTF: %ld\n", mtime);
      printf("WTF2: %ld\n", mtime2);
    }
  }

  return 0;
}

The results :

$ gcc test.c -o out -lrt && ./out
WTF: 11
WTF2: 12
WTF: 21
WTF2: 21

I thought it wrong as the useconds part is cyclic and could lead to a big negative difference. But it will not lead to such big time as you use signed long integers ...

my2cents

Edit : from man nanosleep :

The current implementation of nanosleep() is based on the normal kernel timer mechanism, which has a resolution of 1/HZ s (see time(7)). Therefore, nanosleep() pauses always for at least the specified time, however it can take up to 10 ms longer than specified until the process becomes runnable again. For the same reason, the value returned in case of a delivered signal in *rem is usually rounded to the next larger multiple of 1/HZ s.