2011-04-12 19:38:05

by Tim Shepard

[permalink] [raw]
Subject: 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]


2011-04-12 23:22:44

by Shaun Ruffell

[permalink] [raw]
Subject: Re: 2.6.39-rc3 udevadm settle timeout, many hdb events, interrupt storm

Just adding my "me too" with some comments.

On 04/12/2011 02:14 PM, Tim Shepard wrote:
> 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).

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.

> # 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)

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]

> I am getting over 1300 interrupts per second for ide0:

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

2011-04-17 17:12:57

by Maciej Rutecki

[permalink] [raw]
Subject: Re: 2.6.39-rc3 udevadm settle timeout, many hdb events, interrupt storm

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!

On wtorek, 12 kwietnia 2011 o 21:14:35 Tim Shepard wrote:
> 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]
> --
> To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
> the body of a message to [email protected]
> More majordomo info at http://vger.kernel.org/majordomo-info.html
> Please read the FAQ at http://www.tux.org/lkml/

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

2011-04-19 18:01:24

by Tim Shepard

[permalink] [raw]
Subject: Re: 2.6.39-rc3 udevadm settle timeout, many hdb events, interrupt storm




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]

2011-04-27 21:28:53

by Tim Shepard

[permalink] [raw]
Subject: Re: 2.6.39-rc3 udevadm settle timeout, many hdb events, interrupt storm



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]