fsys_gettimeofday leaps days if it runs with nojitter

RFC PATCH Applied Hidetoshi Seto 4 participants 9 messages Jul 5, 2007 – Jul 13, 2007

lore

Share & tools

lore

Hidetoshi Seto

author

2007-07-05 07:50 UTC #0 lore raw

RFC PATCH 1/1 fsys_gettimeofday leaps days if it runs with nojitter

Hi all,

I have run a test of gettimeofday() with "nojitter" option to make sure whether time fluctuating is really there or not.

Quoted 9 lines

$ dmesg | grep ITC
Jitter checking for ITC timers disabled
CPU 0: base freq 0.000MHz, ITC ratio/2, ITC freq00.000MHz
CPU 1: synchronized ITC with CPU 0 (last diff 0 cycles, maxerr 568 cycles)
CPU 1: base freq 0.000MHz, ITC ratio/2, ITC freq00.000MHz
CPU 2: synchronized ITC with CPU 0 (last diff 5 cycles, maxerr 2087 cycles)
CPU 2: base freq 0.000MHz, ITC ratio/2, ITC freq00.000MHz
CPU 3: synchronized ITC with CPU 0 (last diff 0 cycles, maxerr 2098 cycles)
CPU 3: base freq 0.000MHz, ITC ratio/2, ITC freq00.000MHz

CPUs on this server are poorly synchronized. It seems that someone located between FSBs is lazy.

There were no problem until number of running threads are less than 3.

Quoted 9 lines

$ ./a.out
Oops, time goes backword!
 old: 1181506369.260876
 new: 1181224894.285294
diff:     281474.975582
   3: 1181224894.284165
   2: 1181224894.284165
   1: 1181506369.260876
   0: 1181224894.285294

Wow.
My test said "backward" since it got smaller value than previous one. But in fact it didn't go to past but just returned from future. 280000sec is about 3days...

To investigate this phenomenon, I made up a debug patch:

<PATCH>

Quoted 70 lines

Index: linux-2.6.21/arch/ia64/kernel/fsys.S =================================> --- linux-2.6.21.orig/arch/ia64/kernel/fsys.S +++ linux-2.6.21/arch/ia64/kernel/fsys.S

(quoted diff) +6 -0

@@ -244,6 +244,12 @@
        cmp.ne p13,p0 = r2,r0   // need jitter compensation?
        extr r21 = r21,16,8     // shift factor
        ;;
+       // DEBUG
+       //  if nojitter then r3, r30, r23, and r25 are free
+       //   p8 = 1
+       //   p9 = 0 & p10 = 0 : r30
+       //   p13 = 0          : r23, r25, r3
+       // DEBUG
 .time_redo:
        .pred.rel.mutex p8,p9,p10
        ld4.acq r28 = [r29]     // xtime_lock.sequence. Must come first for lock

ing purposes

(quoted diff) +21 -3

@@ -253,6 +259,10 @@
 (p10)  ld4 r2 = [r30]          // readw(ti->address)
 (p13)  add r23 = IA64_TIME_INTERPOLATOR_LAST_CYCLE_OFFSET,r20
        ;;                      // could be removed by moving the last add upward
+       // DEBUG
+       //  get itc again
+       mov r3 = ar.itc
+       // DEBUG
        ld8 r26 = [r22]         // time_interpolator->last_counter
 (p13)  ld8 r25 = [r23]         // time interpolator->last_cycle
        add r24 = IA64_TIME_INTERPOLATOR_OFFSET_OFFSET,r20

@@ -273,6 +283,10 @@
        ;;
        and r10 = r10,r14       // Apply mask
        ;;
+       // DEBUG
+       //  now r14 is free. get itc again
+       mov r14 = ar.itc
+       // DEBUG
        setf.sig f8 = r10
        nop.i 123
        ;;

@@ -283,20 +297,37 @@
        ;;
 (p15)  ld8 r17 = [r19],-IA64_TIMESPEC_TV_NSEC_OFFSET
 (p7)   cmp.ne p7,p0 = r25,r3   // if cmpxchg not successful redo
