Bug 597232

what is the output of "lspci" ?

do you see more messages regarding modprobe?

most likely a video kernel driver problem

Created attachment 417642 [details]
lspci from t400

!!! booted with blacklisted snd-hda-intel

Some useful info from mentioned T400

lkocman@ThinkPad T400$ rpm -qa | grep kernel
kernel-firmware-2.6.32-30.el6.noarch
kernel-devel-2.6.32-28.el6.x86_64
kernel-headers-2.6.32-30.el6.x86_64
kernel-2.6.32-27.el6.x86_64
abrt-addon-kerneloops-1.1.4-1.el6.x86_64
kernel-devel-2.6.32-27.el6.x86_64
kernel-devel-2.6.32-30.el6.x86_64
kernel-2.6.32-28.el6.x86_64
dracut-kernel-004-19.el6.noarch
kernel-2.6.32-30.el6.x86_64

All older present kernels suffer from the same issue ...
I'd like to mention again that the issue started today after yum update

============================================================================
modprobe snd-hda-intel hangs (following output is during modprobe)
============================================================================
lkocman@ThinkPad T400$ ps ax | grep insmod | grep -v grep
lkocman@ThinkPad T400$ 

lkocman@ThinkPad T400$ ps ax | grep modprobe | grep -v grep
8753 pts/1    D+     0:00 modprobe snd_hda_intel
8761 ?        S      0:07 /sbin/modprobe -q -- snd_hda_codec_id:14f15051

lkocman@ThinkPad T400$ sudo tail -30  /var/log/messages
May 28 16:50:46 dhcp-29-7 udevd[499]: seq 1913 queued, 'add' 'module'
May 28 16:50:46 dhcp-29-7 udevd[499]: passed 135 bytes to monitor 0x14859f0
May 28 16:50:46 dhcp-29-7 udevd-work[8181]: seq 1913 running
May 28 16:50:46 dhcp-29-7 udevd-work[8181]: RUN 'socket:@/org/freedesktop/hal/udev_event' /etc/udev/rules.d/90-hal.rules:2
May 28 16:50:46 dhcp-29-7 udevd-work[8181]: passed 125 bytes to monitor 0x14859f0
May 28 16:50:46 dhcp-29-7 udevd-work[8181]: passed -1 bytes to monitor 0x14c6780
May 28 16:50:46 dhcp-29-7 udevd-work[8181]: seq 1913 processed with 0
May 28 16:50:46 dhcp-29-7 udevd[499]: seq 1913 done with 0
May 28 16:50:46 dhcp-29-7 udevd-work[8177]: 'udev-acl --action=add --device=/dev/snd/seq' returned with exitcode 0
May 28 16:50:46 dhcp-29-7 udevd-work[8177]: passed 219 bytes to monitor 0x1646ec0
May 28 16:50:46 dhcp-29-7 udevd-work[8177]: passed -1 bytes to monitor 0x14c6430
May 28 16:50:46 dhcp-29-7 udevd-work[8177]: seq 1912 processed with 0
May 28 16:50:46 dhcp-29-7 udevd[499]: seq 1912 done with 0
May 28 16:50:46 dhcp-29-7 udevd[499]: seq 1914 queued, 'add' 'module'
May 28 16:50:46 dhcp-29-7 udevd[499]: passed 139 bytes to monitor 0x14859f0
May 28 16:50:46 dhcp-29-7 udevd-work[8177]: seq 1914 running
May 28 16:50:46 dhcp-29-7 udevd-work[8177]: RUN 'socket:@/org/freedesktop/hal/udev_event' /etc/udev/rules.d/90-hal.rules:2
May 28 16:50:46 dhcp-29-7 udevd-work[8177]: passed 133 bytes to monitor 0x1646ec0
May 28 16:50:46 dhcp-29-7 udevd-work[8177]: passed -1 bytes to monitor 0x14c6430
May 28 16:50:46 dhcp-29-7 udevd-work[8177]: seq 1914 processed with 0
May 28 16:50:46 dhcp-29-7 udevd[499]: seq 1914 done with 0
May 28 16:50:46 dhcp-29-7 udevd[499]: seq 1915 queued, 'add' 'module'
May 28 16:50:46 dhcp-29-7 udevd[499]: passed 139 bytes to monitor 0x14859f0
May 28 16:50:46 dhcp-29-7 udevd-work[8177]: seq 1915 running
May 28 16:50:46 dhcp-29-7 udevd-work[8177]: RUN 'socket:@/org/freedesktop/hal/udev_event' /etc/udev/rules.d/90-hal.rules:2
May 28 16:50:46 dhcp-29-7 udevd-work[8177]: passed 133 bytes to monitor 0x1646ec0
May 28 16:50:46 dhcp-29-7 udevd-work[8177]: passed -1 bytes to monitor 0x14c6430
May 28 16:50:46 dhcp-29-7 udevd-work[8177]: seq 1915 processed with 0
May 28 16:50:46 dhcp-29-7 udevd[499]: seq 1915 done with 0
May 28 16:50:46 dhcp-29-7 kernel: HDA Intel 0000:00:1b.0: PCI INT B -> GSI 17 (level, low) -> IRQ 17

See the same problem on Thinkpad T510. Was able to boot with the following added to /etc/modprobe.d/blacklist.conf:

blacklist snd-hda-intel

See the following output from dmesg after a "modprobe snd_hda_intel":


