~30s boot pause

I am also seeing long pauses on boot-up of Maverick (and Lucid was doing it too, before the upgrade), and I use the escape key to continue, however the number of times I press the escape key varies distinctly from 1 to 6 times, so this is probably a race condition. There is usually a dmesg entry right before (or very nearly before) the pause like:

[ 8.085519] udev[446]: starting version 163

Hi Billstei - can you include a full dmesg from your boot, and maybe some details of your hardware?

Dave

This seems considerably worse on natty, while we had ~30 second pause on Maverick on the current 2.6.37-11-generic #25-Ubuntu Natty we have about 75 seconds (and I think in this time the screen on Natty is completely blank)

Dec 25 12:19:44 major kernel: [ 4.594366] sd 6:0:0:0: [sdb] Write Protect is off
Dec 25 12:19:44 major kernel: [ 4.597498] sdb: sdb1
Dec 25 12:19:44 major kernel: [ 4.598819] sd 6:0:0:0: [sdb] Attached SCSI removable disk
Dec 25 12:19:44 major kernel: [ 18.443145] CE: hpet2 increased min_delta_ns to 7500 nsec
Dec 25 12:19:44 major kernel: [ 18.443155] CE: hpet2 increased min_delta_ns to 11250 nsec
Dec 25 12:19:44 major kernel: [ 18.443159] hrtimer: interrupt took 5335 ns
Dec 25 12:19:44 major kernel: [ 46.209436] CE: hpet3 increased min_delta_ns to 7500 nsec
Dec 25 12:19:44 major kernel: [ 46.209442] CE: hpet3 increased min_delta_ns to 11250 nsec
Dec 25 12:19:44 major kernel: [ 66.495751] EXT4-fs (sda1): mounted filesystem with ordered data mode. Opts: (null)
Dec 25 12:19:44 major kernel: [ 80.509736] Adding 2000088k swap on /dev/sda2. Priority:-1 extents:1 across:2000088k
Dec 25 12:19:44 major kernel: [ 80.942370] EXT4-fs (sda1): re-mounted. Opts: errors=remount-ro
Dec 25 12:19:44 major kernel: [ 80.992449] udev[558]: starting version 165

This morning I booted kernel 2.6.35-25 in Maverick and pressed the Escape key 4 times (varies, see above) to continue the boot. I waited approximately 20 to 30 seconds after each "hang" before pressing Escape again. Here is the interesting part of the dmesg for this boot attempt:

[ 4.342743] hub 1-3.4.1:1.0: USB hub found
[ 4.342852] hub 1-3.4.1:1.0: 4 ports detected
[ 4.428607] usb 1-3.4.4: new high speed USB device using ehci_hcd and address 8
[ 10.265435] REISERFS (device sda1): replayed 643 transactions in 7 seconds
[ 10.265787] REISERFS (device sda1): Using r5 hash to sort names
[ 11.648925] udev[438]: starting version 163
[ 38.301359] Adding 7999484k swap on /dev/sda2. Priority:-1 extents:1 across:7999484k
[ 127.667142] lp: driver loaded but no devices found
[ 127.685693] input: Wacom Intuos3 6x8 as /devices/pci0000:00/0000:00:12.0/usb4/4-4/4-4:1.0/input/input5
[ 127.688164] usbcore: registered new interface driver wacom

The mouse on this system (per comments above), a Microsoft USB "Basic Optical Mouse", was replaced with a Logitech Wireless M505 (which uses the Logitech Unifying USB receiver) and now exhibits a new behaviour: the system still hangs on boot-up but as soon as the mouse is moved the system continues booting (no Escape key presses are needed).

I spoke to soon, with the new mouse/Unifying Receiver, it not only hangs (sometimes?), but locks up the keyboard so that I can't press Escape and continue booting. Put the old mouse back on.

I have just started having this problem after doing an "apt-get autoremove" on my Ubuntu 10.10 64-bit system (Acer timelinex 3820TG with the dual GPU "switchable graphics").

