nohz and strange sleep latencies

nohz and strange sleep latencies

[Pavel Machek]

Hi!

On unloaded x60 system, 2.6.24-rc3 (tainted-pavel-so if someone can
reproduce it, it would be helpful):

pavel@amd:~$ while true; do time sleep 0.01; done
0.00user 0.00system 0.01 (0m0.013s) elapsed 30.71%CPU
0.00user 0.00system 0.02 (0m0.024s) elapsed 8.36%CPU
0.00user 0.00system 0.01 (0m0.013s) elapsed 15.53%CPU
0.00user 0.00system 0.02 (0m0.026s) elapsed 7.75%CPU
0.00user 0.00system 0.01 (0m0.013s) elapsed 23.34%CPU
0.00user 0.00system 0.20 (0m0.207s) elapsed 1.45%CPU
0.00user 0.00system 0.01 (0m0.013s) elapsed 15.59%CPU
0.00user 0.00system 0.23 (0m0.230s) elapsed 1.30%CPU
0.00user 0.00system 0.01 (0m0.013s) elapsed 15.61%CPU
0.00user 0.00system 0.20 (0m0.201s) elapsed 1.48%CPU
0.00user 0.00system 0.01 (0m0.013s) elapsed 15.50%CPU
0.00user 0.00system 0.19 (0m0.190s) elapsed 1.05%CPU
0.00user 0.00system 0.01 (0m0.013s) elapsed 23.37%CPU
0.00user 0.00system 0.04 (0m0.049s) elapsed 4.09%CPU
0.00user 0.00system 0.01 (0m0.013s) elapsed 23.35%CPU
0.00user 0.00system 0.01 (0m0.017s) elapsed 11.89%CPU
0.00user 0.00system 0.01 (0m0.013s) elapsed 23.38%CPU
0.00user 0.00system 0.08 (0m0.081s) elapsed 3.71%CPU
0.00user 0.00system 0.01 (0m0.013s) elapsed 23.33%CPU
0.00user 0.00system 0.01 (0m0.019s) elapsed 15.92%CPU

nohz=off helps a lot. while true; do time sleep 0.0; done does not
have unexpected latencies.
									Pavel
-- 
(english) http://www.livejournal.com/~pavelmachek
(cesky, pictures) http://atrey.karlin.mff.cuni.cz/~pavel/picture/horses/blog.html

Re: nohz and strange sleep latencies

[Ingo Molnar]

* Pavel Machek <pavel@ucw.cz> wrote:

> Hi!
> 
> On unloaded x60 system, 2.6.24-rc3 (tainted-pavel-so if someone can
> reproduce it, it would be helpful):
> 
> pavel@amd:~$ while true; do time sleep 0.01; done
> 0.00user 0.00system 0.01 (0m0.013s) elapsed 30.71%CPU
> 0.00user 0.00system 0.02 (0m0.024s) elapsed 8.36%CPU
> 0.00user 0.00system 0.01 (0m0.013s) elapsed 15.53%CPU
> 0.00user 0.00system 0.02 (0m0.026s) elapsed 7.75%CPU
> 0.00user 0.00system 0.01 (0m0.013s) elapsed 23.34%CPU
> 0.00user 0.00system 0.20 (0m0.207s) elapsed 1.45%CPU
> 0.00user 0.00system 0.01 (0m0.013s) elapsed 15.59%CPU
> 0.00user 0.00system 0.23 (0m0.230s) elapsed 1.30%CPU
> 0.00user 0.00system 0.01 (0m0.013s) elapsed 15.61%CPU
> 0.00user 0.00system 0.20 (0m0.201s) elapsed 1.48%CPU
> 0.00user 0.00system 0.01 (0m0.013s) elapsed 15.50%CPU
> 0.00user 0.00system 0.19 (0m0.190s) elapsed 1.05%CPU
> 0.00user 0.00system 0.01 (0m0.013s) elapsed 23.37%CPU
> 0.00user 0.00system 0.04 (0m0.049s) elapsed 4.09%CPU
> 0.00user 0.00system 0.01 (0m0.013s) elapsed 23.35%CPU
> 0.00user 0.00system 0.01 (0m0.017s) elapsed 11.89%CPU
> 0.00user 0.00system 0.01 (0m0.013s) elapsed 23.38%CPU
> 0.00user 0.00system 0.08 (0m0.081s) elapsed 3.71%CPU
> 0.00user 0.00system 0.01 (0m0.013s) elapsed 23.33%CPU
> 0.00user 0.00system 0.01 (0m0.019s) elapsed 15.92%CPU
> 
> nohz=off helps a lot. while true; do time sleep 0.0; done does not 
> have unexpected latencies.

does hpet=disable on the boot line also help? (without nohz=off)

	Ingo

Re: nohz and strange sleep latencies

[Pavel Machek]

Hi!

