2.6.39-rc3 udevadm settle timeout, many hdb events, interrupt storm

2.6.38 is working fine on my PowerBook G4 (powerpc) and has none of the issues described below.

Last week I tried 2.6.39-rc2 and it hung on reboot. Same thing with 2.6.39-rc3 this week.

I've tracked this down to the "udevadm settle" in /etc/init.d/udev (from Debian squeeze).

If I am patient it does timeout after 180 seconds and continues booting. But after booting finishes udev is still chewing CPU cycles and load average is stuck at 1.

After the system is up:

# udevadm monitor
monitor will print the received events for:
UDEV - the event which udev sends out after rule processing
KERNEL - the kernel uevent

KERNEL[1302632376.412055] change   /devices/pci0002:24/0002:24:0d.0/ide0/0.1/block/hdb (block)
KERNEL[1302632376.460742] change   /devices/pci0002:24/0002:24:0d.0/ide0/0.1/block/hdb (block)
UDEV  [1302632376.501101] change   /devices/pci0002:24/0002:24:0d.0/ide0/0.1/block/hdb (block)
KERNEL[1302632376.510745] change   /devices/pci0002:24/0002:24:0d.0/ide0/0.1/block/hdb (block)
KERNEL[1302632376.560742] change   /devices/pci0002:24/0002:24:0d.0/ide0/0.1/block/hdb (block)
UDEV  [1302632376.601155] change   /devices/pci0002:24/0002:24:0d.0/ide0/0.1/block/hdb (block)
KERNEL[1302632376.610755] change   /devices/pci0002:24/0002:24:0d.0/ide0/0.1/block/hdb (block)
KERNEL[1302632376.660744] change   /devices/pci0002:24/0002:24:0d.0/ide0/0.1/block/hdb (block)
UDEV  [1302632376.701186] change   /devices/pci0002:24/0002:24:0d.0/ide0/0.1/block/hdb (block)
KERNEL[1302632376.710751] change   /devices/pci0002:24/0002:24:0d.0/ide0/0.1/block/hdb (block)
KERNEL[1302632376.760727] change   /devices/pci0002:24/0002:24:0d.0/ide0/0.1/block/hdb (block)
UDEV  [1302632376.801135] change   /devices/pci0002:24/0002:24:0d.0/ide0/0.1/block/hdb (block)
KERNEL[1302632376.810753] change   /devices/pci0002:24/0002:24:0d.0/ide0/0.1/block/hdb (block)
KERNEL[1302632376.860748] change   /devices/pci0002:24/0002:24:0d.0/ide0/0.1/block/hdb (block)
UDEV  [1302632376.901068] change   /devices/pci0002:24/0002:24:0d.0/ide0/0.1/block/hdb (block)
KERNEL[1302632376.910748] change   /devices/pci0002:24/0002:24:0d.0/ide0/0.1/block/hdb (block)
KERNEL[1302632376.960746] change   /devices/pci0002:24/0002:24:0d.0/ide0/0.1/block/hdb (block)
UDEV  [1302632377.004023] change   /devices/pci0002:24/0002:24:0d.0/ide0/0.1/block/hdb (block)
KERNEL[1302632377.010786] change   /devices/pci0002:24/0002:24:0d.0/ide0/0.1/block/hdb (block)
KERNEL[1302632377.210681] change   /devices/pci0002:24/0002:24:0d.0/ide0/0.1/block/hdb (block)
KERNEL[1302632377.260749] change   /devices/pci0002:24/0002:24:0d.0/ide0/0.1/block/hdb (block)
UDEV  [1302632377.301096] change   /devices/pci0002:24/0002:24:0d.0/ide0/0.1/block/hdb (block)
KERNEL[1302632377.310749] change   /devices/pci0002:24/0002:24:0d.0/ide0/0.1/block/hdb (block)
KERNEL[1302632377.360749] change   /devices/pci0002:24/0002:24:0d.0/ide0/0.1/block/hdb (block)
UDEV  [1302632377.401136] change   /devices/pci0002:24/0002:24:0d.0/ide0/0.1/block/hdb (block)
KERNEL[1302632377.410753] change   /devices/pci0002:24/0002:24:0d.0/ide0/0.1/block/hdb (block)
KERNEL[1302632377.460748] change   /devices/pci0002:24/0002:24:0d.0/ide0/0.1/block/hdb (block)
UDEV  [1302632377.501264] change   /devices/pci0002:24/0002:24:0d.0/ide0/0.1/block/hdb (block)
KERNEL[1302632377.510749] change   /devices/pci0002:24/0002:24:0d.0/ide0/0.1/block/hdb (block)
KERNEL[1302632377.560730] change   /devices/pci0002:24/0002:24:0d.0/ide0/0.1/block/hdb (block)
UDEV  [1302632377.601147] change   /devices/pci0002:24/0002:24:0d.0/ide0/0.1/block/hdb (block)
KERNEL[1302632377.610793] change   /devices/pci0002:24/0002:24:0d.0/ide0/0.1/block/hdb (block)
^C# 
# 
# 
# dmesg | grep hdb
hdb: MATSHITADVD-R UJ-846, ATAPI CD/DVD-ROM drive
hdb: host max PIO4 wanted PIO255(auto-tune) selected PIO4
hdb: UDMA/66 mode selected
ide-cd: hdb: ATAPI 24X DVD-ROM DVD-R CD-R/RW drive, 2048kB Cache
# 
# dmesg | grep ide
radeonfb: Using Firmware dividers 0x00040089 from PPLL 0
ide-pmac 0002:24:0d.0: enabling device (0000 -> 0002)
ide-pmac: Found Apple UniNorth ATA-6 controller (PCI), bus ID 3, irq 39
Probing IDE interface ide0...
ide0 at 0xf106a000-0xf106a070,0xf106a160 on irq 39
ide-gd driver 1.18
ide-cd driver 5.00
ide-cd: hdb: ATAPI 24X DVD-ROM DVD-R CD-R/RW drive, 2048kB Cache
#

