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

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

[Hidetoshi Seto]

Hi all,

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

> $ dmesg | grep ITC
> Jitter checking for ITC timers disabled
> CPU 0: base freq 0.000MHz, ITC ratio\x15/2, ITC freq\x1500.000MHz
> CPU 1: synchronized ITC with CPU 0 (last diff 0 cycles, maxerr 568 cycles)
> CPU 1: base freq 0.000MHz, ITC ratio\x15/2, ITC freq\x1500.000MHz
> CPU 2: synchronized ITC with CPU 0 (last diff 5 cycles, maxerr 2087 cycles)
> CPU 2: base freq 0.000MHz, ITC ratio\x15/2, ITC freq\x1500.000MHz
> CPU 3: synchronized ITC with CPU 0 (last diff 0 cycles, maxerr 2098 cycles)
> CPU 3: base freq 0.000MHz, ITC ratio\x15/2, ITC freq\x1500.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.

> $ ./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>
> 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
> @@ -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
> @@ -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
> +       ;;
> +       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>
> 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
> 
> 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>
> 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
</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 <seto.hidetoshi@jp.fujitsu.com>

-----
 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

Re: [RFC][PATCH] fsys_gettimeofday leaps days if it runs with nojitter

[Andreas Schwab]

Hidetoshi Seto <seto.hidetoshi@jp.fujitsu.com> writes:

> I suspected the value of r28.
> So I just relocate "consuming" of r28 to early stage.
>
> <PATCH>
>> 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
> </PATCH>
>
> 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.

-- 
Andreas Schwab, SuSE Labs, schwab@suse.de
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."

Re: [RFC][PATCH] fsys_gettimeofday leaps days if it runs with nojitter

[Hidetoshi Seto]

Andreas Schwab wrote:
> Hidetoshi Seto <seto.hidetoshi@jp.fujitsu.com> writes:
>> <PATCH>
>>> 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
>> </PATCH>
> 
> How can the register lose its contents?  The only thing that can make a
> difference is the stop bit.

I tried

 >>>  	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

RE: [RFC][PATCH] fsys_gettimeofday leaps days if it runs with nojitter

[Luck, Tony]

 >>>  	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

Re: [RFC][PATCH] fsys_gettimeofday leaps days if it runs with nojitter

[Hidetoshi Seto]

Luck, Tony wrote:
>  >>>  	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?

> 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.

> 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

RE: [RFC][PATCH] fsys_gettimeofday leaps days if it runs with nojitter

[Luck, Tony]

> > 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

Re: [RFC][PATCH] fsys_gettimeofday leaps days if it runs with nojitter

[Hidetoshi Seto]

Luck, Tony wrote:
>>> 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").

Thank you for checking it.

> 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

Re: [RFC][PATCH] fsys_gettimeofday leaps days if it runs with nojitter

[Bob Picco]

Hi,

Hidetoshi Seto wrote:	[Thu Jul 12 2007, 09:27:30PM EDT]
> Luck, Tony wrote:
> >>>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").
> 
> Thank you for checking it.
> 
> >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
> 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

RE: [RFC][PATCH] fsys_gettimeofday leaps days if it runs with nojitter

[Luck, Tony]

> 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.

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

Applied.

-Tony