gettimeofday running backwards on 2.4.20

gettimeofday running backwards on 2.4.20

[Trammell Hudson]

[ Please cc hudson@osresearch.net on any replies.  Thank you! ]

A few months ago I noticed gettimeofday running backwards on
dual Pentium II and dual Pentium Pro systems with 2.4.18.  Based
on postings made to linux-kernel in June of 2002, I upgraded 
to 2.4.20 and the problem seemed to go away:

  http://groups.google.com/groups?threadm=3D16DE83.3060409@tiscalinet.it

Just recently my NAS benchmarks and MPI latency tests showed bizarre
results, so I pulled out my test program and am seeing the same
problems again.  It seems that roughly 50 in 1 million calls go
backwards, even with 2.4.20.

Occasionally it is 4295 seconds (very consistently that value),
but most of them are just a few microseconds backwards.  No error
code is returned from the system call either.  No NTP or rdate type
services are running.

My test program can be seen here:

	http://www.swcp.com/~hudson/gettimeofday.c

Interestingly, it only happens on the compute nodes with NFS root.
The service node has booted from a local SCSI disk and is serving roughly
140 compute nodes without any timing bugs.

service:~/tflop-linux: ssh node-181 uname -a \; cat /proc/cpuinfo      
Linux node-181 2.4.20 #73 SMP Mon Apr 21 14:06:49 MDT 2003 i686 unknown
processor       : 0
vendor_id       : GenuineIntel
cpu family      : 6
model           : 3
model name      : Pentium II (Klamath)
stepping        : 2
cpu MHz         : 333.356
cache size      : 512 KB
fdiv_bug        : no
hlt_bug         : no
f00f_bug        : no
coma_bug        : no
fpu             : yes
fpu_exception   : yes
cpuid level     : 2
wp              : yes
flags           : fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 mmx fxsr
bogomips        : 665.19

processor       : 1
vendor_id       : GenuineIntel
cpu family      : 6
model           : 3
model name      : Pentium II (Klamath)
stepping        : 2
cpu MHz         : 333.356
cache size      : 512 KB
fdiv_bug        : no
hlt_bug         : no
f00f_bug        : no
coma_bug        : no
fpu             : yes
fpu_exception   : yes
cpuid level     : 2
wp              : yes
flags           : fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 mmx fxsr
bogomips        : 665.19

Trammell
-- 
  -----|----- hudson@osresearch.net                   W 240-283-1700