Here's what my dmesg looks like:

[ 1.688349] sd 0:0:0:0: [sda] Attached SCSI disk
[ 1.799582] hub 2-1:1.0: USB hub found
[ 1.799791] hub 2-1:1.0: 8 ports detected
[ 2.075196] usb 2-1.5: new high speed USB device using ehci_hcd and address 3
[ 2.597199] EXT4-fs (sda7): mounted filesystem with ordered data mode. Opts: (null)
[ 42.726500] udev[444]: starting version 163
[ 42.738288] lp: driver loaded but no devices found
[ 42.802317] intel ips 0000:00:1f.6: Warning: CPU TDP doesn't match expected value (found 25, expected 35)
[ 42.802341] alloc irq_desc for 18 on node -1
[ 42.802344] alloc kstat_irqs on node -1
[ 42.802357] intel ips 0000:00:1f.6: PCI INT C -> GSI 18 (level, low) -> IRQ 18
[ 42.802521] intel ips 0000:00:1f.6: failed to get i915 symbols, graphics turbo disabled

So a full 40-second delay. All the while the hard drive churns away, and the cursor blinks on the screen; then an error message flashes up too quickly to read and then the plymouth splash screen appears.
The hard drive churning and the mounted filesystem notice make me wonder if it's related to the disk mount.
Must be some package I removed; if I can figure out which one it was, might help to locate this problem.

I managed to grab an alt-sysrq-t during the hang today; the interesting thing from my view of it is that there are a load of udevd processes and not much else.

Feb 6 12:30:41 major kernel: [ 9.201283] CE: hpet4 increased min_delta_ns to 7500 nsec
Feb 6 12:30:41 major kernel: [ 9.201292] CE: hpet4 increased min_delta_ns to 11250 nsec
Feb 6 12:30:41 major kernel: [ 9.201297] hrtimer: interrupt took 7733 ns
Feb 6 12:30:41 major kernel: [ 29.432401] CE: hpet6 increased min_delta_ns to 7500 nsec
Feb 6 12:30:41 major kernel: [ 29.432410] CE: hpet6 increased min_delta_ns to 11250 nsec
Feb 6 12:30:41 major kernel: [ 32.861312] SysRq : HELP : loglevel(0-9) reBoot Crash terminate-all-tasks(E) memory-full-oom-kill(F) kill-all-tasks(I) thaw-filesystems(J) saK show-backtrace-all-active-cpus(L) show-memory-usage(M) nice-all-RT-tasks(N) powerOff show-registers(P) show-all-timers(Q) unRaw Sync show-task-states(T) Unmount force-fb(V) show-blocked-tasks(W) dump-ftrace-buffer(Z)
Feb 6 12:30:41 major kernel: [ 33.711121] SysRq : Show State
Feb 6 12:30:41 major kernel: [ 33.711127] task PC stack pid father
Feb 6 12:30:41 major kernel: [ 33.711131] init S 0000000000000007 0 1 0 0x00000000
Feb 6 12:30:41 major kernel: [ 33.711138] ffff8802274d1e68 0000000000000086 ffff8802274d1fd8 ffff8802274d0000
Feb 6 12:30:41 major kernel: [ 33.711145] 0000000000013b00 ffff8802274c83a0 ffff8802274d1fd8 0000000000013b00
Feb 6 12:30:41 major kernel: [ 33.711152] ffff8802275bdb00 ffff8802274c8000 ffff8802274d1e68 0000000000000000
Feb 6 12:30:41 major kernel: [ 33.711158] Call Trace:
Feb 6 12:30:41 major kernel: [ 33.711169] [<ffffffff81068f45>] do_wait+0x1d5/0x270
Feb 6 12:30:41 major kernel: [ 33.711175] [<ffffffff810646dc>] ? do_fork+0xcc/0x340
Feb 6 12:30:41 major kernel: [ 33.711181] [<ffffffff8106a373>] sys_wait4+0xa3/0x100
Feb 6 12:30:41 major kernel: [ 33.711187] [<ffffffff810676b0>] ? child_wait_callback+0x0/0x60
Feb 6 12:30:41 major kernel: [ 33.711193] [<ffffffff8100c002>] system_call_fastpath+0x16/0x1b
Feb 6 12:30:41 major kernel: [ 33.711197] kthreadd S 0000000000000004 0 2 0 0x00000000
Feb 6 12:30:41 major kernel: [ 33.711203] ffff8802274d3ee0 0000000000000046 ffff8802274d3fd8 ffff8802274d2000
Feb 6 12:30:41 major kernel: [ 33.711209] 0000000000013b00 ffff8802274c9a60 ffff8802274d3fd8 0000000000013b00
Feb 6 12:30:41 major kernel: [ 33.711216] ffff880227562d80 ffff8802274c96c0 ffffffff8100ce20 ffff880221f0bd90
Feb 6 12:30:41 major kernel: [ 33.711222] Call Trace:
Feb 6 12:30:41 major kernel: [ 33.711227] [<ffffffff8100ce20>] ? kernel_thread_helper+0x0/0x10
Feb 6 12:30:41 major kernel: [ 33.711234] [<ffffffff810872f5>] kthreadd+0x135/0x140
Feb 6 12:30:41 major kernel: [ 33.711241] [<ffffffff8100a6e0>] ? __switch_to+0xc0/0x2f0
Feb 6 12:30:41 major kernel: [ 33.711247] [<ffffffff81054e11>] ? finish_task_switch+0x41/0xe0
Feb 6 12:30:41 major kernel: [ 33.711252] [<ffffffff8100ce24>] kernel_thread_helper+0x4/0x10
Feb 6 12:30:41 major kernel: [ 33.711257] [<ffffffff810871c0>] ? kthreadd+0x0/0x140
Fe...

