Timer interrupt stops, causes soft lockup

Timer interrupt stops, causes soft lockup

[Joel K. Greene]

Hello,

We have been seeing a condition where wall time gets stuck in a 4-second
loop:
        lab-m500-5:~ # date
        Thu Mar 13 17:54:48 EDT 2008
        lab-m500-5:~ # date
        Thu Mar 13 17:54:49 EDT 2008
        lab-m500-5:~ # date
        Thu Mar 13 17:54:49 EDT 2008
        lab-m500-5:~ # date
        Thu Mar 13 17:54:45 EDT 2008
        lab-m500-5:~ # date
        Thu Mar 13 17:54:46 EDT 2008
        lab-m500-5:~ # date
        Thu Mar 13 17:54:46 EDT 2008
        lab-m500-5:~ # date
        Thu Mar 13 17:54:47 EDT 2008

Of course when time stops progessing forward at a steady pace all
sorts of Bad Things happen.  

The clock loop is caused by jiffies not incrementing. It seems that wall
time updates itself and then resync's with jiffies every ~4s.

We verified that all spinlocks ( xtime_lock in particular ) were not
being held, and that the kernel had no reason not to update jiffies.
Other interrupts continue to fire, so we're not stuck in the timer
handler.

So, we went on to look at the PIC. We threw together a little kernel
module to get some debug info.

What we found is that when the time loop occurs, the PIC registers look
like this:

                ... PIC  IMR: ff00
                ... PIC  IRR: 0001
                ... PIC  ISR: 0001
                ... PIC ELCR: 0e00
                

When running correctly these registers look like:

                        ... PIC  IMR: fffa
                        ... PIC  IRR: 0000
                        ... PIC  ISR: 0000
                        ... PIC ELCR: 0ea0
        
        
The Interrupt Mask Register masks off the corresponding interrupts,
preventing the CPU from getting these. In the bad state, all interrupts
have been enabled. This is wrong, but does not seem to contribute to the
problem directly. I do not believe that INT2, INT4-INT7 are connected to
anything in our system.  But the register is getting stomped, and we
have no idea how.

The Interrupt Request Register shows that the PIC has received an
interrupt request from the hardware - the timer, in our case. However,
this is a problem here because the timer interrupt is edge-triggered. As
we understand it, the IRR bit should never get set for an edge-triggered
interrupt.

The In Service Register indicates which interrupt the PIC thinks the CPU
is processing at the time. This bit staying set indicates that the PIC
thinks that the CPU is in the timer interrupt handler. This is what is
preventing the PIC from interrupting the CPU again. Presumably, the PIC
missed the End of Interrupt cycle for the last timer interrupt. We are
about 90% certain that the PIC is configured in Auto-EOI mode.

We have found that calling the kernel functions mask_and_ack_8259A and
init_8259A will clear the ISR bit and allow the timer interrupt, and
therefore the system, to go back to functioning normally. ( As far as we
can tell ) When we do this, the registers show:

        ... PIC  IMR: ff00
        ... PIC  IRR: 0001
        ... PIC  ISR: 0000
        ... PIC ELCR: 0ea0
        
IMR,IRR, and ELCR are not corrected, but do not see to affect system
operation
- as far as we can tell. We are not comfortable enough to declare the
system "stable" after this recovery, but have not found anything that
doesn't work.

So- 
We have no idea what is getting us into this state other than the vague
impression that it is caused by hardware delays. HZ=1000 seems to
aggragate it, even without our cPCI cards or SW in the system. Others
seem to have had verious hardware failures, including faulty DIMMs lead
to this. It _seems_ to be a race aggravated by hardware delays.

We originally saw this on the SLED10 kernel - SuSE's version of
2.6.16.21 - where the issue would occur in a matter of weeks or months.
We have been working with Novell, and have duplicate it on SuSE's
updated kernels 2.6.16.46 and 2.6.16.54. Yesterday I pulled down
2.6.16.60 from kernel.org and built that kernel with HZ=1000 and
reproduced the problem in about 7 hours. We are testing with HZ=100, but
have no conclusive data yet.  We have run the same systems on SuSE 9.2
( 2.6.8 ) with no known occurances. We have no confirmed sightings on
several other platforms running the same SLED10 and very similar
applications. 

We have over 10 systems demonstrating the problem, many in customer
sites. 

We have disabled irg balancer, and determined that is not a cause.
Binding all interrupts to CPU0 does seem to make the problem happen
faster, but staticaly distributing them does not prevent.