> > On unloaded x60 system, 2.6.24-rc3 (tainted-pavel-so if someone can
> > reproduce it, it would be helpful):
> > 
> > pavel@amd:~$ while true; do time sleep 0.01; done
> > 0.00user 0.00system 0.01 (0m0.013s) elapsed 30.71%CPU
> > 0.00user 0.00system 0.02 (0m0.024s) elapsed 8.36%CPU
> > 0.00user 0.00system 0.01 (0m0.013s) elapsed 15.53%CPU
> > 0.00user 0.00system 0.02 (0m0.026s) elapsed 7.75%CPU
> > 0.00user 0.00system 0.01 (0m0.013s) elapsed 23.34%CPU
> > 0.00user 0.00system 0.20 (0m0.207s) elapsed 1.45%CPU
> > 0.00user 0.00system 0.01 (0m0.013s) elapsed 15.59%CPU
> > 0.00user 0.00system 0.23 (0m0.230s) elapsed 1.30%CPU
> > 0.00user 0.00system 0.01 (0m0.013s) elapsed 15.61%CPU
> > 0.00user 0.00system 0.20 (0m0.201s) elapsed 1.48%CPU
> > 0.00user 0.00system 0.01 (0m0.013s) elapsed 15.50%CPU
> > 0.00user 0.00system 0.19 (0m0.190s) elapsed 1.05%CPU
> > 0.00user 0.00system 0.01 (0m0.013s) elapsed 23.37%CPU
> > 0.00user 0.00system 0.04 (0m0.049s) elapsed 4.09%CPU
> > 0.00user 0.00system 0.01 (0m0.013s) elapsed 23.35%CPU
> > 0.00user 0.00system 0.01 (0m0.017s) elapsed 11.89%CPU
> > 0.00user 0.00system 0.01 (0m0.013s) elapsed 23.38%CPU
> > 0.00user 0.00system 0.08 (0m0.081s) elapsed 3.71%CPU
> > 0.00user 0.00system 0.01 (0m0.013s) elapsed 23.33%CPU
> > 0.00user 0.00system 0.01 (0m0.019s) elapsed 15.92%CPU
> > 
> > nohz=off helps a lot. while true; do time sleep 0.0; done does not 
> > have unexpected latencies.
> 
> does hpet=disable on the boot line also help? (without nohz=off)

hpet-disable helps.. a bit. 200msec latencies are gone. (What is used
for wakeups in this case?)

pavel@amd:~$ while true; do time sleep 0.01; done
0.00user 0.00system 0.01 (0m0.013s) elapsed 22.96%CPU
0.00user 0.00system 0.01 (0m0.018s) elapsed 11.05%CPU
0.00user 0.00system 0.01 (0m0.013s) elapsed 15.54%CPU
0.00user 0.00system 0.03 (0m0.037s) elapsed 8.05%CPU
0.00user 0.00system 0.01 (0m0.013s) elapsed 23.34%CPU
0.00user 0.00system 0.03 (0m0.037s) elapsed 8.14%CPU
0.00user 0.00system 0.01 (0m0.013s) elapsed 23.33%CPU
0.00user 0.00system 0.03 (0m0.037s) elapsed 8.16%CPU
0.00user 0.00system 0.01 (0m0.013s) elapsed 23.30%CPU
0.00user 0.00system 0.03 (0m0.037s) elapsed 5.47%CPU
0.00user 0.00system 0.01 (0m0.013s) elapsed 23.25%CPU
0.00user 0.00system 0.01 (0m0.013s) elapsed 15.54%CPU
0.00user 0.00system 0.01 (0m0.013s) elapsed 15.56%CPU
0.00user 0.00system 0.03 (0m0.036s) elapsed 5.49%CPU
0.00user 0.00system 0.01 (0m0.013s) elapsed 23.35%CPU
0.00user 0.00system 0.03 (0m0.037s) elapsed 8.14%CPU
0.00user 0.00system 0.01 (0m0.013s) elapsed 23.35%CPU
0.00user 0.00system 0.03 (0m0.037s) elapsed 8.14%CPU
0.00user 0.00system 0.01 (0m0.013s) elapsed 23.34%CPU
									Pavel
-- 
(english) http://www.livejournal.com/~pavelmachek
(cesky, pictures) http://atrey.karlin.mff.cuni.cz/~pavel/picture/horses/blog.html

Re: nohz and strange sleep latencies

[Ingo Molnar]

* Pavel Machek <pavel@ucw.cz> wrote:

> > > 0.00user 0.00system 0.08 (0m0.081s) elapsed 3.71%CPU
> > > 0.00user 0.00system 0.01 (0m0.013s) elapsed 23.33%CPU
> > > 0.00user 0.00system 0.01 (0m0.019s) elapsed 15.92%CPU
> > > 
> > > nohz=off helps a lot. while true; do time sleep 0.0; done does not 
> > > have unexpected latencies.
> > 
> > does hpet=disable on the boot line also help? (without nohz=off)
> 
> hpet-disable helps.. a bit. 200msec latencies are gone. (What is used 
> for wakeups in this case?)
> 
> pavel@amd:~$ while true; do time sleep 0.01; done
> 0.00user 0.00system 0.01 (0m0.013s) elapsed 22.96%CPU
> 0.00user 0.00system 0.01 (0m0.018s) elapsed 11.05%CPU
> 0.00user 0.00system 0.01 (0m0.013s) elapsed 15.54%CPU