Thanks for taking the time to report his bug and comment on it. However, I've noticed that this bug has been Confirmed although there is not clear indication as to how to recreate this bug [ or version of software affected ]. Subsequently, I'm setting its status to Incomplete until that information is provided. You can learn more about bug statuses at http://wiki.ubuntu.com/Bugs/Status. Thanks for taking the time to make Ubuntu better!

So I enabled udev debugging (to info level) and lvm debug and attached the log.

It's a bit difficult to tell because the time skew in the log looks pretty small - certainly not the ~90 seconds I get during a normal boot.

There doesn't look like too much helpful in there, there are a splurge of errors of the form:

Feb 18 16:25:18 major libvirtd: 16:25:18.643: error : udev_device_read_db:251 : no db file to read 0: No such file or directory#012
Feb 18 16:25:18 major libvirtd: 16:25:18.643: error : udev_device_new_from_syspath:445 : device 0x7fff6c002c80 has devpath 'H<85>ÀH<89>Å#017<84>î'#012

Feb 18 16:25:18 major libvirtd: 16:25:18.644: error : udev_device_read_db:295 : device 0x7fff6bffebd0 filled with db file data#012
Feb 18 16:25:18 major libvirtd: 16:25:18.644: error : udev_device_new_from_syspath:445 : device 0x7fff6c002c80 has devpath 'H<85>ÀH<89>Å#017<84>î'#012

There is also a couple of:

Feb 18 16:25:18 major libvirtd: 16:25:18.465: error : virRunWithHook:855 : internal error '/sbin/vgchange -ay main' exited with non-zero status 5 and signal 0:
Feb 18 16:25:18 major libvirtd: 16:25:18.465: error : storageDriverAutostart:86 : Failed to autostart storage pool 'main': internal error '/sbin/vgchange -ay main' exited with non-zero status 5 and signal 0:

it's not obvious to me why libvirtd is getting involved at that point (many of the LVM partitions under main are vm guests - but none of the VMs start at boot).