We have a 2.6.16.54-0.2.5-smp running HZ=100 that we are monitoring SMI
on to see if perhaps SMM is biting us, but have no data yet. 

This is running on a Kontron DT-64:
http://us.kontron.com/index.php?id=226&cat=480&productid=103
It's a dual P3 with a ServerWorks chipset. The PIC is implemented in a
CSB5 v2.1, rev 0x11.


Per suggetions in the lkml FAQ, I'm not posting .config and lots of
other stuff ( first time caller...). I can provide anything on
request... The only change I have made from the SLED10
config-2.6.16.21-0.8-smp is CONFIG_HZ_1000=y.

Please cc: me on any replies.

Any advice appreciated!!!

Thanks,
Joel.






Devices:
lab-m500-5:~ # lspci
00:00.0 Host bridge: Broadcom CNB20LE Host Bridge (rev 06)
00:00.1 Host bridge: Broadcom CNB20LE Host Bridge (rev 06)
00:03.0 VGA compatible controller: Chips and Technologies F69000
HiQVideo (rev 64)
00:0f.0 Host bridge: Broadcom CSB5 South Bridge (rev 93)
00:0f.1 IDE interface: Broadcom CSB5 IDE Controller (rev 93)
00:0f.2 USB Controller: Broadcom OSB4/CSB5 OHCI USB Controller (rev 05)
00:0f.3 ISA bridge: Broadcom CSB5 LPC bridge
01:02.0 Ethernet controller: Intel Corporation 82544EI Gigabit Ethernet
Controller (Copper) (rev 02)
01:03.0 Ethernet controller: Intel Corporation 82544EI Gigabit Ethernet
Controller (Copper) (rev 02)
01:05.0 PCI bridge: Hint Corp HB6 Universal PCI-PCI bridge (transparent
mode) (rev 04)
02:0f.0 PCI bridge: Intel Corporation 21154 PCI-to-PCI Bridge
03:0d.0 PCI bridge: Intel Corporation 21154 PCI-to-PCI Bridge
03:0e.0 PCI bridge: Intel Corporation 21154 PCI-to-PCI Bridge
03:0f.0 PCI bridge: Intel Corporation 21154 PCI-to-PCI Bridge
        


EXCERPTS from boot.msg:

<5>Linux version 2.6.16.60-smp (root@linuxdt036) (gcc version 4.1.2 20070115 (prerelease) (SUSE Linux)) #1 SMP Thu Mar 13 11:08:55 EDT 2008
<6>BIOS-provided physical RAM map:
<4> BIOS-e820: 0000000000000000 - 000000000009e800 (usable)
<4> BIOS-e820: 000000000009e800 - 00000000000a0000 (reserved)
<4> BIOS-e820: 00000000000e0000 - 0000000000100000 (reserved)
<4> BIOS-e820: 0000000000100000 - 0000000040000000 (usable)
<4> BIOS-e820: 00000000fec00000 - 00000000fec10000 (reserved)
<4> BIOS-e820: 00000000fee00000 - 00000000fee01000 (reserved)
<4> BIOS-e820: 00000000fff80000 - 0000000100000000 (reserved)
<5>824MB HIGHMEM available.
<5>200MB LOWMEM available.
<6>found SMP MP-table at 000f7860
<7>On node 0 totalpages: 262144
<7>  DMA zone: 4096 pages, LIFO batch:0
<7>  DMA32 zone: 0 pages, LIFO batch:0
<7>  Normal zone: 47104 pages, LIFO batch:15
<7>  HighMem zone: 210944 pages, LIFO batch:31
<6>DMI present.
<6>Using APIC driver default
<3>ACPI: Unable to locate RSDP
<6>Intel MultiProcessor Specification v1.4
<6>    Virtual Wire compatibility mode.
<6>OEM ID: RCC      Product ID: LE30 SERVER APIC at: 0xFEE00000
<4>Processor #3 6:11 APIC version 17
<4>Processor #0 6:11 APIC version 17
<6>I/O APIC #1 Version 17 at 0xFEC00000.
<6>I/O APIC #2 Version 17 at 0xFEC01000.
<6>I/O APIC #4 Version 17 at 0xFEC02000.
<6>I/O APIC #5 Version 17 at 0xFEC03000.
<4>Enabling APIC mode:  Flat.  Using 4 I/O APICs
<6>Processors: 2
<4>Allocating PCI resources starting at 50000000 (gap: 40000000:bec00000)
<4>Built 1 zonelists
<5>Kernel command line: root=/dev/hda6 vga=0x314  splash=verbose  catt_mach=m500-1 vmalloc=824M
<7>mapped APIC to ffffd000 (fee00000)
<7>mapped IOAPIC to ffffc000 (fec00000)
<7>mapped IOAPIC to ffffb000 (fec01000)
<7>mapped IOAPIC to ffffa000 (fec02000)
<7>mapped IOAPIC to ffff9000 (fec03000)
<6>Enabling fast FPU save and restore... done.
<6>Enabling unmasked SIMD FPU exception support... done.
<6>Initializing CPU#0
<4>PID hash table entries: 1024 (order: 10, 16384 bytes)
<4>Detected 931.108 MHz processor.
<6>Using tsc for high-res timesource
<4>Dentry cache hash table entries: 32768 (order: 5, 131072 bytes)
<4>Inode-cache hash table entries: 16384 (order: 4, 65536 bytes)
<6>Memory: 1032764k/1048576k available (1562k kernel code, 14640k reserved, 655k data, 192k init, 843776k highmem)
<4>Checking if this processor honours the WP bit even in supervisor mode... Ok.
<4>Calibrating delay using timer specific routine.. 1863.47 BogoMIPS (lpj=931736)
<6>Security Framework v1.0.0 initialized
<4>Mount-cache hash table entries: 512
<7>CPU: After generic identify, caps: 0383fbff 00000000 00000000 00000000 00000000 00000000 00000000
<7>CPU: After vendor identify, caps: 0383fbff 00000000 00000000 00000000 00000000 00000000 00000000
<6>CPU: L1 I cache: 16K, L1 D cache: 16K
<6>CPU: L2 cache: 512K
<7>CPU: After all inits, caps: 0383fbff 00000000 00000000 00000040 00000000 00000000 00000000
<6>Intel machine check architecture supported.
<6>Intel machine check reporting enabled on CPU#0.
<6>Checking 'hlt' instruction... OK.
<4>CPU0: Intel(R) Pentium(R) III CPU - S          933MHz stepping 04
<4>Booting processor 1/0 eip 3000
<6>Initializing CPU#1
<4>Calibrating delay using timer specific routine.. 1861.64 BogoMIPS (lpj=930820)
<7>CPU: After generic identify, caps: 0383fbff 00000000 00000000 00000000 00000000 00000000 00000000
<7>CPU: After vendor identify, caps: 0383fbff 00000000 00000000 00000000 00000000 00000000 00000000
<6>CPU: L1 I cache: 16K, L1 D cache: 16K
<6>CPU: L2 cache: 512K
<7>CPU: After all inits, caps: 0383fbff 00000000 00000000 00000040 00000000 00000000 00000000
<6>Intel machine check architecture supported.
<6>Intel machine check reporting enabled on CPU#1.
<4>CPU1: Intel(R) Pentium(R) III CPU - S          933MHz stepping 04
<6>Total of 2 processors activated (3725.11 BogoMIPS).
<4>ExtINT not setup in hardware but reported by MP table
<4>ENABLING IO-APIC IRQs
<6>..TIMER: vector=0x31 apic1=0 pin1=2 apic2=0 pin2=0
<3>..MP-BIOS bug: 8254 timer not connected to IO-APIC
<6>...trying to set up timer (IRQ0) through the 8259A ...
<4>..... (found pin 0) ...works.
<6>checking TSC synchronization across 2 CPUs: passed.
<6>Brought up 2 CPUs
<4>migration_cost=2082
<6>PCI: PCI BIOS revision 2.10 entry at 0xfda21, last bus=6
<6>PCI: Using configuration type 1
<6>ACPI: Subsystem revision 20060127
<6>ACPI: Interpreter disabled.
<6>SvrWks CSB5: IDE controller at PCI slot 0000:00:0f.1
<6>SvrWks CSB5: chipset revision 147
<6>SvrWks CSB5: not 100% native mode: will probe irqs later
<6>piix4_smbus 0000:00:0f.0: Found 0000:00:0f.0 device
<6>piix4_smbus 0000:00:0f.0: Unusual config register value
<6>piix4_smbus 0000:00:0f.0: Try using fix_hstcfg=1 if you experience problems
<3>piix4_smbus 0000:00:0f.0: Illegal Interrupt configuration (or code out of date)!

Re: Timer interrupt stops, causes soft lockup

