2.6.16-rt11: Hires timer makes sleep wait far too long

2.6.16-rt11: Hires timer makes sleep wait far too long

[Jonathan Woithe]

A few days ago I compiled and tested 2.6.16-rt11 on a Pentium3 desktop box
with the high resolution timer feature enabled.  It was set to a frequency
of 1000.  Things appeared to work fine so I tried exactly the same thing
on a 2.0 GHz Centrino-based laptop last night.

Unfortunately the laptop had an issue: whenever the system scripts called
sleep the system would wait for *way* longer than it should have.  Calling
  sleep 1
would give rise to a wait of as much as 45 seconds before the command 
prompt returned.

This was similar to an issue I had earlier (around 2.6.13) which was
associated with the new clock source infrastructure.  However, this time
around the timekeeping (as in the time of day reported by "date") did not
appear to run slow as it did in this previous fault condition.

I tested the situation under the four clock sources reported to be available
in /sys/devices/system/clocksource/clocksource0/:

  pit, jiffies, acpi_pm (the default), tsc

The actual amount of time waited by a "sleep 1" call from bash was tested
at least twice for each timer source:

  pit: 12 seconds, 29 seconds, 28 seconds
  tsc: 45 seconds, 45 seconds
  acpi_pm: 45 seconds, 29 seconds
  jiffies: 45 seconds, 32 seconds

I then rebuilt the 2.6.16-rt11 kernel without the HR-timers option selected.
After rebooting, running sleep worked exactly as expected.

I'm more than happy to run additional tests to try to narrow down the
problem.

Regards
  jonathan

Re: 2.6.16-rt11: Hires timer makes sleep wait far too long

[Thomas Gleixner]

On Tue, 2006-04-04 at 13:10 +0930, Jonathan Woithe wrote:
> The actual amount of time waited by a "sleep 1" call from bash was tested
> at least twice for each timer source:
> 
>   pit: 12 seconds, 29 seconds, 28 seconds
>   tsc: 45 seconds, 45 seconds
>   acpi_pm: 45 seconds, 29 seconds
>   jiffies: 45 seconds, 32 seconds

Hmm, can you please send me your .config and the bootlog of the
machine ?

	tglx

Re: 2.6.16-rt11: Hires timer makes sleep wait far too long

[Jonathan Woithe]

Thomas

> On Tue, 2006-04-04 at 13:10 +0930, Jonathan Woithe wrote:
> > The actual amount of time waited by a "sleep 1" call from bash was tested
> > at least twice for each timer source:
> > 
> >   pit: 12 seconds, 29 seconds, 28 seconds
> >   tsc: 45 seconds, 45 seconds
> >   acpi_pm: 45 seconds, 29 seconds
> >   jiffies: 45 seconds, 32 seconds
> 
> Hmm, can you please send me your .config and the bootlog of the
> machine ?

Because of the size of the files I've posted this privately.  The following
are extracts from the files in case others are interested.

Selected boot messages with hr-timers enabled:
  ACPI: PM-Timer IO Port: 0x1008
  ACPI: Local APIC address 0xfee00000
  ACPI: LAPIC (acpi_id[0x00] lapic_id[0x00] enabled)
  Processor #0 6:13 APIC version 20
  :
  Detected 1995.072 MHz processor.
  Real-Time Preemption Support (C) 2004-2006 Ingo Molnar
  :
  CPU: Intel(R) Pentium(R) M processor 2.00GHz stepping 08
  :
  ENABLING IO-APIC IRQs
  ..TIMER: vector=0x31 apic1=0 pin1=2 apic2=-1 pin2=-1
  Event source pit new caps set: 05
  Event source lapic installed with caps set: 02
  :
  Time: tsc clocksource has been installed.
  hrtimers: Switched to high resolution mode CPU 0
  :
  Time: acpi_pm clocksource has been installed.
  hrtimers: Switched to high resolution mode CPU 0

Config options related to timers:
  CONFIG_HPET_TIMER=y
  CONFIG_HPET_EMULATE_RTC=y
  CONFIG_HIGH_RES_TIMERS=y
  CONFIG_HIGH_RES_RESOLUTION=10000
  :
  CONFIG_X86_PM_TIMER=y

Regards
  jonathan

Re: 2.6.16-rt11: Hires timer makes sleep wait far too long

[Thomas Gleixner]

Jonathan,

On Wed, 2006-04-05 at 09:51 +0930, Jonathan Woithe wrote:
>   ENABLING IO-APIC IRQs
>   ..TIMER: vector=0x31 apic1=0 pin1=2 apic2=-1 pin2=-1
>   Event source pit new caps set: 05
>   Event source lapic installed with caps set: 02
>   :
>   Time: tsc clocksource has been installed.
>   hrtimers: Switched to high resolution mode CPU 0
>   :
>   Time: acpi_pm clocksource has been installed.
>   hrtimers: Switched to high resolution mode CPU 0

Nothing wrong so far. I have to find a test box with pm timer to get
some more info.

	tglx

Re: 2.6.16-rt11: Hires timer makes sleep wait far too long

[Jonathan Woithe]

Thomas

> On Wed, 2006-04-05 at 09:51 +0930, Jonathan Woithe wrote:
> >   ENABLING IO-APIC IRQs
> >   ..TIMER: vector=0x31 apic1=0 pin1=2 apic2=-1 pin2=-1
> >   Event source pit new caps set: 05
> >   Event source lapic installed with caps set: 02
> >   :
> >   Time: tsc clocksource has been installed.
> >   hrtimers: Switched to high resolution mode CPU 0
> >   :
> >   Time: acpi_pm clocksource has been installed.
> >   hrtimers: Switched to high resolution mode CPU 0
> 
> Nothing wrong so far. I have to find a test box with pm timer to get
> some more info.

Note that the fault condition persisted no matter which clocksource was
in use: I tried all four (tsc, pm_timer, jiffies, pit) and they all resulted
in "sleep 1" lasting far longer than 1 second.

Feel free to email if I can be of further assistance.  In the meantime I'll
try 2.6.16-rt12 over the weekend to see if the situation is any different.

Regards
  jonathan

Re: 2.6.16-rt11: Hires timer makes sleep wait far too long

[Jonathan Woithe]

Thomas

> On Wed, 2006-04-05 at 09:51 +0930, Jonathan Woithe wrote:
> >   ENABLING IO-APIC IRQs
> >   ..TIMER: vector=0x31 apic1=0 pin1=2 apic2=-1 pin2=-1
> >   Event source pit new caps set: 05
> >   Event source lapic installed with caps set: 02
> >   :
> >   Time: tsc clocksource has been installed.
> >   hrtimers: Switched to high resolution mode CPU 0
> >   :
> >   Time: acpi_pm clocksource has been installed.
> >   hrtimers: Switched to high resolution mode CPU 0
> 
> Nothing wrong so far. I have to find a test box with pm timer to get
> some more info.

FYI, the same problem occurs in 2.6.16-rt12.  I note that rt14 is out now
so I'll give that a go overnight and let you know the results.

One final observation I did make under 2.6.16-rt12: in the first 30 seconds
or there abouts after the boot, "sleep 1" did result in short sleeps - they
weren't always 1 second, but they were in the ballpark.  After the machine
had been up for 30-60 seconds however, "sleep 1" would produce waits along
the lines of what I reported in the initial report - anywhere between 20
seconds to 45 seconds and more.  There didn't seem to be any gradual
increase either - the "sleep 1" wait times seemed to jump from 1-2 seconds
up to 20-30 seconds very suddenly.

Regards
  jonathan