I am getting over 1300 interrupts per second for ide0:

# while grep ide /proc/interrupts && sleep 1 ; do : ; done
 39:     722724   MPIC 1     ide0
 39:     723042   MPIC 1     ide0
 39:     723364   MPIC 1     ide0
 39:     723685   MPIC 1     ide0
 39:     724012   MPIC 1     ide0
 39:     724334   MPIC 1     ide0
 39:     724656   MPIC 1     ide0
 39:     724978   MPIC 1     ide0
 39:     725296   MPIC 1     ide0
 39:     725615   MPIC 1     ide0
 39:     725936   MPIC 1     ide0
 39:     726257   MPIC 1     ide0
 39:     726577   MPIC 1     ide0
 39:     726901   MPIC 1     ide0
 39:     727226   MPIC 1     ide0
 39:     727549   MPIC 1     ide0
 39:     727868   MPIC 1     ide0
 39:     728190   MPIC 1     ide0
 39:     728512   MPIC 1     ide0
 39:     728833   MPIC 1     ide0
 39:     729152   MPIC 1     ide0
 39:     729473   MPIC 1     ide0
 39:     729800   MPIC 1     ide0
 39:     730111   MPIC 1     ide0
 39:     730435   MPIC 1     ide0
 39:     730755   MPIC 1     ide0
 39:     731083   MPIC 1     ide0
 39:     731402   MPIC 1     ide0
 39:     731720   MPIC 1     ide0
 39:     732052   MPIC 1     ide0
 39:     732368   MPIC 1     ide0
 39:     732689   MPIC 1     ide0
 39:     733010   MPIC 1     ide0
^C

I tried using the CDROM drive and it actually does work (as /dev/hdb). So the only real problems are the 180 second hang while booting and the interrupt storm and udev event storm that continues.

Any hints?

-Tim Shepard
[email protected]

Just adding my "me too" with some comments.

I noticed this hang on udevadm settle too. I'm temporarily working around it by adding udevtimeout=5 to the command line. I haven't looked into it any further.

On my system I bisected these constant change notifications to 929e27252e 'ide: ide_requeue_and_plug() reinstate "always plug" behaviour' [1] but haven't looked any past that.

[1] http://lkml.kernel.org/r/[email protected]

On my system, I'm not noticing anything strange here, but I'm not using the CDROM drive:

]# cat /proc/interrupts | grep ide && sleep 3 && cat /proc/interrupts | grep ide

 14:        100      43433        522          0   IO-APIC-edge      ide0
 15:          0          0          0          0   IO-APIC-edge      ide1
 14:        100      43469        522          0   IO-APIC-edge      ide0
 15:          0          0          0          0   IO-APIC-edge      ide1

Cheers,
Shaun

I created a Bugzilla entry at
https://bugzilla.kernel.org/show_bug.cgi?id=33412
for your bug report, please add your address to the CC list in there, thanks!

Maciej Rutecki
http://www.maciek.unixy.pl

I have tried 2.6.39-rc4 and the same problem still exists.

(And the rate of the interrupt storm is over 300 interrupts per
second. I misstated that as over 1300 interrupts per second in my initial report, but the while loop output that I included accurately shows the rate of the interrupt storm.)

-Tim Shepard
[email protected]

I tested 2.6.39-rc5 today and this bug appears to be fixed.... no delay on bootup, "udevadm monitor" shows no spurious events, and monitoring /proc/interrupts I see no ide-related interrupt storm.

I added a comment at https://bugzilla.kernel.org/show_bug.cgi?id=33412
but I could not figure out how to mark this bug closed/fixed, even though I was logged in.

Please mark this bug closed and/or fixed (in 2.6.39-rc5).

-Tim Shepard
[email protected]