HDA Intel 0000:00:1b.0: PCI INT B -> GSI 17 (level, low) -> IRQ 17
  alloc irq_desc for 35 on node -1
  alloc kstat_irqs on node -1
HDA Intel 0000:00:1b.0: irq 35 for MSI/MSI-X
HDA Intel 0000:00:1b.0: setting latency timer to 64
INFO: task modprobe:10600 blocked for more than 120 seconds.
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
modprobe      D ffff880137c23280     0 10600  10580 0x00000084
 ffff88010d085988 0000000000000086 0000000000000000 ffff880028396840
 ffff88010d085908 ffffffff8104e5dc ffff88010d085928 000000010012791a
 ffff8800a1a866b0 ffff88010d085fd8 00000000000103b8 ffff8800a1a866b0
Call Trace:
 [<ffffffff8104e5dc>] ? enqueue_task+0x5c/0x70
 [<ffffffff814d4af5>] schedule_timeout+0x225/0x2f0
 [<ffffffff8108ff96>] ? autoremove_wake_function+0x16/0x40
 [<ffffffff8104efa9>] ? __wake_up_common+0x59/0x90
 [<ffffffff8101aea6>] ? native_read_tsc+0x6/0x20
 [<ffffffff814d474d>] wait_for_common+0x11d/0x190
 [<ffffffff8105b980>] ? default_wake_function+0x0/0x20
 [<ffffffff8108af31>] ? __queue_work+0x41/0x50
 [<ffffffff814d487d>] wait_for_completion+0x1d/0x20
 [<ffffffff810894b6>] call_usermodehelper_exec+0xf6/0x120
 [<ffffffffa06880c3>] ? snd_hda_codec_configure+0x2c3/0x4f0 [snd_hda_codec]
 [<ffffffff8108966b>] __request_module+0x18b/0x210
 [<ffffffff8125a164>] ? snprintf+0x34/0x40
 [<ffffffffa06880c3>] snd_hda_codec_configure+0x2c3/0x4f0 [snd_hda_codec]
 [<ffffffffa03811a0>] ? azx_send_cmd+0x0/0x1c0 [snd_hda_intel]
 [<ffffffffa0380ef0>] ? azx_get_response+0x0/0x2b0 [snd_hda_intel]
 [<ffffffffa0370039>] ? crypt_resume+0x9/0x20 [dm_crypt]
 [<ffffffffa03820ba>] azx_probe+0x881/0x985 [snd_hda_intel]
 [<ffffffff8126d8a7>] local_pci_probe+0x17/0x20
 [<ffffffff8126ea71>] pci_device_probe+0x101/0x120
 [<ffffffff8132dc52>] ? driver_sysfs_add+0x62/0x90
 [<ffffffff8132ddf0>] driver_probe_device+0xa0/0x2a0
 [<ffffffff8132e09b>] __driver_attach+0xab/0xb0
 [<ffffffff8132dff0>] ? __driver_attach+0x0/0xb0
 [<ffffffff8132d064>] bus_for_each_dev+0x64/0x90
 [<ffffffff8132db8e>] driver_attach+0x1e/0x20
 [<ffffffff8132d4a0>] bus_add_driver+0x200/0x300
 [<ffffffff812524d8>] ? kset_find_obj+0x38/0x80
 [<ffffffff8132e3c6>] driver_register+0x76/0x140
 [<ffffffff814d9345>] ? notifier_call_chain+0x55/0x80
 [<ffffffff8126ecc6>] __pci_register_driver+0x56/0xd0
 [<ffffffff810953a5>] ? __blocking_notifier_call_chain+0x65/0x80
 [<ffffffffa0280000>] ? alsa_card_azx_init+0x0/0x20 [snd_hda_intel]
 [<ffffffffa028001e>] alsa_card_azx_init+0x1e/0x20 [snd_hda_intel]
 [<ffffffff8100a04c>] do_one_initcall+0x3c/0x1d0
 [<ffffffff810adfdf>] sys_init_module+0xdf/0x250
 [<ffffffff81013172>] system_call_fastpath+0x16/0x1b

This is not fixed by using older kernels, however downgrading module-init-tools to 3.9-10.el6 does fix this, so moving over to m-i-t.

Note that after I performed the workaround in comment 7, I still had no network.  I undid that change and reverted to module-init-tools-3.9-10.el6.x86_64 which solved both problems.

*** Bug 598040 has been marked as a duplicate of this bug. ***

Also faced this problem this morning with lenovo T500. Added to /etc/modprobe.d/blacklist.conf:

blacklist snd-hda-intel    

But still udev start more slowly than it did before..

Good battle this morning ;-)

*** Bug 598108 has been marked as a duplicate of this bug. ***

Hitting this too. Lenovo T61 Intel.

blacklist snd-hda-intel works for me... but not ideal obviously.

This bug is caused by the implementation of the fix to 515413. That bug implements an elaborate mechanism in modprobe to run only one modprobe instance at a time, which does handle direct child dependences, but does not handle indirect ones by means of a synchronous call into the kernel. It is possible to have modprobe also exclude calls made directly from u_m_h (the kernel helper) but this gets a lot more complex than just doing the one-at-a-time solution in udev.

So, the fix for 515413 is being reverted, we're going with the udev option, and not until after the beta refresh at this point. Sorry for any inconvenience.

Jon.