+// DEBUG
+// to keep r2 (=current_clock), use r25 instead
        // simulate tbit.nz.or p7,p0 = r28,0
        and r28 = ~1,r28        // Make sequence even to force retry if odd
-       getf.sig r2 = f8
+//     getf.sig r2 = f8
+       getf.sig r25 = f8
        mf
        add r8 = r8,r18         // Add time interpolator offset
        ;;
        ld4 r10 = [r29]         // xtime_lock.sequence
 (p15)  add r8 = r8, r17        // Add monotonic.nsecs to nsecs
-       shr.u r2 = r2,r21
+//     shr.u r2 = r2,r21
+       shr.u r25 = r25,r21
        ;;              // overloaded 3 bundles!
        // End critical section.
-       add r8 = r8,r2          // Add xtime.nsecs
+//     add r8 = r8,r2          // Add xtime.nsecs
+       add r8 = r8,r25         // Add xtime.nsecs
        cmp4.ne.or p7,p0 = r28,r10
 (p7)   br.cond.dpnt.few .time_redo     // sequence number changed ?
+// DEBUG
+       // DEBUG
+       //  bug if r8 is too large
+       movl r30 = 1000000000000        // 100sec
+       ;;

Review line 333

Quoted 10 lines

(quoted diff) +7 -0

+       cmp.ge p6,p0 = r8,r30
+       ;;
+(p6)   mov r30 = ar.itc        // get itc again if NG
+       ;;
+(p6)   ld8 r3 = [r0]           // BUG!
+       ;;
+       // DEBUG
        // Now r8=tv->tv_nsec and r9=tv->tv_sec
        mov r10 = r0
        movl r2 = 1000000000

</PATCH>

and got a stack trace from applied kernel:

<TRACE>

Quoted 26 lines

a.out[5126]: NaT consumption 17179869216 [1]
Modules linked in: sunrpc binfmt_misc dm_mirror dm_mod thermal processor fan con
tainer button sr_mod sg e100 mii usb_storage ehci_hcd ohci_hcd
Pid: 5126, CPU 3, comm: a.out
psr : 00001010085a6010 ifs : 8000000000000008 ip : [<a00000010000f830>] Not
tainted
ip is at fsys_gettimeofday+0x1f0/0x320
unat: 0000000000000000 pfs : c000000000000008 rsc : 000000000000000f
rnat: 0000000000000000 bsps: 600007ffffe24048 pr : 0000000000564141
ldrs: 0000000000800000 ccv : 0000000000000000 fpsr: 0009804c8a70033f csd : 0000000000000000 ssd : 0000000000000000
b0 : 4000000000000ed0 b6 : 2000000000167520 b7 : a00000010000f640 f6 : 000000000000000000000 f7 : 1003e000000000000aaaa f8 : 1003efffffffffa4e05b2 f9 : 000000000000000000000 f10 : 000000000000000000000 f11 : 000000000000000000000 r1 : 2000000000260238 r2 : 0000001672312e22 r3 : 0000001672312e28 r8 : 000100000bebbe9a r9 : 00000000468cd7b3 r10 : 0000000000007d5a r11 : c00000000000038f r12 : 60000fffffe1f6e0 r13 : 200000000004f270 r14 : 0000001672314111 r15 : 000000000000043f r16 : e00000011b1f8000 r17 : 000000000000003f r18 : 000000000000024c r19 : 0000000000000118 r20 : a0000001009413f8 r21 : 0000000000000010 r22 : a000000100941418 r23 : 60000fffffe1f708 r24 : a000000100941410 r25 : 0000fffffffffa4e r26 : 00000016723136ad r27 : a000000100ae5210 r28 : 0000000000007d5a r29 : a0000001008f9680 r30 : 000000167231430d r31 : 60000fffffe1f710

Quoted 15 lines

