Hi Thomas,
I switched my custom kernel timer to use the ktimers with the prio of -1
as you mentioned to me offline. I set up the timer to be monotonic and
have a requirement that the returned time is always greater or equal to
the last time returned from do_get_ktime_mono.
Now here's the results that I got between two calls of do_get_ktime_mono
358.069795728 secs then later 355.981483177. Should this ever happen?
I haven't look to see if this happens in vanilla -rt10 but I haven't
touched your ktimer code except for my logging and the patch with the
unlock_ktimer_base (since I was based off of -rt9)
FYI, the system is UP. And I compiled without CONFIG_KTIME_SCALAR.
Thanks
-- Steve
On Wed, 2005-10-19 at 10:59 -0400, Steven Rostedt wrote:
> Hi Thomas,
>
> I switched my custom kernel timer to use the ktimers with the prio of -1
> as you mentioned to me offline. I set up the timer to be monotonic and
> have a requirement that the returned time is always greater or equal to
> the last time returned from do_get_ktime_mono.
>
> Now here's the results that I got between two calls of do_get_ktime_mono
>
> 358.069795728 secs then later 355.981483177. Should this ever happen?
Definitely not. monotonic time must go forwards.
> I haven't look to see if this happens in vanilla -rt10 but I haven't
> touched your ktimer code except for my logging and the patch with the
> unlock_ktimer_base (since I was based off of -rt9)
The ktimer code itself calls the timeofday code, which provides the
monotonic clock. I have no idea what might go wrong.
Is this reproducible ?
tglx
* Steven Rostedt <[email protected]> wrote:
> Hi Thomas,
>
> I switched my custom kernel timer to use the ktimers with the prio of
> -1 as you mentioned to me offline. I set up the timer to be monotonic
> and have a requirement that the returned time is always greater or
> equal to the last time returned from do_get_ktime_mono.
>
> Now here's the results that I got between two calls of
> do_get_ktime_mono
>
> 358.069795728 secs then later 355.981483177. Should this ever happen?
should be monotone - the latest -rt kernels include a debugging check
for the monotonicity of do_get_ktime_mono().
Ingo
On Wed, 19 Oct 2005, Steven Rostedt wrote:
>
> Hi Thomas,
>
> I switched my custom kernel timer to use the ktimers with the prio of -1
> as you mentioned to me offline. I set up the timer to be monotonic and
> have a requirement that the returned time is always greater or equal to
> the last time returned from do_get_ktime_mono.
>
> Now here's the results that I got between two calls of do_get_ktime_mono
>
> 358.069795728 secs then later 355.981483177. Should this ever happen?
Are you running NTP ?
Daniel
-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1
Steven Rostedt wrote:
> 358.069795728 secs then later 355.981483177. Should this ever happen?
Pretty sure that "NO" is the correct answer :)
> FYI, the system is UP. And I compiled without CONFIG_KTIME_SCALAR.
What sort of CPU? Does it have frequency scaling?
Frank
- --
Frank Sorenson - KD7TZK
Systems Manager, Computer Science Department
Brigham Young University
[email protected]
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.2.7 (GNU/Linux)
Comment: Using GnuPG with Fedora - http://enigmail.mozdev.org
iD8DBQFDVnfeaI0dwg4A47wRAomrAKDN6y1AsA1P3jhTqBcNHmrSc18pVQCgu9Fh
AGO6q8+agAmlP9jIDXVxgOs=
=Nn7R
-----END PGP SIGNATURE-----
On Wed, 2005-10-19 at 17:10 +0200, Thomas Gleixner wrote:
> On Wed, 2005-10-19 at 10:59 -0400, Steven Rostedt wrote:
> > Hi Thomas,
> >
> > I switched my custom kernel timer to use the ktimers with the prio of -1
> > as you mentioned to me offline. I set up the timer to be monotonic and
> > have a requirement that the returned time is always greater or equal to
> > the last time returned from do_get_ktime_mono.
> >
> > Now here's the results that I got between two calls of do_get_ktime_mono
> >
> > 358.069795728 secs then later 355.981483177. Should this ever happen?
>
> Definitely not. monotonic time must go forwards.
Steven: What clocksource are you using? Could you send me your dmesg?
> > I haven't look to see if this happens in vanilla -rt10 but I haven't
> > touched your ktimer code except for my logging and the patch with the
> > unlock_ktimer_base (since I was based off of -rt9)
>
> The ktimer code itself calls the timeofday code, which provides the
> monotonic clock. I have no idea what might go wrong.
>
> Is this reproducible ?
Last night I just caught a bug I accidentally introduced with the fixed
interval math (oh, if only optimizations didn't dirty code so!), where
time inconsistencies were possible when clocksources were changed. I'm
not sure if that's the issue being seen above, but I'll wrap things up
and send out a B8 release today if I can.
thanks
-john
On Wed, 19 Oct 2005, Thomas Gleixner wrote:
> On Wed, 2005-10-19 at 10:59 -0400, Steven Rostedt wrote:
>
> The ktimer code itself calls the timeofday code, which provides the
> monotonic clock. I have no idea what might go wrong.
>
> Is this reproducible ?
>
Right now I'm compiling for the -rt kernel without my updates, to see if
it is reproducible there. It is reproducible with my customizations. One
thing that my kernel does is take the CPU from all other processes
(including tasklet threads) for long periods of time. I'll see if I can
trigger this with the hackbench of highest priority on -rt, which does the
same thing.
-- Steve
On Wed, 19 Oct 2005, Ingo Molnar wrote:
>
> should be monotone - the latest -rt kernels include a debugging check
> for the monotonicity of do_get_ktime_mono().
>
Hi Ingo,
Hmm, I think this will help in that debugging check :-)
-- Steve
Index: linux-2.6.14-rc4-rt12/kernel/ktimers.c
===================================================================
--- linux-2.6.14-rc4-rt12.orig/kernel/ktimers.c 2005-10-20 02:15:17.000000000 -0400
+++ linux-2.6.14-rc4-rt12/kernel/ktimers.c 2005-10-20 02:33:38.000000000 -0400
@@ -971,7 +971,7 @@
}
return prev;
}
-
+ per_cpu(prev_mono_time, cpu) = now;
return now;
}
On Wed, 19 Oct 2005, Daniel Walker wrote:
> On Wed, 19 Oct 2005, Steven Rostedt wrote:
>
> >
> > Hi Thomas,
> >
> > I switched my custom kernel timer to use the ktimers with the prio of -1
> > as you mentioned to me offline. I set up the timer to be monotonic and
> > have a requirement that the returned time is always greater or equal to
> > the last time returned from do_get_ktime_mono.
> >
> > Now here's the results that I got between two calls of do_get_ktime_mono
> >
> > 358.069795728 secs then later 355.981483177. Should this ever happen?
>
> Are you running NTP ?
>
Yes, but that shouldn't make a difference. NTP can slow down or speed up
the clock, but it should never make it go backwards. Especially for a
monotonic clock (as the name suggests).
-- Steve
On Wed, 19 Oct 2005, Frank Sorenson wrote:
> -----BEGIN PGP SIGNED MESSAGE-----
> Hash: SHA1
>
> Steven Rostedt wrote:
> > 358.069795728 secs then later 355.981483177. Should this ever happen?
>
> Pretty sure that "NO" is the correct answer :)
By definition, I figured as much :-)
>
> > FYI, the system is UP. And I compiled without CONFIG_KTIME_SCALAR.
>
> What sort of CPU? Does it have frequency scaling?
>
Well, it's a normal desktop PC (not a laptop) but here's cpuinfo:
snoopy:~/rt_linux# cat /proc/cpuinfo
processor : 0
vendor_id : GenuineIntel
cpu family : 15
model : 2
model name : Intel(R) Pentium(R) 4 CPU 2.00GHz
stepping : 7
cpu MHz : 1994.256
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 clflush dts acpi mmx fxsr sse sse2 ss ht tm pbe cid
bogomips : 3990.73
-- Steve
On Wed, 19 Oct 2005, john stultz wrote:
> > >
> > > Now here's the results that I got between two calls of do_get_ktime_mono
> > >
> > > 358.069795728 secs then later 355.981483177. Should this ever happen?
> >
> > Definitely not. monotonic time must go forwards.
>
> Steven: What clocksource are you using? Could you send me your dmesg?
I have both a PIT/TSC and apic. So, as Thomas told me, the ktimer code
should figure out what to use. So that's pretty much all I can say on
clocksource ;)
As for the dmesg, there isn't really one. I have my own logging code that
flagged this, as well as a check that would BUG on the system when this
happened. So my messages may not mean much to you. I'm currently
compiling Ingo's -rt12 (with a fix to his checking) to see if I can
trigger it there too. My custom kernel doesn't touch the ktimer/timeofday
code so I'm assuming that I can. But until I can trigger this on a kernel
that I didn't taint, I'll stop bothering you :-)
>
>
> > > I haven't look to see if this happens in vanilla -rt10 but I haven't
> > > touched your ktimer code except for my logging and the patch with the
> > > unlock_ktimer_base (since I was based off of -rt9)
> >
> > The ktimer code itself calls the timeofday code, which provides the
> > monotonic clock. I have no idea what might go wrong.
> >
> > Is this reproducible ?
>
> Last night I just caught a bug I accidentally introduced with the fixed
> interval math (oh, if only optimizations didn't dirty code so!), where
> time inconsistencies were possible when clocksources were changed. I'm
> not sure if that's the issue being seen above, but I'll wrap things up
> and send out a B8 release today if I can.
>
Hmm, I believe that the ktimers use the apic (when available) and let the
jiffies still be calculated via PIT/TSC.
Thomas, is the above correct?
Would that have triggered your bug?
Thanks,
-- Steve
* Steven Rostedt <[email protected]> wrote:
> > should be monotone - the latest -rt kernels include a debugging check
> > for the monotonicity of do_get_ktime_mono().
>
> Hi Ingo,
>
> Hmm, I think this will help in that debugging check :-)
> + per_cpu(prev_mono_time, cpu) = now;
> return now;
> }
*blush*, applied.
I was already wondering a bit why that check never triggered for anyone.
It is easy to have a non-monotonic clock (there's lots of crappy hw and
the gettimeofday code has to work hard) and the effects of time warps
are subtle, if noticeable at all, so i expected some detections.
i have released -rt13 with another change: the other timer warning is
only printed once. (a steady stream of messages is not helpful)
Ingo
* Steven Rostedt <[email protected]> wrote:
> > Last night I just caught a bug I accidentally introduced with the fixed
> > interval math (oh, if only optimizations didn't dirty code so!), where
> > time inconsistencies were possible when clocksources were changed. I'm
> > not sure if that's the issue being seen above, but I'll wrap things up
> > and send out a B8 release today if I can.
>
> Hmm, I believe that the ktimers use the apic (when available) and let
> the jiffies still be calculated via PIT/TSC.
>
> Thomas, is the above correct?
>
> Would that have triggered your bug?
if the bug is only possible when timesources are changed on the fly,
then i think it shouldnt happen. We pick our sources at bootup time and
stick with them.
in the -rt tree we also have clockevents and HRT support, so the clocks
used should depend on whether you have the APIC enabled in the .config,
and whether the BIOS has it enabled by default. If the BIOS has the APIC
disabled then you can force the kernel to enable it by adding "lapic" to
the boot-line.
without the APIC active, the equation is simple: we use the PIT for both
jiffies and HRT. We use the TSC for gettimeofday. No interaction between
the two.
if the APIC is active, then we have both the local APIC timer interrupt
for and the PIT for HRT timing. The clockevents framework sees both
hardware clocks and automatically decides which one to use, based on
their ranking. A typical PIT reprogramming PIO sequence takes 20-30
usecs, while a typical APIC timer reprogramming takes ~5 nanoseconds on
my box, so the choice is rather easy ;-) The jiffies interrupt is still
off the PIT. gettimeofday is off the TSC counter.
i could imagine the following hardware effects to cause time warps:
- the TSC is in fact the 'read counter' method of the local APIC timer
hardware. So there can be interactions in theory: programming the APIC
timer could impact the TSC and vice versa. There have been CPU
erratums in this area in the past.
- powersaving can impact the TSC - and can thus impact the APIC timer
too. Errata-land as well.
- the TSC itself could have short, temporary warps. I had a box that
showed such effects.
besides hardware bugs, another, albeit very small possibility is that
somewhere in the thousands of lines of shiny-new generic-time-of-day,
ktimers, clockevents and high-res-timers code, there is a software bug,
which is causing time warps ;-)
Ingo
On Thu, 20 Oct 2005, Ingo Molnar wrote:
>
> if the bug is only possible when timesources are changed on the fly,
> then i think it shouldnt happen. We pick our sources at bootup time and
> stick with them.
>
> in the -rt tree we also have clockevents and HRT support, so the clocks
> used should depend on whether you have the APIC enabled in the .config,
> and whether the BIOS has it enabled by default. If the BIOS has the APIC
> disabled then you can force the kernel to enable it by adding "lapic" to
> the boot-line.
On this test machine, I had to add the lapic command line, but that was
there when I first had to get NMI working on this machine back in the V0.7
days :-)
>
> without the APIC active, the equation is simple: we use the PIT for both
> jiffies and HRT. We use the TSC for gettimeofday. No interaction between
> the two.
>
> if the APIC is active, then we have both the local APIC timer interrupt
> for and the PIT for HRT timing. The clockevents framework sees both
> hardware clocks and automatically decides which one to use, based on
> their ranking. A typical PIT reprogramming PIO sequence takes 20-30
> usecs, while a typical APIC timer reprogramming takes ~5 nanoseconds on
> my box, so the choice is rather easy ;-) The jiffies interrupt is still
> off the PIT. gettimeofday is off the TSC counter.
>
> i could imagine the following hardware effects to cause time warps:
>
> - the TSC is in fact the 'read counter' method of the local APIC timer
> hardware. So there can be interactions in theory: programming the APIC
> timer could impact the TSC and vice versa. There have been CPU
> erratums in this area in the past.
Could this cause a 2 second drop backwards?
>
> - powersaving can impact the TSC - and can thus impact the APIC timer
> too. Errata-land as well.
Well, this machine is a normal PC not a laptop, and anyway, this backwards
clock happened during a stress test with pretty much 100% CPU usage, so I
think we can rule out power saving.
>
> - the TSC itself could have short, temporary warps. I had a box that
> showed such effects.
Can this be a 2 second warp?
>
> besides hardware bugs, another, albeit very small possibility is that
> somewhere in the thousands of lines of shiny-new generic-time-of-day,
> ktimers, clockevents and high-res-timers code, there is a software bug,
> which is causing time warps ;-)
>
My older code first used jiffies as a timer, then I switched to TSC and
then to APIC timer, and then finally ktimer. ktimer was the first to show
a backwards get_time.
-- Steve
* Steven Rostedt <[email protected]> wrote:
> > i could imagine the following hardware effects to cause time warps:
> >
> > - the TSC is in fact the 'read counter' method of the local APIC timer
> > hardware. So there can be interactions in theory: programming the APIC
> > timer could impact the TSC and vice versa. There have been CPU
> > erratums in this area in the past.
>
> Could this cause a 2 second drop backwards?
i dont think so.
> > - the TSC itself could have short, temporary warps. I had a box that
> > showed such effects.
>
> Can this be a 2 second warp?
the ones i saw were in the 1000-cycles range.
> My older code first used jiffies as a timer, then I switched to TSC
> and then to APIC timer, and then finally ktimer. ktimer was the first
> to show a backwards get_time.
another thing: the monotonicity check is only in get_ktime_mono(), while
there are other places where a monotonic clock is used, which this check
might miss.
Ingo
Slightly different issue.
I just ran hackbench as a high priority process (higher than the tasklets)
and it once again has sys_gettimeofday going backwards. It runs for 30
seconds, hogging the CPU from all other processes, and the gettimeofday
once again overflows. This time it's more complex than then last time
because of the changes (I guess John) made.
Following the code into sys_gettimeofday, I end up at __get_nsec_offset.
static inline nsec_t __get_nsec_offset(void)
{
cycle_t cycle_now, cycle_delta;
nsec_t ns_offset;
/* read clocksource */
cycle_now = read_clocksource(clock);
/* calculate the delta since the last timeofday_periodic_hook */
cycle_delta = (cycle_now - cycle_last) & clock->mask;
/* convert to nanoseconds */
ns_offset = cyc2ns(clock, ntp_adj, cycle_delta);
/* Special case for jiffies tick/offset based systems
* add arch specific offset
*/
ns_offset += arch_getoffset();
return ns_offset;
}
cycle_now is 32 bits. If the clocksource overflows (which it can in 30
seconds) the cyclec_delta will be wrong.
Not only this, but pretty much all places cycle_last is updated will be
wrong.
I'm not sure of a good fix around this. Please don't say (well, don't run
with priority above timers tasklet ;-)
Would it be OK to move some of the accounting to the sched_tick code. Or
someplace that only happens periodically. Or is this too much of a
latency. But then again, if we don't do something, a high priority
process can screw up the time keeping for all others.
-- Steve
* Steven Rostedt <[email protected]> wrote:
> static inline nsec_t __get_nsec_offset(void)
> {
> cycle_t cycle_now, cycle_delta;
> nsec_t ns_offset;
>
> /* read clocksource */
> cycle_now = read_clocksource(clock);
>
> /* calculate the delta since the last timeofday_periodic_hook */
> cycle_delta = (cycle_now - cycle_last) & clock->mask;
>
> /* convert to nanoseconds */
> ns_offset = cyc2ns(clock, ntp_adj, cycle_delta);
>
> /* Special case for jiffies tick/offset based systems
> * add arch specific offset
> */
> ns_offset += arch_getoffset();
>
> return ns_offset;
> }
>
> cycle_now is 32 bits. If the clocksource overflows (which it can in
> 30 seconds) the cyclec_delta will be wrong.
isnt cycle_t 64 bits?
Ingo
On Thu, 20 Oct 2005, Ingo Molnar wrote:
>
> * Steven Rostedt <[email protected]> wrote:
>
> > static inline nsec_t __get_nsec_offset(void)
> > {
> > cycle_t cycle_now, cycle_delta;
> > nsec_t ns_offset;
> >
> > /* read clocksource */
> > cycle_now = read_clocksource(clock);
> >
> > /* calculate the delta since the last timeofday_periodic_hook */
> > cycle_delta = (cycle_now - cycle_last) & clock->mask;
> >
> > /* convert to nanoseconds */
> > ns_offset = cyc2ns(clock, ntp_adj, cycle_delta);
> >
> > /* Special case for jiffies tick/offset based systems
> > * add arch specific offset
> > */
> > ns_offset += arch_getoffset();
> >
> > return ns_offset;
> > }
> >
> > cycle_now is 32 bits. If the clocksource overflows (which it can in
> > 30 seconds) the cyclec_delta will be wrong.
>
> isnt cycle_t 64 bits?
>
Not anymore.
include/linux/time.h:
/* timeofday base types */
typedef s64 nsec_t;
typedef unsigned long cycle_t;
-- Steve
On Thu, 20 Oct 2005, Steven Rostedt wrote:
> > isnt cycle_t 64 bits?
> >
>
> Not anymore.
>
> include/linux/time.h:
>
> /* timeofday base types */
> typedef s64 nsec_t;
> typedef unsigned long cycle_t;
>
At least not on a 32 bit machine.
-- Steve
On Thu, 20 Oct 2005, Steven Rostedt wrote:
>
> On Thu, 20 Oct 2005, Ingo Molnar wrote:
>
> >
> > * Steven Rostedt <[email protected]> wrote:
> >
> > > static inline nsec_t __get_nsec_offset(void)
> > > {
> > > cycle_t cycle_now, cycle_delta;
> > > nsec_t ns_offset;
> > >
> > > /* read clocksource */
> > > cycle_now = read_clocksource(clock);
> > >
> > > /* calculate the delta since the last timeofday_periodic_hook */
> > > cycle_delta = (cycle_now - cycle_last) & clock->mask;
> > >
> > > /* convert to nanoseconds */
> > > ns_offset = cyc2ns(clock, ntp_adj, cycle_delta);
> > >
> > > /* Special case for jiffies tick/offset based systems
> > > * add arch specific offset
> > > */
> > > ns_offset += arch_getoffset();
> > >
> > > return ns_offset;
> > > }
> > >
> > > cycle_now is 32 bits. If the clocksource overflows (which it can in
> > > 30 seconds) the cyclec_delta will be wrong.
> >
> > isnt cycle_t 64 bits?
> >
>
> Not anymore.
>
> include/linux/time.h:
>
> /* timeofday base types */
> typedef s64 nsec_t;
> typedef unsigned long cycle_t;
>
FYI,
I just switched cycle_t to u64 and hackbench no longer makes the time go
backwards.
John, would this cause any problems to keep cycle_t at s64?
-- Steve
On Thu, 20 Oct 2005, Steven Rostedt wrote:
> >
> > Not anymore.
> >
> > include/linux/time.h:
> >
> > /* timeofday base types */
> > typedef s64 nsec_t;
> > typedef unsigned long cycle_t;
> >
>
> FYI,
>
> I just switched cycle_t to u64 and hackbench no longer makes the time go
> backwards.
>
> John, would this cause any problems to keep cycle_t at s64?
I mean at u64.
-- Steve
On Wed, 19 Oct 2005, Thomas Gleixner wrote:
> On Wed, 2005-10-19 at 10:59 -0400, Steven Rostedt wrote:
> > Hi Thomas,
> >
> > I switched my custom kernel timer to use the ktimers with the prio of -1
> > as you mentioned to me offline. I set up the timer to be monotonic and
> > have a requirement that the returned time is always greater or equal to
> > the last time returned from do_get_ktime_mono.
> >
> > Now here's the results that I got between two calls of do_get_ktime_mono
> >
> > 358.069795728 secs then later 355.981483177. Should this ever happen?
>
> Definitely not. monotonic time must go forwards.
>
> > I haven't look to see if this happens in vanilla -rt10 but I haven't
> > touched your ktimer code except for my logging and the patch with the
> > unlock_ktimer_base (since I was based off of -rt9)
>
> The ktimer code itself calls the timeofday code, which provides the
> monotonic clock. I have no idea what might go wrong.
>
> Is this reproducible ?
>
FYI, I just merged my changes with -rt13 and everything seems to be
working very smoothly. I've been running my kernel over an hour without
showing the backward times. I haven't even added the change from cycle_t
to be 64 bits.
So, knock on wood, maybe one of the latest updates fixed the problem. Or
maybe as soon as I hit send, the machine will crash.
I'll keep you all posted.
-- Steve
On Thu, 20 Oct 2005, Steven Rostedt wrote:
>
> Yes, but that shouldn't make a difference. NTP can slow down or speed up
> the clock, but it should never make it go backwards. Especially for a
> monotonic clock (as the name suggests).
It looks like if ntp_adj held a big negative number you might end
up with a smaller output . ntp_adj is signed too .. I don't know how
ntp_adj is set though .
I thought I remember George Anzinger speculating that ntp could
cause the time to backwards , that's why I brought it up. Maybe if he's
read he can clue us in ..
Daniel
On Thu, 20 Oct 2005, Steven Rostedt wrote:
>
> FYI, I just merged my changes with -rt13 and everything seems to be
> working very smoothly. I've been running my kernel over an hour without
> showing the backward times. I haven't even added the change from cycle_t
> to be 64 bits.
>
>
> So, knock on wood, maybe one of the latest updates fixed the problem. Or
> maybe as soon as I hit send, the machine will crash.
>
> I'll keep you all posted.
>
Spoke too soon ;-)
About ten minutes after sending this, the clock went backwards, and once
again by 2 seconds.
now=5856:283756196 last_count=5858:436968526
Where now is 5856.283756196 seconds and last count is 5858.436968526.
I'll have to put this test in other places in Ingo's kernel to see if I
can trigger it there.
Also, after the machine rebooted into Ingo's -rt13 it hit a NMI watchdog
detected lockup on bootup. This looks like a false positive since this
was spit out without any pause.
EXT3-fs: write access will be enabled during recovery.
NMI watchdog detected lockup on CPU#0 (50000/50000)
Pid: 773, comm: IRQ 14
EIP: 0060:[<c0143892>] CPU: 0
EIP is at trace_special_pid+0x52/0xb0
EFLAGS: 00000002 Not tainted (2.6.14-rc4-rt13)
EAX: 00000000 EBX: c03efb60 ECX: c030248d EDX: 00000000
ESI: 00000002 EDI: 00000000 EBP: df4e1dcc DS: 007b ES: 007b
CR0: 8005003b CR2: fffa7000 CR3: 003dc000 CR4: 000006d0
[<c0101482>] show_regs+0x152/0x180 (36)
[<c01155ba>] nmi_watchdog_tick+0x15a/0x220 (52)
[<c01051c2>] default_do_nmi+0x72/0x180 (96)
[<c0105330>] do_nmi+0x50/0x60 (24)
[<c0103fe6>] nmi_stack_correct+0x1d/0x22 (104)
[<c030248d>] __down_mutex+0x40d/0x920 (124)
[<c0304dd8>] _spin_lock_irqsave+0x28/0x60 (28)
[<c0128738>] lock_timer_base+0x28/0x50 (24)
[<c012879e>] __mod_timer+0x3e/0xe0 (36)
[<c028387d>] __ide_set_handler+0x4d/0x80 (32)
[<c02838ea>] ide_set_handler+0x3a/0x50 (28)
[<c0287d06>] task_in_intr+0x86/0x110 (36)
[<c028203f>] ide_intr+0xdf/0x190 (40)
[<c014f31c>] handle_IRQ_event+0x6c/0x110 (52)
[<c01503e6>] thread_edge_irq+0x66/0x110 (36)
[<c01504d7>] do_hardirq+0x47/0xc0 (20)
[<c01505c7>] do_irqd+0x77/0xb0 (32)
[<c013569e>] kthread+0xae/0xc0 (48)
[<c01014b5>] kernel_thread_helper+0x5/0x10 (548528156)
---------------------------
| preempt count: 00000004 ]
| 4-level deep critical section nesting:
----------------------------------------
.. [<c0145c1a>] .... add_preempt_count+0x1a/0x20
.....[<c030298c>] .. ( <= __down_mutex+0x90c/0x920)
.. [<c0145c1a>] .... add_preempt_count+0x1a/0x20
.....[<c03020d6>] .. ( <= __down_mutex+0x56/0x920)
.. [<c0145c1a>] .... add_preempt_count+0x1a/0x20
.....[<c03020e2>] .. ( <= __down_mutex+0x62/0x920)
.. [<c0145c1a>] .... add_preempt_count+0x1a/0x20
.....[<c011558b>] .. ( <= nmi_watchdog_tick+0x12b/0x220)
------------------------------
| showing all locks held by: | (IRQ 14/773 [df4de7a0, 54]):
------------------------------
#001: [c0373b40] {ide_lock}
... acquired at: ide_set_handler+0x18/0x50
I'll look into this as well.
-- Steve
On Thu, 20 Oct 2005, Steven Rostedt wrote:
>
> Also, after the machine rebooted into Ingo's -rt13 it hit a NMI watchdog
> detected lockup on bootup. This looks like a false positive since this
> was spit out without any pause.
>
My mistake, there is a pause, I just didn't notice it the first time. So
this is probably not a false positive.
-- Steve
* Steven Rostedt <[email protected]> wrote:
> > I just switched cycle_t to u64 and hackbench no longer makes the time go
> > backwards.
> >
> > John, would this cause any problems to keep cycle_t at s64?
>
> I mean at u64.
ugh. There's both cycles_t and cycle_t. We should unify the two and it
should be 64-bit. The faster systems get, the sooner the 32-bit counter
overflows. 64-bit systems are keeping 32-bit compatibility for quite
some time to come. So with an 8GHz CPU the 32-bit cycle_t would wrap in
like 500 msecs, way too fast to rely on ... (even with a 4GHz CPUs it's
only one second.)
i've made cycle_t u64 and have uploaded -rt14.
Ingo
On Thu, 20 Oct 2005, Steven Rostedt wrote:
>
> On Thu, 20 Oct 2005, Steven Rostedt wrote:
> >
> > FYI, I just merged my changes with -rt13 and everything seems to be
> > working very smoothly. I've been running my kernel over an hour without
> > showing the backward times. I haven't even added the change from cycle_t
> > to be 64 bits.
> >
> >
> > So, knock on wood, maybe one of the latest updates fixed the problem. Or
> > maybe as soon as I hit send, the machine will crash.
> >
> > I'll keep you all posted.
> >
>
> Spoke too soon ;-)
>
> About ten minutes after sending this, the clock went backwards, and once
> again by 2 seconds.
>
> now=5856:283756196 last_count=5858:436968526
>
> Where now is 5856.283756196 seconds and last count is 5858.436968526.
>
Pádraig sent me an email showing that this time difference is what it
would take a 2GHz machine to overflow a 32 bit number. I'll go and switch
the cycle_t to 64 bits and see if this solves the problem.
-- Steve
On Thu, 20 Oct 2005, Ingo Molnar wrote:
>
> * Steven Rostedt <[email protected]> wrote:
>
> > > I just switched cycle_t to u64 and hackbench no longer makes the time go
> > > backwards.
> > >
> > > John, would this cause any problems to keep cycle_t at s64?
> >
> > I mean at u64.
>
> ugh. There's both cycles_t and cycle_t. We should unify the two and it
> should be 64-bit. The faster systems get, the sooner the 32-bit counter
> overflows. 64-bit systems are keeping 32-bit compatibility for quite
> some time to come. So with an 8GHz CPU the 32-bit cycle_t would wrap in
> like 500 msecs, way too fast to rely on ... (even with a 4GHz CPUs it's
> only one second.)
>
> i've made cycle_t u64 and have uploaded -rt14.
>
Ingo,
I'm disappointed in you, I expected you to upload 2.6.14-rc5-rt1
;-)
-- Steve
On Thu, 2005-10-20 at 06:05 -0400, Steven Rostedt wrote:
>
> On Thu, 20 Oct 2005, Steven Rostedt wrote:
>
> > >
> > > Not anymore.
> > >
> > > include/linux/time.h:
> > >
> > > /* timeofday base types */
> > > typedef s64 nsec_t;
> > > typedef unsigned long cycle_t;
> > >
> >
> > FYI,
> >
> > I just switched cycle_t to u64 and hackbench no longer makes the time go
> > backwards.
> >
> > John, would this cause any problems to keep cycle_t at s64?
>
> I mean at u64.
Performance would be the only concern. It had been a u64 before I
started optimizing the code a bit.
The real problem however was the timeofday_perioidic_hook() was being
starved. Since not all clocksources are 64 bits wide (although most do
not overflow as fast as 32bits of the TSC) I'm not sure that will always
solve the issue.
Ingo: Should the periodic_hook() call be converted to using the ktimer
or some other interface to ensure that it will be regularly run at some
frequency (currently 50ms, but that can be changed)?
thanks
-john
On Thu, 20 Oct 2005, john stultz wrote:
> > >
> > > John, would this cause any problems to keep cycle_t at s64?
> >
> > I mean at u64.
>
> Performance would be the only concern. It had been a u64 before I
> started optimizing the code a bit.
>
> The real problem however was the timeofday_perioidic_hook() was being
> starved. Since not all clocksources are 64 bits wide (although most do
> not overflow as fast as 32bits of the TSC) I'm not sure that will always
> solve the issue.
>
> Ingo: Should the periodic_hook() call be converted to using the ktimer
> or some other interface to ensure that it will be regularly run at some
> frequency (currently 50ms, but that can be changed)?
>
Thomas showed me a trick with the ktimers API, that I use to schedule my
custom scheduler. If you set periodic_hook to be called via ktimer with a
prio of -1, it will force the timer to be run in the timer interrupt
instead of a softirq task.
Now the issue is the latency this would cause and to make sure that
periodic_hook only grabs raw locks. Ingo?
-- Steve
On Thu, 2005-10-20 at 12:58 -0400, Steven Rostedt wrote:
> On Thu, 20 Oct 2005, john stultz wrote:
>
> > > >
> > > > John, would this cause any problems to keep cycle_t at s64?
> > >
> > > I mean at u64.
> >
> > Performance would be the only concern. It had been a u64 before I
> > started optimizing the code a bit.
> >
> > The real problem however was the timeofday_perioidic_hook() was being
> > starved. Since not all clocksources are 64 bits wide (although most do
> > not overflow as fast as 32bits of the TSC) I'm not sure that will always
> > solve the issue.
> >
> > Ingo: Should the periodic_hook() call be converted to using the ktimer
> > or some other interface to ensure that it will be regularly run at some
> > frequency (currently 50ms, but that can be changed)?
> >
>
> Thomas showed me a trick with the ktimers API, that I use to schedule my
> custom scheduler. If you set periodic_hook to be called via ktimer with a
> prio of -1, it will force the timer to be run in the timer interrupt
> instead of a softirq task.
>
> Now the issue is the latency this would cause and to make sure that
> periodic_hook only grabs raw locks. Ingo?
Ok, do let me know if its a problem spot. I've not been too thoughtful
in minimizing how long the lock is held for. I'll see if that cannot be
minimized.
Thanks for the thorough testing and feedback!
-john
* john stultz <[email protected]> wrote:
> > > John, would this cause any problems to keep cycle_t at s64?
> >
> > I mean at u64.
>
> Performance would be the only concern. It had been a u64 before I
> started optimizing the code a bit.
no, this is really a bad optimization that causes unrobustness.
Correctness and robustness comes first. It is so easy to cause a
500-1000msec delay in the kernel, due to a bad driver or anything. The
timekeeping code should not break like that.
Ingo
On Thu, 2005-10-20 at 21:32 +0200, Ingo Molnar wrote:
> * john stultz <[email protected]> wrote:
>
> > > > John, would this cause any problems to keep cycle_t at s64?
> > >
> > > I mean at u64.
> >
> > Performance would be the only concern. It had been a u64 before I
> > started optimizing the code a bit.
>
> no, this is really a bad optimization that causes unrobustness.
> Correctness and robustness comes first. It is so easy to cause a
> 500-1000msec delay in the kernel, due to a bad driver or anything. The
> timekeeping code should not break like that.
Eh, its an easy enough change, so I'll put it back to u64. We can
revisit it again later if needed.
However making sure periodic_hook isn't starved for too long is
important for good timekeeping, since ntp and cpufreq adjustments are
made at that point. Steven's suggestion of moving it to use ktimers
sounds like a good plan, but let me know if you can see any other holes.
thanks
-john.
* john stultz <[email protected]> wrote:
> > no, this is really a bad optimization that causes unrobustness.
> > Correctness and robustness comes first. It is so easy to cause a
> > 500-1000msec delay in the kernel, due to a bad driver or anything. The
> > timekeeping code should not break like that.
>
> Eh, its an easy enough change, so I'll put it back to u64. We can
> revisit it again later if needed.
yeah. i didnt notice u64 hurting that much, and we can optimize it later
on. As long as the 64-bit CPUs are ok, we shouldnt care all that much
about micro-performance - especially not at the expense of robustness.
> However making sure periodic_hook isn't starved for too long is
> important for good timekeeping, since ntp and cpufreq adjustments are
> made at that point. Steven's suggestion of moving it to use ktimers
> sounds like a good plan, but let me know if you can see any other
> holes.
yes. Besides driver bugs and 'badly behaving' code, there's another use
case: in the PREEMPT_RT kernel it's the user that picks the priorities
for kernel functionalities in a very finegrained way: if his
data-collection device interrupt and driver code is more important than
anything else on the system (including timekeeping), then that's the way
it will be. So the seemingly contradictory (and amusing) situation
arises that the -rt kernel, which is all about low latencies, also
increases the the need for subsystems to more robustly _bear with_
higher latencies - for the case where they happen to be the lowprio guy
...
but i agree - excessive latencies cannot be tolerated - but up to a few
seconds can easily happen in various situations.
Ingo
Steven Rostedt wrote:
~> Could this cause a 2 second drop backwards?
>
>
A 2 second warp is _most_ likely an overflow issue with nanoseconds (not many seconds fit in a
32-bit long).
~
--
George Anzinger [email protected]
HRT (High-res-timers): http://sourceforge.net/projects/high-res-timers/
Daniel Walker wrote:
> On Thu, 20 Oct 2005, Steven Rostedt wrote:
>
>>
>> Yes, but that shouldn't make a difference. NTP can slow down or speed up
>> the clock, but it should never make it go backwards. Especially for a
>> monotonic clock (as the name suggests).
>
>
> It looks like if ntp_adj held a big negative number you might end up
> with a smaller output . ntp_adj is signed too .. I don't know how
> ntp_adj is set though .
>
> I thought I remember George Anzinger speculating that ntp could
> cause the time to backwards , that's why I brought it up. Maybe if he's
> read he can clue us in ..
>
I think John has changed this, but in the "old" code if ntp was correcting the clock such that less
than TICK_NSEC was added on a tick, AND, the time was read just prior to this tick the get_offset
code would return ~TICK_NSEC of offset which would mean that a read right after the tick might be
less than the one just prior to the tick. The error, however, would be in the nanosecond area (no
where near a second). Again, as I said, I think John has changed this in is code so that the
get_offset equivalent is also ntp corrected, thus eliminating the small back step.
>
--
George Anzinger [email protected]
HRT (High-res-timers): http://sourceforge.net/projects/high-res-timers/
On Thu, 2005-10-20 at 15:19 -0700, George Anzinger wrote:
> Daniel Walker wrote:
> > On Thu, 20 Oct 2005, Steven Rostedt wrote:
> >
> >>
> >> Yes, but that shouldn't make a difference. NTP can slow down or speed up
> >> the clock, but it should never make it go backwards. Especially for a
> >> monotonic clock (as the name suggests).
> >
> >
> > It looks like if ntp_adj held a big negative number you might end up
> > with a smaller output . ntp_adj is signed too .. I don't know how
> > ntp_adj is set though .
> >
> > I thought I remember George Anzinger speculating that ntp could
> > cause the time to backwards , that's why I brought it up. Maybe if he's
> > read he can clue us in ..
> >
> I think John has changed this, but in the "old" code if ntp was correcting the clock such that less
> than TICK_NSEC was added on a tick, AND, the time was read just prior to this tick the get_offset
> code would return ~TICK_NSEC of offset which would mean that a read right after the tick might be
> less than the one just prior to the tick. The error, however, would be in the nanosecond area (no
> where near a second). Again, as I said, I think John has changed this in is code so that the
> get_offset equivalent is also ntp corrected, thus eliminating the small back step.
> >
Indeed. This is one of the bugs my patch addresses. NTP adjustments are
made as frequency adjustments for a entire interval, rather then fixed
value adjustments made at tick time. Thus time is accumulated in the
same way it is calculated in gettimeofday, avoiding time
inconsistencies.
However, my code does require periodic_hook be called at least once per
rollover of the clocksource counter, so that we get a chance to
accumulate time properly. But considering the current code has issues if
we miss a single tick, I consider it an improvement. :)
thanks
-john
On Thu, 20 Oct 2005, Ingo Molnar wrote:
>
> * john stultz <[email protected]> wrote:
>
> > > > John, would this cause any problems to keep cycle_t at s64?
> > >
> > > I mean at u64.
> >
> > Performance would be the only concern. It had been a u64 before I
> > started optimizing the code a bit.
>
> no, this is really a bad optimization that causes unrobustness.
> Correctness and robustness comes first. It is so easy to cause a
> 500-1000msec delay in the kernel, due to a bad driver or anything. The
> timekeeping code should not break like that.
>
FYI,
With rc4-rt13 and changing cycle_t to u64, my machine ran all night
without one backward step. Since it use to show up after a couple of
hours, I would say that this is the fix.
John, Do you want me to take a crack at changing the periodic_hook into
using the ktimer code? I understand Ingo's kernel much more than you, but
you definitely understand the timing code better than I.
Cheers,
-- Steve
On Fri, 2005-10-21 at 02:03 -0400, Steven Rostedt wrote:
> On Thu, 20 Oct 2005, Ingo Molnar wrote:
> With rc4-rt13 and changing cycle_t to u64, my machine ran all night
> without one backward step. Since it use to show up after a couple of
> hours, I would say that this is the fix.
>
> John, Do you want me to take a crack at changing the periodic_hook into
> using the ktimer code? I understand Ingo's kernel much more than you, but
> you definitely understand the timing code better than I.
Steve,
I think the hook is too complex to move it into the timer interrupt
context. We still have to reimplement the dynamic priority adjustment of
the ktimer softirq in a clean way. Once this is done, we can move it
over and set a proper priority up for that.
tglx
Thomas,
I noticed you changed the names around for ktimer_start/restart. Is it OK
to just use the restart, if you don't know if it has already started,
every time, and never call the start. It seems to be OK now, but will
that ever change?
Basically, is just the ktimer_init good enough for ktimer_restart?
Thanks,
-- Steve
On Fri, 21 Oct 2005, Thomas Gleixner wrote:
> On Fri, 2005-10-21 at 02:03 -0400, Steven Rostedt wrote:
> > On Thu, 20 Oct 2005, Ingo Molnar wrote:
>
> > With rc4-rt13 and changing cycle_t to u64, my machine ran all night
> > without one backward step. Since it use to show up after a couple of
> > hours, I would say that this is the fix.
> >
> > John, Do you want me to take a crack at changing the periodic_hook into
> > using the ktimer code? I understand Ingo's kernel much more than you, but
> > you definitely understand the timing code better than I.
>
> Steve,
>
> I think the hook is too complex to move it into the timer interrupt
> context. We still have to reimplement the dynamic priority adjustment of
> the ktimer softirq in a clean way. Once this is done, we can move it
> over and set a proper priority up for that.
>
OK, but the u64 cycle_t should stay. Even with the dynamic priority of
the softirq, a process with a super high priority that doesn't care about
the timing code can still make the periodic_hook delay for a few seconds.
-- Steve
On Fri, 2005-10-21 at 04:00 -0400, Steven Rostedt wrote:
> Thomas,
>
> I noticed you changed the names around for ktimer_start/restart. Is it OK
> to just use the restart, if you don't know if it has already started,
> every time, and never call the start. It seems to be OK now, but will
> that ever change?
No. Note also that there are no functional changes in the code. Its only
a cleanup vs. coding style and namespaces.
> Basically, is just the ktimer_init good enough for ktimer_restart?
Yes
tglx
On Fri, 2005-10-21 at 02:03 -0400, Steven Rostedt wrote:
> With rc4-rt13 and changing cycle_t to u64, my machine ran all night
> without one backward step. Since it use to show up after a couple of
> hours, I would say that this is the fix.
Great. I've committed that change to my tree already.
> John, Do you want me to take a crack at changing the periodic_hook into
> using the ktimer code? I understand Ingo's kernel much more than you, but
> you definitely understand the timing code better than I.
If Thomas doesn't think its a good idea, then don't worry about it. I'd
be somewhat curious just how bad it is, but that can wait for now.
thanks
-john
On Fri, 2005-10-21 at 11:09 -0700, john stultz wrote:
> On Fri, 2005-10-21 at 02:03 -0400, Steven Rostedt wrote:
> > With rc4-rt13 and changing cycle_t to u64, my machine ran all night
> > without one backward step. Since it use to show up after a couple of
> > hours, I would say that this is the fix.
>
> Great. I've committed that change to my tree already.
>
>
> > John, Do you want me to take a crack at changing the periodic_hook into
> > using the ktimer code? I understand Ingo's kernel much more than you, but
> > you definitely understand the timing code better than I.
>
> If Thomas doesn't think its a good idea, then don't worry about it. I'd
> be somewhat curious just how bad it is, but that can wait for now.
We actually try to keep everything out of hard interrupt context what
can be done elsewhere. Especially out of the timer interrupt.
tglx