I've upgraded to 11.04 which seems to have solved this issue for me

Try the following command and see if it helps:

sudo rm -v /var/lib/ureadahead/*pack*

I had exactly the same issue, and the above command helped me a lot.

Hi,

I'm on oneiric and since two days my udev hangs for around 60 seconds...
I have no idea how to get around it or what caused it.

It might be related to /usr/share/initramfs-tools/scripts/init-bottom/udev since in recover boot I see the init-bottom scripts for a long time and in the udev script there is a timeout of 61sec...
What does this do and why could it change the boot process in such a dramatic way?

Seems to be like #818177 filed for oneiric...

Attachment is a bootchart when same problem hit me.
After I remade swap partition and I hit several times when boot time, the problem happen to be gone..

Attachement is a chart when problem occurs.

following is a log.
Dec 23 13:52:51 tuna kernel: [ 2.231976] usbhid: USB HID core driver
Dec 23 13:52:51 tuna kernel: [ 2.243343] usb 2-1.6: new full speed USB device number 5 using ehci_hcd
Dec 23 13:52:51 tuna kernel: [ 2.361649] ata2.00: configured for UDMA/100
Dec 23 13:52:51 tuna kernel: [ 2.963152] scsi 1:0:0:0: CD-ROM TSSTcorp CDDVDW SH-S223C SB03 PQ: 0 ANSI: 5
Dec 23 13:52:51 tuna kernel: [ 2.966365] sr0: scsi3-mmc drive: 52x/52x writer dvd-ram cd/rw xa/form2 cdda tray
Dec 23 13:52:51 tuna kernel: [ 2.966371] cdrom: Uniform CD-ROM driver Revision: 3.20
Dec 23 13:52:51 tuna kernel: [ 2.966516] sr 1:0:0:0: Attached scsi CD-ROM sr0
Dec 23 13:52:51 tuna kernel: [ 2.966579] sr 1:0:0:0: Attached scsi generic sg1 type 5
Dec 23 13:52:51 tuna kernel: [ 3.286349] ata3: SATA link down (SStatus 0 SControl 300)
Dec 23 13:52:51 tuna kernel: [ 3.606094] ata4: SATA link down (SStatus 0 SControl 300)
Dec 23 13:52:51 tuna kernel: [ 3.925860] ata5: SATA link down (SStatus 0 SControl 300)
Dec 23 13:52:51 tuna kernel: [ 4.245616] ata6: SATA link down (SStatus 0 SControl 300)
Dec 23 13:52:51 tuna kernel: [ 4.708530] EXT4-fs (sda1): mounted filesystem with ordered data mode. Opts: (null)
Dec 23 13:52:51 tuna kernel: [ 66.951398] Adding 3905532k swap on /dev/sda6. Priority:-1 extents:1 across:3905532k
Dec 23 13:52:51 tuna kernel: [ 67.800504] lp: driver loaded but no devices found
Dec 23 13:52:51 tuna kernel: [ 68.451122] parport_pc 00:06: reported by Plug and Play ACPI
Dec 23 13:52:51 tuna kernel: [ 68.451176] parport0: PC-style at 0x378 (0x778), irq 7, dma 3 [PCSPP,TRISTATE,COMPAT,ECP,DMA]
Dec 23 13:52:51 tuna kernel: [ 68.540511] lp0: using parport0 (interrupt-driven).
Dec 23 13:52:51 tuna kernel: [ 68.641501] ppdev: user-space parallel port driver
Dec 23 13:52:51 tuna kernel: [ 68.806270] device-mapper: multipath: version 1.3.0 loaded
Dec 23 13:52:51 tuna kernel: [ 68.991564] EDAC MC: Ver: 2.1.0

This bug was filed against a series that is no longer supported and so is being marked as Won't Fix. If this issue still exists in a supported series, please file a new bug.

This change has been made by an automated script, maintained by the Ubuntu Kernel Team.