Call Trace:
 [<a0000001000139a0>] show_stack+0x40/0xa0
                                spà0000011b1ffa20 bspà0000011b1f8d38
 [<a000000100014600>] show_regs+0x840/0x880
                                spà0000011b1ffbf0 bspà0000011b1f8ce0
 [<a000000100036940>] die+0x1c0/0x2c0
                                spà0000011b1ffbf0 bspà0000011b1f8c98
 [<a000000100036a90>] die_if_kernel+0x50/0x80
                                spà0000011b1ffc10 bspà0000011b1f8c68
 [<a000000100037ca0>] ia64_fault+0x11e0/0x1300
                                spà0000011b1ffc10 bspà0000011b1f8c10
 [<a00000010000bdc0>] ia64_leave_kernel+0x0/0x280
                                spà0000011b1ffe30 bspà0000011b1f8c10
 [<a00000010000f830>] fsys_gettimeofday+0x1f0/0x320
                                spà0000011b200000 bspà0000011b1f8bc8

</TRACE>

Let's think.

r2 : 0000001672312e22 is current_clock, fetched from ar.itc at first. r26 : 00000016723136ad is last_counter, stored by CPU0 at last tick.

It is clear that leaping time is caused by getting larger last_counter than current_clock.

r8 : 000100000bebbe9a is calculated offset.

Negative offset was treated as unsigned.

r3 : 0000001672312e28 is clock value just after fetching counters r14 : 0000001672314111 is clock before xmpy.l
r30 : 000000167231430d is clock at exit on bug

Clocks between r3 to r14 are about 4800. Who was there? Interrupt? The value of last_counter is a clock between r3 to r14.
So it can be assumed that there were timer interrupts.
A timer interrupt on CPU0 updates last_counter while it takes xtime_lock.

r28 : 0000000000007d5a is xtime_lock.sequence at entrance (dropped bit0) r10 : 0000000000007d5a is xtime_lock.sequence at exit

However this couple of xtime_lock.sequence value claims there were no writer took xtime_lock during this operation.

...What is wrong?

I suspected the value of r28.
So I just relocate "consuming" of r28 to early stage.

<PATCH>

Quoted 14 lines

Index: linux-2.6.21/arch/ia64/kernel/fsys.S =================================> --- linux-2.6.21.orig/arch/ia64/kernel/fsys.S +++ linux-2.6.21/arch/ia64/kernel/fsys.S

(quoted diff) +3 -0

@@ -247,6 +247,9 @@
 .time_redo:
 	.pred.rel.mutex p8,p9,p10
 	ld4.acq r28 = [r29]	// xtime_lock.sequence. Must come first for locking purposes
+	;;
+	and r28 = ~1,r28	// Make sequence even to force retry if odd
+	;;
 (p8)	mov r2 = ar.itc		// CPU_TIMER. 36 clocks latency!!!
 	add r22 = IA64_TIME_INTERPOLATOR_LAST_COUNTER_OFFSET,r20
 (p9)	ld8 r2 = [r30]		// readq(ti->address). Could also have latency issues..

Review line 292

Quoted 7 lines

(quoted diff) +0 -1

@@ -284,7 +287,6 @@
 (p15)	ld8 r17 = [r19],-IA64_TIMESPEC_TV_NSEC_OFFSET
 (p7)	cmp.ne p7,p0 = r25,r3	// if cmpxchg not successful redo
 	// simulate tbit.nz.or p7,p0 = r28,0
-	and r28 = ~1,r28	// Make sequence even to force retry if odd
 	getf.sig r2 = f8
 	mf
 	add r8 = r8,r18		// Add time interpolator offset

</PATCH>

What a surprise! This patch solves the problem!

Therefore now my concern is what does "acq" of ld4.acq provides. According to ASDM, it says "Acquire data accesses guarantee that they are made visible prior to all subsequent data accesses."

I'm not sure but since the problem is solved by above patch, it seems that value loaded to r28 on CPU3 was not xtime_lock.sequence before timer interrupt on CPU0 but one after the interrupt.

Is this software/coding bug?
Or is this a hardware/firmware's bug which don't follow requirement of "Acquire data access"?

If this is coding bug, there would be another solution that adding comparison of last_counter and current_clock. But clearly relocation is cheaper way.

Thanks,
H.Seto

Signed-off-by Hidetoshi Seto <[email protected]>

-----

 arch/ia64/kernel/fsys.S |    4 +++-
 1 file changed, 3 insertions(+), 1 deletion(-)

