Bugzilla – Bug 388295
Long delay on boot (~10 seconds)
Last modified: 2008-05-19 18:10:03 UTC
Created attachment 213609 [details] Boot log When booting, just before(!) the message "Loading required kernel modules" is shown, there is a delay of ~10 seconds. IMHO you can even see it in /var/log/boot.msg; have a look at the timestamps in the lines beginning with "Boot logging started": [...] <6>loop: module loaded <4>fuse init (API version 7.9) Kernel logging (ksyslog) stopped. Kernel log daemon terminating. Boot logging started on /dev/tty1(/dev/console) at Wed May 7 19:48:50 2008 Creating device nodes with udev Trying manual resume from /dev/sda5 Invoking userspace resume from /dev/sda5 resume: libgcrypt version: 1.4.0 Trying manual resume from /dev/sda5 Invoking in-kernel resume from /dev/sda5 Waiting for device /dev/disk/by-id/scsi-SATA_Hitachi_HTS5416_SB2404SJJTXMNE-part3 to appear: ok fsck 1.40.8 (13-Mar-2008) [/sbin/fsck.ext3 (1) -- /] fsck.ext3 -a -C0 /dev/disk/by-id/scsi-SATA_Hitachi_HTS5416_SB2404SJJTXMN /dev/disk/by-id/scsi-SATA_Hitachi_HTS5416_SB2404SJJTXMNE-part3: clean, 118967/983040 files, 787564/ fsck succeeded. Mounting root device read-write. Mounting root /dev/disk/by-id/scsi-SATA_Hitachi_HTS5416_SB2404SJJTXMNE-part3 Boot logging started on /dev/tty1(/dev/console (deleted)) at Wed May 7 21:48:57 2008 done Starting udevd: done Loading required kernel modules done [...] Adding "clock=pit" (kernel says this is deprecated) or "clocksource=acpi_pm", as described in Bug 346478, does not help.
Can you try the Beta2 release, this should be solved.
Ugh, sorry, thought this was a duplicate here... reassigning to Tejun to look at...
Sorry, my fault. I forgot to mention that I use 11.0 Beta2 in(!) the bug report, not only in its header.
Can you please attach /var/log/boot.msg?
IMHO, it is already attached to the initial report.
Hmmm... I don't see anything wrong with ata part. Can you please boot with "printk.time=1" kernel parameter and attach /var/log/boot.msg? Let's see where the kernel is spending the 10 secs.
Created attachment 214890 [details] /var/log/boot.msg with printk.time=1
Her you are. The line "ALSA sound/pci/hda/hda_intel.c:596: hda_intel: azx_get_response timeout, switching to polling mode: last cmd=0x020f000d" is not shown on each boot (see my first boot log). The delay in booting seems to be independent of this warning.
cc'ing Takashi as it might have something to do with audio driver. Jan, does creating /etc/modprobe.d/my-blacklist which contains the following line make any difference? blacklist snd_hda_intel
The timeout of hda-intel is 1 second, so 10 seconds dely is definitely too long.
Hmmm... This bug report might be a misunderstanding. Jan, what did you exactly mean by 10sec delay?
> [...] Jan, what did you exactly mean by 10sec delay? I do not know how to express it better than in the initial description. When I boot 11.0 Beta2, there is a ~10 second delay while nothing happens on the screen. That is, there is nothing printed on the tty during the delay. This happens just before(!) the message "Loading required kernel modules" is shown. The last message shown before this delay varies. And the alsa warning is NOT always printed, but the delay is always there. The attachment in Comment #7 shows the delay: <4>[ 11.956869] ALSA sound/pci/hda/hda_intel.c:596: hda_intel: azx_get_response timeout, switching to polling mode: last cmd=0x020f000d <6>[ 40.595542] Adding 4929080k swap on /dev/sda5. Priority:-1 extents:1 across:4929080k If these are seconds, the delay is longer than I thought. Perhaps it varies, too.
> blacklist snd_hda_intel There is no difference (in fact, there is no sound now, but booting is still delayed).
So, the delay is right after "starting udevd is printed"?
Not exactly. After "Starting udevd" is printed, there are many, many device related lines printed without any delay. Then, it takes >10 seconds before the next step, i.e., "Loading required kernel modules", is printed. IMHO, this is shown in the attachment to Comment #7: all of the udev configuration messages are printed before time 12. But the messages about adding swap, starting device mapper, loading loop module and initializing fuse do not happen before time 40.
Can you please tell me the last thing the system says before stalling? I can't really tell what's causing the stall from what happens next.
No, sorry, I can't. The last message that is printed before the delay is not the same for each boot! Sometimes it is "ALSA sound/pci/hda/hda_intel.c:596: hda_intel: azx_get_response timeout, switching to polling mode: last cmd=0x020f000d" like in the boot.msg attached to Comment #7. And sometimes this message is not printed and, thus, the "wmaster0 renamed to wmaster0_rename" is the last message before the delay. Don't you see the delay in the boot.msg attached to Comment #7? Or is this gap between 11.956869 and 40.595542 no delay?
Yeap, I do see the delay in kernel printk timestamps but messages from boot scripts are printed intermixed with kernel messages on console during boot unlike /var/log/boot.msg, so I was hoping there were more clues. Loading required modules is printed from S04boot.loadmodules. I don't think it will actually load anything. Can you please post /etc/sysconfig/kernel? swap is enabled by S12boot.swap. There are only a few things which can prevent rc from proceeding from S04 to S12 - setclock, device-mapper, lvm and localfs. Some of these scripts are delaying boot. It might not be a kernel problem.
The delay happens while starting udev. The messages printed on konsole are almost the same as in /var/log/boot.msg. However, I do not remember to have seen the line "ieee1394: Host added: ID:BUS[0-00:1023] GUID[00016c20001634c0]" on the konsole. This line in boot.msg seems to always one of the last lines. I will try to blacklist Firewire. BTW, this time, the last message printed before the delay was "mmc0: SDHCI at 0xf8101800 irq 18 DMA". linux:~ # grep -v "^#" /etc/sysconfig/kernel INITRD_MODULES="processor thermal ahci ata_piix fan jbd ext3 edd" DOMU_INITRD_MODULES="xennet xenblk" MODULES_LOADED_ON_BOOT="" ACPI_DSDT="" SCHED_MINTIMESLICE="" SCHED_MAXTIMESLICE="" SKIP_RUNNING_KERNEL=""
I'm pretty sure this is a duplicate of bug 371776 Can you test beta 3 to verify it?
Thanks Greg. It looks like you are right. Beta3 fixed this problem. Anyway, thanks to Tejun for his patience, too! *** This bug has been marked as a duplicate of bug 371776 ***