could you run this while doing the sleep test:

  http://people.redhat.com/mingo/cfs-scheduler/tools/cfs-debug-info.sh

and send us the output? (Enabling CONFIG_TIMER_STATS, CONFIG_SCHED_DEBUG 
and CONFIG_SCHEDSTATS would maximize the amount of information.)

	Ingo

Re: nohz and strange sleep latencies

[Ingo Molnar]

* Ingo Molnar <mingo@elte.hu> wrote:

> > hpet-disable helps.. a bit. 200msec latencies are gone. (What is 
> > used for wakeups in this case?)
> > 
> > pavel@amd:~$ while true; do time sleep 0.01; done
> > 0.00user 0.00system 0.01 (0m0.013s) elapsed 22.96%CPU
> > 0.00user 0.00system 0.01 (0m0.018s) elapsed 11.05%CPU
> > 0.00user 0.00system 0.01 (0m0.013s) elapsed 15.54%CPU
> 
> could you run this while doing the sleep test:
> 
>   http://people.redhat.com/mingo/cfs-scheduler/tools/cfs-debug-info.sh
> 
> and send us the output? (Enabling CONFIG_TIMER_STATS, 
> CONFIG_SCHED_DEBUG and CONFIG_SCHEDSTATS would maximize the amount of 
> information.)

another question: do you feel and see these timer latencies? If unsure 
you can do a timing test from a remote (known-good) box:

   while :; do time ssh testbox sleep 0.01; done

there'll be a fair bit of offset cost and noise, but these fluctuations 
should still be there and should be noticeable.

but i suspect the delays are "real", i.e. caused by timers not firing at 
the right moment and not by some GTOD anomaly. Once you send the debug 
data we might be able to tell more.

	Ingo

Re: nohz and strange sleep latencies

[Thomas Gleixner]

On Mon, 19 Nov 2007, Pavel Machek wrote:
> On unloaded x60 system, 2.6.24-rc3 (tainted-pavel-so if someone can
> reproduce it, it would be helpful):

Can you please provide your .config ?

    tglx

Re: nohz and strange sleep latencies

[Pavel Machek]

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

Hi!
> 
> > > > 0.00user 0.00system 0.08 (0m0.081s) elapsed 3.71%CPU
> > > > 0.00user 0.00system 0.01 (0m0.013s) elapsed 23.33%CPU
> > > > 0.00user 0.00system 0.01 (0m0.019s) elapsed 15.92%CPU
> > > > 
> > > > nohz=off helps a lot. while true; do time sleep 0.0; done does not 
> > > > have unexpected latencies.
> > > 
> > > does hpet=disable on the boot line also help? (without nohz=off)
> > 
> > hpet-disable helps.. a bit. 200msec latencies are gone. (What is used 
> > for wakeups in this case?)
> > 
> > pavel@amd:~$ while true; do time sleep 0.01; done
> > 0.00user 0.00system 0.01 (0m0.013s) elapsed 22.96%CPU
> > 0.00user 0.00system 0.01 (0m0.018s) elapsed 11.05%CPU
> > 0.00user 0.00system 0.01 (0m0.013s) elapsed 15.54%CPU
> 
> could you run this while doing the sleep test:
> 
>   http://people.redhat.com/mingo/cfs-scheduler/tools/cfs-debug-info.sh
> 
> and send us the output? (Enabling CONFIG_TIMER_STATS, CONFIG_SCHED_DEBUG 
> and CONFIG_SCHEDSTATS would maximize the amount of information.)

This was w/o hpet=disable . Do you want me to test with hpet=disable?
									Pavel

-- 
(english) http://www.livejournal.com/~pavelmachek
(cesky, pictures) http://atrey.karlin.mff.cuni.cz/~pavel/picture/horses/blog.html