Index: linux-2.6.21/arch/ia64/kernel/fsys.S =================================--- linux-2.6.21.orig/arch/ia64/kernel/fsys.S +++ linux-2.6.21/arch/ia64/kernel/fsys.S
@@ -247,6 +247,9 @@
.time_redo:
.pred.rel.mutex p8,p9,p10
ld4.acq r28 = [r29] // xtime_lock.sequence. Must come first for locking purposes
+ ;;
+ and r28 = ~1,r28 // Make sequence even to force retry if odd
+ ;;
(p8) mov r2 = ar.itc // CPU_TIMER. 36 clocks latency!!!
add r22 = IA64_TIME_INTERPOLATOR_LAST_COUNTER_OFFSET,r20
(p9) ld8 r2 = [r30] // readq(ti->address). Could also have latency issues..
@@ -284,7 +287,6 @@
(p15) ld8 r17 = [r19],-IA64_TIMESPEC_TV_NSEC_OFFSET
(p7) cmp.ne p7,p0 = r25,r3 // if cmpxchg not successful redo
// simulate tbit.nz.or p7,p0 = r28,0
- and r28 = ~1,r28 // Make sequence even to force retry if odd
getf.sig r2 = f8
mf
add r8 = r8,r18 // Add time interpolator offset

Andreas Schwab

2007-07-05 08:48 UTC #1 lore raw

Quoted 27 lines · Hidetoshi Seto

I suspected the value of r28.
So I just relocate "consuming" of r28 to early stage.

<PATCH>

Quoted 14 lines

Index: linux-2.6.21/arch/ia64/kernel/fsys.S =================================>> --- linux-2.6.21.orig/arch/ia64/kernel/fsys.S +++ linux-2.6.21/arch/ia64/kernel/fsys.S

(quoted diff) +3 -0

@@ -247,6 +247,9 @@
 .time_redo:
 	.pred.rel.mutex p8,p9,p10
 	ld4.acq r28 = [r29]	// xtime_lock.sequence. Must come first for locking purposes
+	;;
+	and r28 = ~1,r28	// Make sequence even to force retry if odd
+	;;
 (p8)	mov r2 = ar.itc		// CPU_TIMER. 36 clocks latency!!!
 	add r22 = IA64_TIME_INTERPOLATOR_LAST_COUNTER_OFFSET,r20
 (p9)	ld8 r2 = [r30]		// readq(ti->address). Could also have latency issues..

Review line 292

Quoted 7 lines

(quoted diff) +0 -1

@@ -284,7 +287,6 @@
 (p15)	ld8 r17 = [r19],-IA64_TIMESPEC_TV_NSEC_OFFSET
 (p7)	cmp.ne p7,p0 = r25,r3	// if cmpxchg not successful redo
 	// simulate tbit.nz.or p7,p0 = r28,0
-	and r28 = ~1,r28	// Make sequence even to force retry if odd
 	getf.sig r2 = f8
 	mf
 	add r8 = r8,r18		// Add time interpolator offset

</PATCH>

Quoted 1 line

What a surprise! This patch solves the problem!

How can the register lose its contents? The only thing that can make a difference is the stop bit.

Andreas.

Signature · 4 lines

Andreas Schwab, SuSE Labs, [email protected]
SuSE Linux Products GmbH, Maxfeldstraße 5, 90409 Nürnberg, Germany
PGP key fingerprint = 58CA 54C7 6D53 942B 1756  01D3 44D5 214B 8276 4ED5
"And now for something completely different."

Hidetoshi Seto

author

2007-07-05 08:57 UTC #2 lore raw

In reply to Hidetoshi Seto

Quoted 25 lines · Andreas Schwab

Quoted 15 lines · Hidetoshi Seto

<PATCH>

Quoted 14 lines

Index: linux-2.6.21/arch/ia64/kernel/fsys.S =================================>>> --- linux-2.6.21.orig/arch/ia64/kernel/fsys.S +++ linux-2.6.21/arch/ia64/kernel/fsys.S

(quoted diff) +3 -0