*>=====[]L\   hudson@rotomotion.com                   M 505-463-1896
'     -'-`-   http://www.swcp.com/~hudson/                    KC5RNF

Re: gettimeofday running backwards on 2.4.20

[Daniel Phillips]

On Wed 23 Apr 03 01:23, Trammell Hudson wrote:
> [ Please cc hudson@osresearch.net on any replies.  Thank you! ]
>
> A few months ago I noticed gettimeofday running backwards on
> dual Pentium II and dual Pentium Pro systems with 2.4.18.  Based
> on postings made to linux-kernel in June of 2002, I upgraded
> to 2.4.20 and the problem seemed to go away:
>
>   http://groups.google.com/groups?threadm=3D16DE83.3060409@tiscalinet.it
>
> Just recently my NAS benchmarks and MPI latency tests showed bizarre
> results, so I pulled out my test program and am seeing the same
> problems again.  It seems that roughly 50 in 1 million calls go
> backwards, even with 2.4.20.

It's happening on my VAIO laptop as well, with a similar frequency.  The size 
of the typical regression dropped by roughly an order of magnitude between 
2.4.19 and 2.4.20, from several 10's of ms to a few ms.

There needs to be a final idiot check in there, as the last thing that 
happens in sys_gettimeofday, to catch and prevent such regressions in a 
brutally stupid way, in addition to the fancy algorithm that tries to prevent 
them, and has never fully succeeded in doing that.

A reasonable algorithm is: if time goes backwards by less than a second, it 
wasn't somebody changing the clock, so return the previous timeofday, 
otherwise, save the new value for the next test.

Applications like games (but not only games) can get pretty messed up by a 
timeofday that jumps backwards every couple of seconds.

Regards,

Daniel

Re: gettimeofday running backwards on 2.4.20

[Jamie Lokier]

Daniel Phillips wrote:
> Applications like games (but not only games) can get pretty messed up by a 
> timeofday that jumps backwards every couple of seconds.

It's a foolish game that doesn't implement your monotonicity algorithm
itself...

-- Jamie

Re: gettimeofday running backwards on 2.4.20

[Daniel Phillips]

On Thu 24 Apr 03 23:41, Jamie Lokier wrote:
> Daniel Phillips wrote:
> > Applications like games (but not only games) can get pretty messed up by
> > a timeofday that jumps backwards every couple of seconds.
>
> It's a foolish game that doesn't implement your monotonicity algorithm
> itself...

Maybe so, but on the other hand, game authors could, with some justification, 
accuse kernel developers of being the foolish ones.

There is already code in there that is supposed to fix up the timer: it 
doesn't work very well.

I wonder if SUS or whatnot has anything to say about gettimeofday being 
monotonic, so long as the user does not change the time.

Regards,

Daniel

Re: gettimeofday running backwards on 2.4.20

[john stultz]

>  Just recently my NAS benchmarks and MPI latency tests showed bizarre
>  results, so I pulled out my test program and am seeing the same
>  problems again.  It seems that roughly 50 in 1 million calls go
>  backwards, even with 2.4.20.
[snip]
>  Interestingly, it only happens on the compute nodes with NFS root.
>  The service node has booted from a local SCSI disk and is serving roughly
>  140 compute nodes without any timing bugs.

2.4 still has problems with xtime_lock writer starvation, as well as
being unable to handle lost ticks. Do you see this problem if you run
UP?

Give this patch (against 2.4.21-rc1) a whirl to see if you're getting
caught by xtime_lock starvation. 

thanks
-john


diff -Nru a/arch/i386/kernel/time.c b/arch/i386/kernel/time.c
--- a/arch/i386/kernel/time.c	Tue May  6 13:25:40 2003
+++ b/arch/i386/kernel/time.c	Tue May  6 13:25:40 2003
@@ -79,7 +79,7 @@
  */
 unsigned long fast_gettimeoffset_quotient;
 
-extern rwlock_t xtime_lock;
+extern spinlock_t xtime_lock;
 extern unsigned long wall_jiffies;
 
 spinlock_t rtc_lock = SPIN_LOCK_UNLOCKED;
@@ -444,7 +444,7 @@
 	unsigned long flags;
 	unsigned long usec, sec;
 
-	read_lock_irqsave(&xtime_lock, flags);
+	spin_lock_irqsave(&xtime_lock, flags);
 	usec = do_gettimeoffset();
 	{
 		unsigned long lost = jiffies - wall_jiffies;
@@ -453,7 +453,7 @@
 	}
 	sec = xtime.tv_sec;
 	usec += xtime.tv_usec;
-	read_unlock_irqrestore(&xtime_lock, flags);
+	spin_unlock_irqrestore(&xtime_lock, flags);
 
 	while (usec >= 1000000) {
 		usec -= 1000000;
@@ -466,7 +466,7 @@
 
 void do_settimeofday(struct timeval *tv)
 {
-	write_lock_irq(&xtime_lock);
+	spin_lock_irq(&xtime_lock);
 	/*
 	 * This is revolting. We need to set "xtime" correctly. However, the
 	 * value in this location is the value at the most recent update of
@@ -486,7 +486,7 @@
 	time_status |= STA_UNSYNC;
 	time_maxerror = NTP_PHASE_LIMIT;
 	time_esterror = NTP_PHASE_LIMIT;
-	write_unlock_irq(&xtime_lock);
+	spin_unlock_irq(&xtime_lock);
 }
 
 /*
@@ -652,7 +652,7 @@
 	 * the irq version of write_lock because as just said we have irq
 	 * locally disabled. -arca
 	 */
-	write_lock(&xtime_lock);
+	spin_lock(&xtime_lock);
 
 	if(use_cyclone)
 		mark_timeoffset_cyclone();
@@ -708,7 +708,7 @@
 
 	do_timer_interrupt(irq, NULL, regs);
 
-	write_unlock(&xtime_lock);
+	spin_unlock(&xtime_lock);
 
 }
 
diff -Nru a/kernel/time.c b/kernel/time.c
--- a/kernel/time.c	Tue May  6 13:25:40 2003
+++ b/kernel/time.c	Tue May  6 13:25:40 2003
@@ -38,7 +38,7 @@
 
 /* The xtime_lock is not only serializing the xtime read/writes but it's also
    serializing all accesses to the global NTP variables now. */
-extern rwlock_t xtime_lock;
+extern spinlock_t xtime_lock;
 
 #if !defined(__alpha__) && !defined(__ia64__)
 
@@ -79,7 +79,7 @@
 		return -EPERM;
 	if (get_user(value, tptr))
 		return -EFAULT;
-	write_lock_irq(&xtime_lock);
+	spin_lock_irq(&xtime_lock);
 	vxtime_lock();
 	xtime.tv_sec = value;
 	xtime.tv_usec = 0;
@@ -88,7 +88,7 @@
 	time_status |= STA_UNSYNC;
 	time_maxerror = NTP_PHASE_LIMIT;
 	time_esterror = NTP_PHASE_LIMIT;
-	write_unlock_irq(&xtime_lock);
+	spin_unlock_irq(&xtime_lock);
 	return 0;
 }
 
@@ -127,11 +127,11 @@
  */
 inline static void warp_clock(void)
 {
-	write_lock_irq(&xtime_lock);
+	spin_lock_irq(&xtime_lock);
 	vxtime_lock();
 	xtime.tv_sec += sys_tz.tz_minuteswest * 60;
 	vxtime_unlock();
-	write_unlock_irq(&xtime_lock);
+	spin_unlock_irq(&xtime_lock);
 }
 
 /*
@@ -235,7 +235,7 @@
 		if (txc->tick < 900000/HZ || txc->tick > 1100000/HZ)
 			return -EINVAL;
 
-	write_lock_irq(&xtime_lock);
+	spin_lock_irq(&xtime_lock);
 	result = time_state;	/* mostly `TIME_OK' */
 
 	/* Save for later - semantics of adjtime is to return old value */
