strange nonmonotonic behavior of gettimeoftheday

strange nonmonotonic behavior of gettimeoftheday

[John Being]

I've got following problem with 2.2.17 (Redhat stock kernel)
Linux ***** 2.2.17-14 #1 Mon Feb 5 14:57:25 EST 2001 i586 unknown
on AMD K6,  VIA Technologies VT 82C586, Compaq Presario XL119.
Following C program
#include <stdio.h>
#include <sys/time.h>
#include <unistd.h>
#include <time.h>
#define ABS(x) (x < 0 ? -x : x)
#define TIME_T struct timeval
#define TIME_DIFF_T long
#define GET_TIME(x) gettimeofday(&x, NULL)
#define TIME_DIFF(x1, x2) ((x2.tv_sec - x1.tv_sec)*1000000 + (x2.tv_usec - 
x1.tv_usec))
int main(int argc, char** argv)
{
   TIME_T t1, t2;
   TIME_DIFF_T d;

   GET_TIME(t2);
   while (1) {
     GET_TIME(t1);
     d = TIME_DIFF(t2, t1);
     if (d > 500000 || d < 0) {
             fprintf(stderr, "Leap found: %ld msec\n", d);
             return 0;
     }
     t2 = t1;
   }
return 1;

gives following result on box in question
root@******:# ./clo
Leap found: -1687 msec
and prints nothing on all other  my boxes.
This gives me bunch of troubles with occasional hang ups and I found nothing 
in kernel archives at 
http://www.uwsg.indiana.edu/hypermail/linux/kernel/index.html
just some notes about smth like this for SMP boxes with ntp. Is this issue 
known, and how can I fix it?

  Thanks.


_________________________________________________________________________
Get Your Private, Free E-mail from MSN Hotmail at http://www.hotmail.com.

Re: strange nonmonotonic behavior of gettimeoftheday

[Eli Carter]

John Being wrote:
> 
> I've got following problem with 2.2.17 (Redhat stock kernel)
> Linux ***** 2.2.17-14 #1 Mon Feb 5 14:57:25 EST 2001 i586 unknown
> on AMD K6,  VIA Technologies VT 82C586, Compaq Presario XL119.
> Following C program
> #include <stdio.h>
> #include <sys/time.h>
> #include <unistd.h>
> #include <time.h>
> #define ABS(x) (x < 0 ? -x : x)
> #define TIME_T struct timeval
> #define TIME_DIFF_T long
> #define GET_TIME(x) gettimeofday(&x, NULL)
> #define TIME_DIFF(x1, x2) ((x2.tv_sec - x1.tv_sec)*1000000 + (x2.tv_usec -
> x1.tv_usec))
> int main(int argc, char** argv)
> {
>    TIME_T t1, t2;
>    TIME_DIFF_T d;
> 
>    GET_TIME(t2);
>    while (1) {
>      GET_TIME(t1);
>      d = TIME_DIFF(t2, t1);
>      if (d > 500000 || d < 0) {
>              fprintf(stderr, "Leap found: %ld msec\n", d);
>              return 0;
>      }
>      t2 = t1;
>    }
> return 1;
> 
> gives following result on box in question
> root@******:# ./clo
> Leap found: -1687 msec
> and prints nothing on all other  my boxes.
> This gives me bunch of troubles with occasional hang ups and I found nothing
> in kernel archives at
> http://www.uwsg.indiana.edu/hypermail/linux/kernel/index.html
> just some notes about smth like this for SMP boxes with ntp. Is this issue
> known, and how can I fix it?

(That should read "usec" since you are printing microseconds and not
milliseconds.)

I've seen behaviour like that on an ARM processor because the time code
was not considering missed (or rather, delayed response to) timer
interrupts.  The time jump in that case was slightly less than 1 jiffie
(jiffie = 10ms).  It's likely rather hardware specific; see if you can
get someone with the same hardware to run your test code.

Eli
-----------------------.           Rule of Accuracy: When working toward
Eli Carter             |            the solution of a problem, it always 
eli.carter(at)inet.com `------------------ helps if you know the answer.

Re: strange nonmonotonic behavior of gettimeoftheday

[Manfred Spraul]

[-- Attachment #1: Type: text/plain, Size: 293 bytes --]

>
> on AMD K6, VIA Technologies VT 82C586, Compaq Presario XL119. 
> [snip]
> gives following result on box in question 
> root@******:# ./clo 
> Leap found: -1687 msec 
> and prints nothing on all other my boxes. 

Perhaps APM or SMI problems?
Could you run the attached program?

--
	Manfred

[-- Attachment #2: ms.c --]
[-- Type: text/plain, Size: 612 bytes --]

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

static unsigned long long get_tsc(void)
{
    	unsigned long v1;
	unsigned long v2;
	__asm__ __volatile__(
		"rdtsc\n\t"
		: "=a" (v1), "=d" (v2));
	return (((unsigned long long)v2)<<32)+v1;
}

int main(int argc, char** argv)
{
	unsigned long long t1;
	unsigned long long t2;

	printf("RDTSC tester\n");
	t1 = get_tsc();
	for(;;) {
		t2 = get_tsc();
		if(t1 > t2) {
			printf("tsc jumped backwards: from %lld to %lld.\n",
					t1, t2);
		}
#if 0
		printf("diff is %lld-%lld=%d.\n",t2,t1,t2-t1);
#endif
		t1 = t2;
	
	}
	return 1;
}

Re: strange nonmonotonic behavior of gettimeoftheday

[John Being]

OK, short status from the same box. It was up for about 2 weeks, but
yesterday due this problem it become unuseable, as X failed at startup with 
message about failed select(). Before reboot I made some tests
and found:
- it triggered by starting of X (without X no backjumps)
- it has something with interrupts, at least when I run program above
    (it is correct, at least it can determine problem) as
    while [ 1 ]; do ./clo; done
    and pressed key, it printed much less strings
- jumps are about 300-2000 microseconds
- there are some cases of such behaviour on Usenet (mainly diagnosed as 
screen  flickering due incorrect  screensaver startup)


After reboot problem goes away( nothing changed in config). Maybe it related 
to APM (as I did several suspends before this problem appears). Program 
testing RDTSC works OK now. If this problem appears again - I will run it.
  Thanks for help.


>From: Manfred Spraul <manfred@colorfullife.com>
>To: olonho@hotmail.com
>CC: linux-kernel@vger.kernel.org
>Subject: Re: strange nonmonotonic behavior of gettimeoftheday
>Date: Fri, 02 Mar 2001 18:06:05 +0100
>
> >
> > on AMD K6, VIA Technologies VT 82C586, Compaq Presario XL119.
> > [snip]
> > gives following result on box in question
> > root@******:# ./clo
> > Leap found: -1687 msec
> > and prints nothing on all other my boxes.
>
>Perhaps APM or SMI problems?
>Could you run the attached program?
>
>--
>	Manfred
>#include <stdio.h>
>#include <sys/time.h>
>#include <unistd.h>
>#include <time.h>
>
>static unsigned long long get_tsc(void)
>{
>     	unsigned long v1;
>	unsigned long v2;
>	__asm__ __volatile__(
>		"rdtsc\n\t"
>		: "=a" (v1), "=d" (v2));
>	return (((unsigned long long)v2)<<32)+v1;
>}
>
>int main(int argc, char** argv)
>{
>	unsigned long long t1;
>	unsigned long long t2;
>
>	printf("RDTSC tester\n");
>	t1 = get_tsc();
>	for(;;) {
>		t2 = get_tsc();
>		if(t1 > t2) {
>			printf("tsc jumped backwards: from %lld to %lld.\n",
>					t1, t2);
>		}
>#if 0
>		printf("diff is %lld-%lld=%d.\n",t2,t1,t2-t1);
>#endif
>		t1 = t2;
>
>	}
>	return 1;
>}
>

_________________________________________________________________________
Get Your Private, Free E-mail from MSN Hotmail at http://www.hotmail.com.