@@ -247,6 +247,9 @@
 .time_redo:
 	.pred.rel.mutex p8,p9,p10
 	ld4.acq r28 = [r29]	// xtime_lock.sequence. Must come first for locking purposes
+	;;
+	and r28 = ~1,r28	// Make sequence even to force retry if odd
+	;;
 (p8)	mov r2 = ar.itc		// CPU_TIMER. 36 clocks latency!!!
 	add r22 = IA64_TIME_INTERPOLATOR_LAST_COUNTER_OFFSET,r20
 (p9)	ld8 r2 = [r30]		// readq(ti->address). Could also have latency issues..

@@ -284,7 +287,6 @@

Quoted 8 lines

Review line 292

Quoted 7 lines

(quoted diff) +0 -1

 (p15)	ld8 r17 = [r19],-IA64_TIMESPEC_TV_NSEC_OFFSET
 (p7)	cmp.ne p7,p0 = r25,r3	// if cmpxchg not successful redo
 	// simulate tbit.nz.or p7,p0 = r28,0
-	and r28 = ~1,r28	// Make sequence even to force retry if odd
 	getf.sig r2 = f8
 	mf
 	add r8 = r8,r18		// Add time interpolator offset

</PATCH>

Quoted 2 lines

How can the register lose its contents? The only thing that can make a difference is the stop bit.

I tried

Quoted 3 lines

Review

Quoted 3 lines

(quoted diff) +1 -0

 	ld4.acq r28 = [r29]	// xtime_lock.sequence. Must come first for locking purposes
+	;;
 (p8)	mov r2 = ar.itc		// CPU_TIMER. 36 clocks latency!!!

but nothing changes (leap continues).

Thanks,
H.Seto

Luck, Tony

2007-07-10 22:20 UTC #3 lore raw

In reply to Hidetoshi Seto

Quoted 3 lines

Review

Quoted 3 lines

(quoted diff) +1 -0

 	ld4.acq r28 = [r29]	// xtime_lock.sequence. Must come first for locking purposes
+	;;
 (p8)	mov r2 = ar.itc		// CPU_TIMER. 36 clocks latency!!!

The .acq only causes ordering w.r.t. data accesses. The read from ar.itc isn't a data access, so potentially it could still float before the ld4.acq. Consuming the value loaded into r28 presumably has to ensure that the load completes though.

I'm guessing here ... I haven't cross-checked with the architects.

Does moving the "and r28 = ~1,r28" up into this slot hurt latency for a single call to gettimeofday()? Presumably it will if xtime_lock.sequence is not in the cache.

-Tony

Hidetoshi Seto

author

2007-07-11 01:31 UTC #4 lore raw

In reply to Hidetoshi Seto

Quoted 8 lines · Tony

Quoted 3 lines
Quoted 3 lines
Review
Quoted 3 lines
(quoted diff) +1 -0
 	ld4.acq r28 = [r29]	// xtime_lock.sequence. Must come first for locking purposes
+	;;
 (p8)	mov r2 = ar.itc		// CPU_TIMER. 36 clocks latency!!!
The .acq only causes ordering w.r.t. data accesses. The read from ar.itc isn't a data access, so potentially it could still float before the ld4.acq. Consuming the value loaded into r28 presumably has to ensure that the load completes though.

Hmm, then will this problem not happen if timesource was not ar.itc? If source is mmio, the read from the address is a data access, isn't it?

Quoted 1 line

I'm guessing here ... I haven't cross-checked with the architects.

I'll be grad if we can get a comment from Intel's architects.

Quoted 5 lines

Does moving the "and r28 = ~1,r28" up into this slot hurt latency for a single call to gettimeofday()? Presumably it will if xtime_lock.sequence is not in the cache.
-Tony

It will, I guess.
Anyway, we should make sure that the load of xtime_lock.sequence have complete before reading ar.itc.

Thanks,
H.Seto

Luck, Tony

2007-07-12 22:33 UTC #5 lore raw

In reply to Hidetoshi Seto

Quoted 3 lines

Quoted 1 line
I'm guessing here ... I haven't cross-checked with the architects.
I'll be glad if we can get a comment from Intel's architects.