[-- Attachment #2: cfs-debug-info-2007.11.20-11.51.22.gz --]
[-- Type: application/octet-stream, Size: 44037 bytes --]

Re: nohz and strange sleep latencies

[Ingo Molnar]

* Pavel Machek <pavel@ucw.cz> wrote:

> > and send us the output? (Enabling CONFIG_TIMER_STATS, 
> > CONFIG_SCHED_DEBUG and CONFIG_SCHEDSTATS would maximize the amount 
> > of information.)
> 
> This was w/o hpet=disable . Do you want me to test with hpet=disable?

no, this is fine. You've got a hpet clockevents driver and two lapic 
drivers:

Clock Event Device: hpet
 set_next_event: hpet_legacy_next_event
 set_mode:       hpet_legacy_set_mode
 event_handler:  tick_handle_oneshot_broadcast

Clock Event Device: lapic
 set_next_event: lapic_next_event
 set_mode:       lapic_timer_setup
 event_handler:  hrtimer_interrupt

Clock Event Device: lapic
 set_next_event: lapic_next_event
 set_mode:       lapic_timer_setup
 event_handler:  hrtimer_interrupt

to me this has the feeling of lapic breakage in C2 mode. Does it get any 
better if you boot with 'nolapic'? (but that might in turn turn off 
high-res timers and nohz in essence) Thomas, any ideas?

	Ingo

Re: nohz and strange sleep latencies

[Thomas Gleixner]

On Tue, 20 Nov 2007, Ingo Molnar wrote:
> 
> * Pavel Machek <pavel@ucw.cz> wrote:
> 
> > > and send us the output? (Enabling CONFIG_TIMER_STATS, 
> > > CONFIG_SCHED_DEBUG and CONFIG_SCHEDSTATS would maximize the amount 
> > > of information.)
> > 
> > This was w/o hpet=disable . Do you want me to test with hpet=disable?
> 
> no, this is fine. You've got a hpet clockevents driver and two lapic 
> drivers:
> 
> Clock Event Device: hpet
>  set_next_event: hpet_legacy_next_event
>  set_mode:       hpet_legacy_set_mode
>  event_handler:  tick_handle_oneshot_broadcast
> 
> Clock Event Device: lapic
>  set_next_event: lapic_next_event
>  set_mode:       lapic_timer_setup
>  event_handler:  hrtimer_interrupt
> 
> Clock Event Device: lapic
>  set_next_event: lapic_next_event
>  set_mode:       lapic_timer_setup
>  event_handler:  hrtimer_interrupt
> 
> to me this has the feeling of lapic breakage in C2 mode. Does it get any 
> better if you boot with 'nolapic'? (but that might in turn turn off 
> high-res timers and nohz in essence) Thomas, any ideas?

Hmm, lapic is considered unstable in c2 by default. You have to tell
the kernel that you trust it in C2 on the command line.

/me goes back to read the logs

    tglx

Re: nohz and strange sleep latencies

[Ingo Molnar]

* Thomas Gleixner <tglx@linutronix.de> wrote:

> On Tue, 20 Nov 2007, Ingo Molnar wrote:
> > 
> > * Pavel Machek <pavel@ucw.cz> wrote:
> > 
> > > > and send us the output? (Enabling CONFIG_TIMER_STATS, 
> > > > CONFIG_SCHED_DEBUG and CONFIG_SCHEDSTATS would maximize the amount 
> > > > of information.)
> > > 
> > > This was w/o hpet=disable . Do you want me to test with hpet=disable?
> > 
> > no, this is fine. You've got a hpet clockevents driver and two lapic 
> > drivers:
> > 
> > Clock Event Device: hpet
> >  set_next_event: hpet_legacy_next_event
> >  set_mode:       hpet_legacy_set_mode
> >  event_handler:  tick_handle_oneshot_broadcast
> > 
> > Clock Event Device: lapic
> >  set_next_event: lapic_next_event
> >  set_mode:       lapic_timer_setup
> >  event_handler:  hrtimer_interrupt
> > 
> > Clock Event Device: lapic
> >  set_next_event: lapic_next_event
> >  set_mode:       lapic_timer_setup
> >  event_handler:  hrtimer_interrupt
> > 
> > to me this has the feeling of lapic breakage in C2 mode. Does it get any 
> > better if you boot with 'nolapic'? (but that might in turn turn off 
> > high-res timers and nohz in essence) Thomas, any ideas?
> 
> Hmm, lapic is considered unstable in c2 by default. You have to tell 
> the kernel that you trust it in C2 on the command line.

yeah, i was wondering about that too. ACPI enumerated them properly at a 
certain stage:

 ACPI: CPU0 (power states: C1[C1] C2[C2] C3[C3])
 ACPI: CPU1 (power states: C1[C1] C2[C2] C3[C3])

but perhaps somehow we miss this fact and fail to turn off the lapic 
clockevents drivers?

	Ingo

Re: nohz and strange sleep latencies

[Pavel Machek]

Hi!

> > > > > and send us the output? (Enabling CONFIG_TIMER_STATS, 
> > > > > CONFIG_SCHED_DEBUG and CONFIG_SCHEDSTATS would maximize the amount 
> > > > > of information.)
> > > > 
> > > > This was w/o hpet=disable . Do you want me to test with hpet=disable?
> > > 
> > > no, this is fine. You've got a hpet clockevents driver and two lapic 
> > > drivers:
> > > 
> > > Clock Event Device: hpet
> > >  set_next_event: hpet_legacy_next_event
> > >  set_mode:       hpet_legacy_set_mode
> > >  event_handler:  tick_handle_oneshot_broadcast
> > > 
> > > Clock Event Device: lapic
> > >  set_next_event: lapic_next_event
> > >  set_mode:       lapic_timer_setup
> > >  event_handler:  hrtimer_interrupt
> > > 
> > > Clock Event Device: lapic
> > >  set_next_event: lapic_next_event
> > >  set_mode:       lapic_timer_setup
> > >  event_handler:  hrtimer_interrupt
> > > 
> > > to me this has the feeling of lapic breakage in C2 mode. Does it get any 
> > > better if you boot with 'nolapic'? (but that might in turn turn off 
> > > high-res timers and nohz in essence) Thomas, any ideas?
> > 
> > Hmm, lapic is considered unstable in c2 by default. You have to tell 
> > the kernel that you trust it in C2 on the command line.
> 
> yeah, i was wondering about that too. ACPI enumerated them properly at a 
> certain stage:
> 
>  ACPI: CPU0 (power states: C1[C1] C2[C2] C3[C3])
>  ACPI: CPU1 (power states: C1[C1] C2[C2] C3[C3])
> 
> but perhaps somehow we miss this fact and fail to turn off the lapic 
> clockevents drivers?

I tried to add nolapic_timer manually, and that helped, but:

checking TSC synchronization [CPU#0 -> CPU#1]:
Measured 627605 cycles TSC warp between CPUs, turning off TSC clock.
Marking TSC unstable due to: check_tsc_sync_source failed.
Brought up 2 CPUs
CPU0 attaching sched-domain:
 domain 0: span 3
  groups: 1 2
CPU1 attaching sched-domain:
 domain 0: span 3
  groups: 2 1
net_namespace: 64 bytes
...
Bluetooth: HCI socket layer initialized
ACPI: RTC can wake from S4
Time: hpet clocksource has been installed.
Clockevents: could not switch to one-shot mode:<6>Clockevents: could
not switch to one-shot mode: lapic is not functional.
Could not switch to high resolution mode on CPU 1
 lapic is not functional.
Could not switch to high resolution mode on CPU 0
system 00:00: iomem range 0x0-0x9ffff could not be reserved

...and result is nohz is not functional :-(.
									Pavel
-- 
(english) http://www.livejournal.com/~pavelmachek
(cesky, pictures) http://atrey.karlin.mff.cuni.cz/~pavel/picture/horses/blog.html

Re: nohz and strange sleep latencies

[Pavel Machek]

Hi!

> > > Clock Event Device: hpet
> > >  set_next_event: hpet_legacy_next_event
> > >  set_mode:       hpet_legacy_set_mode
> > >  event_handler:  tick_handle_oneshot_broadcast
> > > 
> > > Clock Event Device: lapic
> > >  set_next_event: lapic_next_event
> > >  set_mode:       lapic_timer_setup
> > >  event_handler:  hrtimer_interrupt
> > > 
> > > Clock Event Device: lapic
> > >  set_next_event: lapic_next_event
> > >  set_mode:       lapic_timer_setup
> > >  event_handler:  hrtimer_interrupt
> > > 
> > > to me this has the feeling of lapic breakage in C2 mode. Does it get any 
> > > better if you boot with 'nolapic'? (but that might in turn turn off 
> > > high-res timers and nohz in essence) Thomas, any ideas?
> > 
> > Hmm, lapic is considered unstable in c2 by default. You have to tell 
> > the kernel that you trust it in C2 on the command line.
> 
> yeah, i was wondering about that too. ACPI enumerated them properly at a 
> certain stage:
> 
>  ACPI: CPU0 (power states: C1[C1] C2[C2] C3[C3])
>  ACPI: CPU1 (power states: C1[C1] C2[C2] C3[C3])
> 
> but perhaps somehow we miss this fact and fail to turn off the lapic 
> clockevents drivers?

I can confirm that setting max-cstate=1 helps. (Plus, problem gets
_way_ more visible with stripped down config. With usb and irda off,
time sleep .01 easily takes 2 seconds).
									Pavel
-- 
(english) http://www.livejournal.com/~pavelmachek
(cesky, pictures) http://atrey.karlin.mff.cuni.cz/~pavel/picture/horses/blog.html

Re: nohz and strange sleep latencies

[Pavel Machek]

Hi!

> > > to me this has the feeling of lapic breakage in C2 mode. Does it get any 
> > > better if you boot with 'nolapic'? (but that might in turn turn off 
> > > high-res timers and nohz in essence) Thomas, any ideas?
> > 
> > Hmm, lapic is considered unstable in c2 by default. You have to tell 
> > the kernel that you trust it in C2 on the command line.
> 
> yeah, i was wondering about that too. ACPI enumerated them properly at a 
> certain stage:
> 
>  ACPI: CPU0 (power states: C1[C1] C2[C2] C3[C3])
>  ACPI: CPU1 (power states: C1[C1] C2[C2] C3[C3])
> 
> but perhaps somehow we miss this fact and fail to turn off the lapic 
> clockevents drivers?

Ok, I guess I'm lost. If I offline second CPU, I immediately get
1000Hz timer tick... is that expected?

I'm trying to decide when system is idle (lets say that means "no user
task is scheduled to wakeup within 10 seconds)... I added some
instrumentation to nohz subsystem, but it does not behave like I'd
expect: even if I run "while true; do sleep .01; done" loop, I see
nohz preparing for 5 seconds sleep... while it seems obvious that it
can only be 10msec sleep, and with max_cstate=1, it works that
way... Plus, nte->start_pid seems to contain some random numbers :-(.

What am I doing wrong?

(Patch for illustration, I can generate full diff against vanilla,
but...)
								Pavel

+++ b/kernel/time/tick-sched.c
@@ -229,11 +232,13 @@ void tick_nohz_stop_sched_tick(void)
 		if (delta_jiffies > 1)
 			cpu_set(cpu, nohz_cpu_mask);
 
+		{
+			int user_wait = get_next_timer_interrupt(last_jiffies, 1) - last_jiffies;
+
+			if ((user_wait > HZ/10) && (num_online_cpus() == 1))
+				printk("NOHZ: user ready for %d:%d sec wait (kernel %d:%d sec wait), naughty %d\n", user_wait/HZ, user_wait%HZ, delta_jiffies/HZ, delta_jiffies%HZ, naughty_pid);
+		}
+
 		/*
 		 * nohz_stop_sched_tick can be called several times before
 		 * the nohz_restart_sched_tick is called. This happens when
+++ b/kernel/timer.c
@@ -691,6 +693,12 @@ static unsigned long __next_timer_interr
 			if (tbase_get_deferrable(nte->base))
 				continue;
 
+			if (flags && (nte->start_pid < 1))
+				continue;
+
+			if (flags)
+				naughty_pid = nte->start_pid;
+
 			found = 1;
 			expires = nte->expires;
 			/* Look at the cascade bucket(s)? */



-- 
(english) http://www.livejournal.com/~pavelmachek
(cesky, pictures) http://atrey.karlin.mff.cuni.cz/~pavel/picture/horses/blog.html

Re: nohz and strange sleep latencies

[Thomas Gleixner]

On Thu, 22 Nov 2007, Pavel Machek wrote:
> > but perhaps somehow we miss this fact and fail to turn off the lapic 
> > clockevents drivers?
> 
> Ok, I guess I'm lost. If I offline second CPU, I immediately get
> 1000Hz timer tick... is that expected?

Hmm. No. I have no idea why this is happening.

34196 total events, 55.083 events/sec
echo 0 >/sys/devices/system/cpu/cpu1/online
36073 total events, 54.679 events/sec

> I'm trying to decide when system is idle (lets say that means "no user
> task is scheduled to wakeup within 10 seconds)... I added some
> instrumentation to nohz subsystem, but it does not behave like I'd
> expect: even if I run "while true; do sleep .01; done" loop, I see
> nohz preparing for 5 seconds sleep... while it seems obvious that it
> can only be 10msec sleep, and with max_cstate=1, it works that
> way... Plus, nte->start_pid seems to contain some random numbers :-(.
> 
> What am I doing wrong?
> 
> (Patch for illustration, I can generate full diff against vanilla,
> but...)

Just to make sure what we are hunting: Do you have the same problem
with an non-pavel-tainted 2.6.24-rc3 ?

     tglx

Re: nohz and strange sleep latencies

[Pavel Machek]

Hi!

> > > but perhaps somehow we miss this fact and fail to turn off the lapic 
> > > clockevents drivers?
> > 
> > Ok, I guess I'm lost. If I offline second CPU, I immediately get
> > 1000Hz timer tick... is that expected?
> 
> Hmm. No. I have no idea why this is happening.
> 
> 34196 total events, 55.083 events/sec
> echo 0 >/sys/devices/system/cpu/cpu1/online
> 36073 total events, 54.679 events/sec

Strange.

> > I'm trying to decide when system is idle (lets say that means "no user
> > task is scheduled to wakeup within 10 seconds)... I added some
> > instrumentation to nohz subsystem, but it does not behave like I'd
> > expect: even if I run "while true; do sleep .01; done" loop, I see
> > nohz preparing for 5 seconds sleep... while it seems obvious that it
> > can only be 10msec sleep, and with max_cstate=1, it works that
> > way... Plus, nte->start_pid seems to contain some random numbers :-(.
> > 
> > What am I doing wrong?
> > 
> > (Patch for illustration, I can generate full diff against vanilla,
> > but...)
> 
> Just to make sure what we are hunting: Do you have the same problem
> with an non-pavel-tainted 2.6.24-rc3 ?

The strange sleep latencies were definitely there, I'll check for
"offline cpu and get 1000 interrupts", too.
								Pavel
-- 
(english) http://www.livejournal.com/~pavelmachek
(cesky, pictures) http://atrey.karlin.mff.cuni.cz/~pavel/picture/horses/blog.html

Re: nohz and strange sleep latencies

[Pavel Machek]

On Thu 2007-11-22 21:29:51, Thomas Gleixner wrote:
> On Thu, 22 Nov 2007, Pavel Machek wrote:
> > > but perhaps somehow we miss this fact and fail to turn off the lapic 
> > > clockevents drivers?
> > 
> > Ok, I guess I'm lost. If I offline second CPU, I immediately get
> > 1000Hz timer tick... is that expected?
> 
> Hmm. No. I have no idea why this is happening.
> 
> 34196 total events, 55.083 events/sec
> echo 0 >/sys/devices/system/cpu/cpu1/online
> 36073 total events, 54.679 events/sec

Strange...

> Just to make sure what we are hunting: Do you have the same problem
> with an non-pavel-tainted 2.6.24-rc3 ?

The effect described above disappeared from both clean and
tainted-pavel trees...?

But I have verified again that time sleep 0.01 is perfectly willing to
sleep for 0.9second on untainted 2.6.24-rc3...
									Pavel
-- 
(english) http://www.livejournal.com/~pavelmachek
(cesky, pictures) http://atrey.karlin.mff.cuni.cz/~pavel/picture/horses/blog.html

Re: nohz and strange sleep latencies

[Pavel Machek]

Hi!

> > > but perhaps somehow we miss this fact and fail to turn off the lapic 
> > > clockevents drivers?
> > 
> > Ok, I guess I'm lost. If I offline second CPU, I immediately get
> > 1000Hz timer tick... is that expected?
> 
> Hmm. No. I have no idea why this is happening.
> 
> 34196 total events, 55.083 events/sec
> echo 0 >/sys/devices/system/cpu/cpu1/online
> 36073 total events, 54.679 events/sec

Digging into process_32|64.c...

64:
        while (1) {
                while (!need_resched()) {
                        void (*idle)(void);

                        if (__get_cpu_var(cpu_idle_state))
                                __get_cpu_var(cpu_idle_state) = 0;

                        tick_nohz_stop_sched_tick();

32:
        while (1) {
                tick_nohz_stop_sched_tick();
                while (!need_resched()) {
                        void (*idle)(void);

                        if (__get_cpu_var(cpu_idle_state))
                                __get_cpu_var(cpu_idle_state) = 0;

...eek? Which one is wrong?
								Pavel

-- 
(english) http://www.livejournal.com/~pavelmachek
(cesky, pictures) http://atrey.karlin.mff.cuni.cz/~pavel/picture/horses/blog.html

Re: nohz and strange sleep latencies

[Rafael J. Wysocki]

On Saturday, 24 of November 2007, Pavel Machek wrote:
> Hi!
> 
> > > > but perhaps somehow we miss this fact and fail to turn off the lapic 
> > > > clockevents drivers?
> > > 
> > > Ok, I guess I'm lost. If I offline second CPU, I immediately get
> > > 1000Hz timer tick... is that expected?
> > 
> > Hmm. No. I have no idea why this is happening.
> > 
> > 34196 total events, 55.083 events/sec
> > echo 0 >/sys/devices/system/cpu/cpu1/online
> > 36073 total events, 54.679 events/sec
> 
> Digging into process_32|64.c...
> 
> 64:
>         while (1) {
>                 while (!need_resched()) {
>                         void (*idle)(void);
> 
>                         if (__get_cpu_var(cpu_idle_state))
>                                 __get_cpu_var(cpu_idle_state) = 0;
> 
>                         tick_nohz_stop_sched_tick();
> 
> 32:
>         while (1) {
>                 tick_nohz_stop_sched_tick();
>                 while (!need_resched()) {
>                         void (*idle)(void);
> 
>                         if (__get_cpu_var(cpu_idle_state))
>                                 __get_cpu_var(cpu_idle_state) = 0;
> 
> ...eek? Which one is wrong?

Hm, it looks like you should have quoted more lines ...

In the second case (32), the tick_nohz_stop_sched_tick() seems to be
redundant, so I bet it's this one.

Greetings,
Rafael

Re: nohz and strange sleep latencies

[Rafael J. Wysocki]

On Sunday, 25 of November 2007, Rafael J. Wysocki wrote:
> On Saturday, 24 of November 2007, Pavel Machek wrote:
> > Hi!
> > 
> > > > > but perhaps somehow we miss this fact and fail to turn off the lapic 
> > > > > clockevents drivers?
> > > > 
> > > > Ok, I guess I'm lost. If I offline second CPU, I immediately get
> > > > 1000Hz timer tick... is that expected?
> > > 
> > > Hmm. No. I have no idea why this is happening.
> > > 
> > > 34196 total events, 55.083 events/sec
> > > echo 0 >/sys/devices/system/cpu/cpu1/online
> > > 36073 total events, 54.679 events/sec
> > 
> > Digging into process_32|64.c...
> > 
> > 64:
> >         while (1) {
> >                 while (!need_resched()) {
> >                         void (*idle)(void);
> > 
> >                         if (__get_cpu_var(cpu_idle_state))
> >                                 __get_cpu_var(cpu_idle_state) = 0;
> > 
> >                         tick_nohz_stop_sched_tick();
> > 
> > 32:
> >         while (1) {
> >                 tick_nohz_stop_sched_tick();
> >                 while (!need_resched()) {
> >                         void (*idle)(void);
> > 
> >                         if (__get_cpu_var(cpu_idle_state))
> >                                 __get_cpu_var(cpu_idle_state) = 0;
> > 
> > ...eek? Which one is wrong?
> 
> Hm, it looks like you should have quoted more lines ...
> 
> In the second case (32), the tick_nohz_stop_sched_tick() seems to be
> redundant, so I bet it's this one.

OTOH, the ARM's process.c is more similar to process_32.c ...

[patch] Re: nohz and strange sleep latencies

[Pavel Machek]

Hi!

Okay, so the problem seems to be we are using unreliable lapic
timer... which is stopped in C3 (and in C2 on broken machines).

I do not see any mechanism to disable lapic; there seems to be some
mechanism to work around stopped lapic timer is used (in
acpi/processor_idle.c) but it does not seem to work. So what about
this?

							Pavel
Signed-off-by: Pavel Machek <pavel@suse.cz>

diff --git a/arch/x86/kernel/apic_32.c b/arch/x86/kernel/apic_32.c
index 08b07c1..b9bf79c 100644
--- a/arch/x86/kernel/apic_32.c
+++ b/arch/x86/kernel/apic_32.c
@@ -63,8 +63,8 @@ static int enable_local_apic __initdata 
 static int local_apic_timer_verify_ok;
 /* Disable local APIC timer from the kernel commandline or via dmi quirk
    or using CPU MSR check */
-int local_apic_timer_disabled;
-/* Local APIC timer works in C2 */
+int local_apic_timer_disabled = 1;
+/* Local APIC timer works in C2: used in processor_idle.c  */
 int local_apic_timer_c2_ok;
 EXPORT_SYMBOL_GPL(local_apic_timer_c2_ok);
 

-- 
(english) http://www.livejournal.com/~pavelmachek
(cesky, pictures) http://atrey.karlin.mff.cuni.cz/~pavel/picture/horses/blog.html

Re: [patch] Re: nohz and strange sleep latencies

[Thomas Gleixner]

On Sun, 25 Nov 2007, Pavel Machek wrote:
> Hi!
> 
> Okay, so the problem seems to be we are using unreliable lapic
> timer... which is stopped in C3 (and in C2 on broken machines).
> 
> I do not see any mechanism to disable lapic; there seems to be some
> mechanism to work around stopped lapic timer is used (in
> acpi/processor_idle.c) but it does not seem to work. So what about
> this?

nolapic_timer on 32bit
noapictimer on 64bit 

Sigh, I know that sucks, but it's the history of the diverged trees.

      tglx

Re: nohz and strange sleep latencies

[Thomas Gleixner]

On Sun, 25 Nov 2007, Rafael J. Wysocki wrote:
> > Digging into process_32|64.c...
> > 
> > 64:
> >         while (1) {
> >                 while (!need_resched()) {
> >                         void (*idle)(void);
> > 
> >                         if (__get_cpu_var(cpu_idle_state))
> >                                 __get_cpu_var(cpu_idle_state) = 0;
> > 
> >                         tick_nohz_stop_sched_tick();
> > 
> > 32:
> >         while (1) {
> >                 tick_nohz_stop_sched_tick();
> >                 while (!need_resched()) {
> >                         void (*idle)(void);
> > 
> >                         if (__get_cpu_var(cpu_idle_state))
> >                                 __get_cpu_var(cpu_idle_state) = 0;
> > 
> > ...eek? Which one is wrong?
> 
> Hm, it looks like you should have quoted more lines ...
> 
> In the second case (32), the tick_nohz_stop_sched_tick() seems to be
> redundant, so I bet it's this one.

No. Both are fine. the 64bit version calls into
tick_nohz_stop_sched_tick() way to often. This is a leftover from the
old theory that we can have non-irq caused wakeups. Will fix it.

    tglx

Re: nohz and strange sleep latencies

[Pavel Machek]

Hi!

> > > but perhaps somehow we miss this fact and fail to turn off the lapic 
> > > clockevents drivers?
> > 
> > Ok, I guess I'm lost. If I offline second CPU, I immediately get
> > 1000Hz timer tick... is that expected?
> 
> Hmm. No. I have no idea why this is happening.
> 
> 34196 total events, 55.083 events/sec
> echo 0 >/sys/devices/system/cpu/cpu1/online
> 36073 total events, 54.679 events/sec

It happened again, this time on 2.6.24-pre-rc1 (mostly untainted).
Reboot and problem goes away... so this one is random :-(.

I'll try plug/unplug loops, perhaps that can trigger it reliably. (cpu
replug does not fix it once triggered).
							Pavel
-- 
(english) http://www.livejournal.com/~pavelmachek
(cesky, pictures) http://atrey.karlin.mff.cuni.cz/~pavel/picture/horses/blog.html