@@ -390,7 +390,7 @@
 	txc->calcnt	   = pps_calcnt;
 	txc->errcnt	   = pps_errcnt;
 	txc->stbcnt	   = pps_stbcnt;
-	write_unlock_irq(&xtime_lock);
+	spin_unlock_irq(&xtime_lock);
 	do_gettimeofday(&txc->time);
 	return(result);
 }
diff -Nru a/kernel/timer.c b/kernel/timer.c
--- a/kernel/timer.c	Tue May  6 13:25:40 2003
+++ b/kernel/timer.c	Tue May  6 13:25:40 2003
@@ -666,7 +666,7 @@
 /*
  * This spinlock protect us from races in SMP while playing with xtime. -arca
  */
-rwlock_t xtime_lock = RW_LOCK_UNLOCKED;
+spinlock_t xtime_lock = SPIN_LOCK_UNLOCKED;
 
 static inline void update_times(void)
 {
@@ -677,7 +677,7 @@
 	 * just know that the irqs are locally enabled and so we don't
 	 * need to save/restore the flags of the local CPU here. -arca
 	 */
-	write_lock_irq(&xtime_lock);
+	spin_lock_irq(&xtime_lock);
 	vxtime_lock();
 
 	ticks = jiffies - wall_jiffies;
@@ -686,7 +686,7 @@
 		update_wall_time(ticks);
 	}
 	vxtime_unlock();
-	write_unlock_irq(&xtime_lock);
+	spin_unlock_irq(&xtime_lock);
 	calc_load(ticks);
 }