alsactl hangs system during boot-up

[Simon Hirscher]

Binary package hint: alsa-utils

Hey there,

for two weeks* already my system almost always hangs for some minutes when booting (sometimes up to 5 minutes and more). This always happens right before the X server is started, i.e. I can already see the tty, can log in and do stuff et cetera until suddenly the screen goes dark and then the Nvidia logo and finally the Unity desktop is being displayed.

This is my system:
- Thinkpad W510
- Intel Quad Core Processor i7 720QM (1.6GHz 1066MHz 6MB L3)
- NVIDIA Quadro FX 880M with 1GB DDR3
- Intel HD Audio with a CX20585 codec
- more info: http://www.thinkwiki.org/wiki/Category:W510

Software:
- Ubuntu 11.04
- alsa-utils 1.0.24.2-0ubuntu6

I suppose that it's alsactl causing the hanging since:
- $ top tells me that only one task is running with several alsactl entries being right on top.
- powertop tells me that alsactl is the reason for 46% of CPU wake-ups.

I already went through the logs but couldn't find almost anything. The only thing I can tell is that the following is being printed as soon as the tty is there (found in /var/log/kern.log):

Jun 15 22:43:42 philosoph kernel: [ 34.105578] IBM TrackPoint firmware: 0x0e, buttons: 3/3
Jun 15 22:43:42 philosoph kernel: [ 34.410516] input: TPPS/2 IBM TrackPoint as /devices/platform/i8042/serio1/serio2/input/input8
Jun 15 22:43:45 philosoph kernel: [ 37.522706] CE: hpet2 increased min_delta_ns to 7500 nsec
Jun 15 22:43:45 philosoph kernel: [ 37.522796] CE: hpet2 increased min_delta_ns to 11250 nsec
Jun 15 22:43:45 philosoph kernel: [ 37.522892] hrtimer: interrupt took 11831 ns
Jun 15 22:44:04 philosoph kernel: [ 56.175240] CE: hpet3 increased min_delta_ns to 7500 nsec
Jun 15 22:44:04 philosoph kernel: [ 56.175328] CE: hpet3 increased min_delta_ns to 11250 nsec
Jun 15 22:44:48 philosoph kernel: [ 100.213623] CE: hpet6 increased min_delta_ns to 7500 nsec
Jun 15 22:44:48 philosoph kernel: [ 100.213696] CE: hpet6 increased min_delta_ns to 11250 nsec
Jun 15 22:45:34 philosoph kernel: [ 146.080280] CE: hpet5 increased min_delta_ns to 7500 nsec
Jun 15 22:45:34 philosoph kernel: [ 146.080348] CE: hpet5 increased min_delta_ns to 11250 nsec
Jun 15 22:46:10 philosoph kernel: [ 182.835694] CE: hpet4 increased min_delta_ns to 7500 nsec
Jun 15 22:46:10 philosoph kernel: [ 182.835771] CE: hpet4 increased min_delta_ns to 11250 nsec
Jun 15 22:46:33 philosoph kernel: [ 205.700026] ppdev: user-space parallel port driver
Jun 15 22:46:33 philosoph kernel: [ 205.727981] audit_printk_skb: 18 callbacks suppressed
Jun 15 22:46:33 philosoph kernel: [ 205.728049] type=1400 audit(1308170793.851:18): apparmor="STATUS" operation="profile_replace" name="/usr/lib/cups/backend/cups-pdf" pid=1985 comm="apparmor_parser"
Jun 15 22:46:33 philosoph kernel: [ 205.729952] type=1400 audit(1308170793.851:19): apparmor="STATUS" operation="profile_replace" name="/usr/sbin/cupsd" pid=1985 comm="apparmor_parser"

At this point the Nvidia logo usually appears and I can't see any more messages. Please notice the time difference.
Maybe the following entry right after the ones from above is of any interest, too:

Jun 15 22:46:35 philosoph kernel: [ 207.745227] ioremap error for 0xc3ff1000-0xc3ff2000, requested 0x10, got 0x0

I can't say for sure whether it was an update that let to this behavior (I think checked almost immediately but couldn't find any update that might be related). Also, yesterday, for the first time it actually didn't hang during boot-up. This might be related to "GRUB_GFXPAYLOAD_LINUX=text", though, which I put into my /etc/default/grub due to bug #771905 (https://bugs.launchpad.net/ubuntu/+source/plymouth/+bug/771905).

I really don't know what to do anymore. I would be glad if someone looked into this. I'll happily provide you with logs and any other information you request.

* Also see my question from two weeks ago: https://answers.launchpad.net/ubuntu/+question/159539 .