I talked this through with an architect, and I'm right. In the sequence:

	ld4.acq  rM = [rN]
	;;
	mov rP = ar.itc

there are no dependencies, so the read of ar.itc can occur "IMMEDIATELY after the load issues".

Consuming the result of the load in between will create a dependency ... so the timestamp will be taken as we want it, after the load.

So I can apply this patch (moving the "and r28 = ~1,r28").

What other time patches are you still pushing? The time interpolator changes that were predicted still look like they are pending somewhere (kernel/timer.c hasn't been changed).

-Tony

Hidetoshi Seto

author

2007-07-13 01:27 UTC #6 lore raw

In reply to Hidetoshi Seto

Quoted 10 lines · Tony

Quoted 2 lines
Quoted 1 line
I'm guessing here ... I haven't cross-checked with the architects.
I'll be glad if we can get a comment from Intel's architects.
I talked this through with an architect, and I'm right. In the sequence:
	ld4.acq  rM = [rN]
	;;
	mov rP = ar.itc

Quoted 8 lines

there are no dependencies, so the read of ar.itc can occur "IMMEDIATELY after the load issues".
Consuming the result of the load in between will create a dependency ... so the timestamp will be taken as we want it, after the load.
So I can apply this patch (moving the "and r28 = ~1,r28").

Thank you for checking it.

Quoted 6 lines

What other time patches are you still pushing? The time interpolator changes that were predicted still look like they are pending somewhere (kernel/timer.c hasn't been changed).
-Tony

I don't know the current status of Bob's patches... I hope you don't mind applying my small patches before Bob's.

Here are 2 pending patches I'm pushing :
- [PATCH] ia64: Scalability improvement of gettimeofday with jitter compensation
- [PATCH] fsys_gettimeofday leaps days if it runs with nojitter

I confirmed that these 2 can be applied to 2.6.22 (with some offset). Let me know if you need refreshed ones.

Thanks,
H.Seto

Bob Picco

2007-07-13 09:49 UTC #7 lore raw

In reply to Hidetoshi Seto

Hi,

Hidetoshi Seto wrote: [Thu Jul 12 2007, 09:27:30PM EDT]

Quoted 22 lines

Quoted 10 lines · Tony
Quoted 2 lines
Quoted 1 line
I'm guessing here ... I haven't cross-checked with the architects.
I'll be glad if we can get a comment from Intel's architects.
I talked this through with an architect, and I'm right. In the sequence:
	ld4.acq  rM = [rN]
	;;
	mov rP = ar.itc
Quoted 8 lines
there are no dependencies, so the read of ar.itc can occur "IMMEDIATELY after the load issues".
Consuming the result of the load in between will create a dependency ... so the timestamp will be taken as we want it, after the load.
So I can apply this patch (moving the "and r28 = ~1,r28").
Thank you for checking it.

Quoted 8 lines

Quoted 6 lines
What other time patches are you still pushing? The time interpolator changes that were predicted still look like they are pending somewhere (kernel/timer.c hasn't been changed).
-Tony
I don't know the current status of Bob's patches...

I was on vacation for two weeks and have spent this week catching up. I should have Pete's patches posted by Sunday.

bob

Quoted 12 lines

I hope you don't mind applying my small patches before Bob's.
Here are 2 pending patches I'm pushing :
- [PATCH] ia64: Scalability improvement of gettimeofday with jitter compensation
- [PATCH] fsys_gettimeofday leaps days if it runs with nojitter
I confirmed that these 2 can be applied to 2.6.22 (with some offset). Let me know if you need refreshed ones.
Thanks,
H.Seto

Luck, Tony

Applied

2007-07-13 23:25 UTC #8 lore raw

In reply to Hidetoshi Seto

Quoted 3 lines

Here are 2 pending patches I'm pushing :
- [PATCH] ia64: Scalability improvement of gettimeofday with jitter compensation

Bob says his (Pete's) patches will be ready soon (Sunday) so I'll wait for them to make sure this all fits together cleanly. This is a definite 2.6.23 candidate.

Quoted 1 line

- [PATCH] fsys_gettimeofday leaps days if it runs with nojitter

Applied.

-Tony