[Arjan van de Ven]

On Fri, 14 Mar 2008 11:53:29 -0400
"Joel K. Greene" <joel.greene@catapult.com> wrote:

> We originally saw this on the SLED10 kernel - SuSE's version of
> 2.6.16.21 - where the issue would occur in a matter of weeks or
> months.

Hi,

this is roughly a 3 year old kernel; and the thing is, this code has been
revamped entirely several times since then. Do you see this behavior with,
say the 2.6.24 kernel? That's a twofold question, since it has with-tickless 
and without-tickless as option. (tickless doesn't tend to use the PIT at all
so would just avoid the entire issue; without-tickless still uses the PIT)

It's really better to use your support contract with Novell to get them to fix
it for SLE(S/D)10 if you are not in a position to test or diagnose with new
kernels; they're there to support you for their old kernel. In general, the folks
on this list are working on current kernels and don't tend to spend time working
on such old kernels. The probability of this bug being fixed since then, or the fix
being totally not applicable to current kernels, is quite high (given the several rewrites
of the timer code) so it'd be a waste of the time of the people on this list.

Now, if you can see the behavior on 2.6.24 (or better, the latest 2.6.25-rc), then
suddenly you'll find a lot more people who're going to be interested....


-- 
If you want to reach me at my work email, use arjan@linux.intel.com
For development, discussion and tips for power savings, 
visit http://www.lesswatts.org

Re: Timer interrupt stops, causes soft lockup

[Joel K. Greene]

Hi Arjan,

Thanks for your response. 

Sorry for the long post, I think the issue required a lot of detail. I'm
sure that it was easy to overlook that this is still an issue in a 6
week old kernel:
>  Yesterday I pulled down 2.6.16.60 from kernel.org and built that
> kernel with HZ=1000 and reproduced the problem in about 7 hours.

It looks like from http://www.kernel.org/pub/linux/kernel/v2.6/ that .16
is the longest-running subversion and is still being maintained. Is
there a better list for 2.6.16 issues?

I am testing 2.6.24.3 now. I am not going tickless. I am not using PIT
with any of the kernels I am testing.



Thanks,
Joel.

Re: Timer interrupt stops, causes soft lockup

[Arjan van de Ven]

On Fri, 14 Mar 2008 13:21:22 -0400
"Joel K. Greene" <joel.greene@catapult.com> wrote:

> Hi Arjan,
> 
> Thanks for your response. 
> 
> Sorry for the long post, I think the issue required a lot of detail.
> I'm sure that it was easy to overlook that this is still an issue in
> a 6 week old kernel:
> >  Yesterday I pulled down 2.6.16.60 from kernel.org and built that
> > kernel with HZ=1000 and reproduced the problem in about 7 hours.

I did see that, doesn't mean it's not 3 years old...




-- 
If you want to reach me at my work email, use arjan@linux.intel.com
For development, discussion and tips for power savings, 
visit http://www.lesswatts.org

Re: Timer interrupt stops, causes soft lockup

[Pavel Machek]

Hi!

> Of course when time stops progessing forward at a steady pace all
> sorts of Bad Things happen.  
> 
> The clock loop is caused by jiffies not incrementing. It seems that wall
> time updates itself and then resync's with jiffies every ~4s.
> 
> We verified that all spinlocks ( xtime_lock in particular ) were not
> being held, and that the kernel had no reason not to update jiffies.
> Other interrupts continue to fire, so we're not stuck in the timer
> handler.
> 
> So, we went on to look at the PIC. We threw together a little kernel
> module to get some debug info.

Nice debugging.

> We have over 10 systems demonstrating the problem, many in customer
> sites. 

Does nosmp help?

Does noapic/nolapic help?

You may want to try testing with HZ=4000... to show the problem
faster.
							Pavel
-- 
(english) http://www.livejournal.com/~pavelmachek
(cesky, pictures) http://atrey.karlin.mff.cuni.cz/~pavel/picture/horses/blog.html

Re: Timer interrupt stops, causes soft lockup

[Joel K. Greene]

Hi Pavel,


> Does nosmp help?
We have not tried. I would expect that it would, but I think that's
changing the system too much, and we cannot do that in production. As we
have seen system run for a couple of months without demonstrating the
issue I think that proving the negative is very difficult. I am focusing
on trying to force the issue so we can gather information.
> 
> Does noapic/nolapic help?
These do not affect the problem.


Thanks!

Joel.