Created attachment 505934 [details] systemd-analyze plot Description of problem: Previous Fedora releases took a reasonable time to boot on my machine, while now it takes longer. This is a new installation, not an upgrade, and the problem is present since the release of Fedora 15. I'm using a standard partition scheme (separate root, boot and home ext4 partitions), not LVM. There are no network filesystems in fstab. 'systemd-analyze time' gives me: Startup finished in 1275ms (kernel) + 4028ms (initrd) + 89779ms (userspace) = 95083ms 'systemd-analyze blame' gives me: 75844ms udev-settle.service 70041ms fedora-readonly.service 68247ms systemd-vconsole-setup.service 4906ms fedora-sysinit-hack.service 4790ms remount-rootfs.service 4422ms media.mount 4154ms systemd-remount-api-vfs.service 4135ms hwclock-load.service 3510ms systemd-sysctl.service 2371ms postgresql.service 1339ms rsyslog.service 1152ms NetworkManager.service 1034ms bluetooth.service 1012ms abrtd.service [...] I attached the result of 'systemd-analyze plot'. This is probably a timeout somewhere, but I can't figure out what's making udev wait, since every hardware component seems to work fine. When booting with the kernel parameters 'log_buf_len=1M systemd.log_level=debug systemd.log_target=kmsg', this the excerpt of dmesg at the jump: [ 12.965799] cfg80211: Calling CRDA to update world regulatory domain [ 12.979190] r852 0000:08:01.3: PCI INT B -> GSI 17 (level, low) -> IRQ 17 [ 12.984324] Bluetooth: Core ver 2.15 [ 12.987675] NET: Registered protocol family 31 [ 12.989657] Bluetooth: HCI device and connection manager initialized [ 12.991504] Bluetooth: HCI socket layer initialized [ 12.994473] uvcvideo: Found UVC 1.00 device USB2.0 1.3M UVC WebCam (04f2:b012) [ 12.995755] Bluetooth: Generic Bluetooth USB driver ver 0.6 [ 13.000264] usbcore: registered new interface driver btusb [ 13.007728] r852: driver loaded succesfully [ 13.010093] cfg80211: World regulatory domain updated: [ 13.011886] cfg80211: (start_freq - end_freq @ bandwidth), (max_antenna_gain, max_eirp) [ 13.013891] cfg80211: (2402000 KHz - 2472000 KHz @ 40000 KHz), (300 mBi, 2000 mBm) [ 13.015729] cfg80211: (2457000 KHz - 2482000 KHz @ 20000 KHz), (300 mBi, 2000 mBm) [ 13.017489] cfg80211: (2474000 KHz - 2494000 KHz @ 20000 KHz), (300 mBi, 2000 mBm) [ 13.019271] cfg80211: (5170000 KHz - 5250000 KHz @ 40000 KHz), (300 mBi, 2000 mBm) [ 13.021008] cfg80211: (5735000 KHz - 5835000 KHz @ 40000 KHz), (300 mBi, 2000 mBm) [ 13.040113] input: USB2.0 1.3M UVC WebCam as /devices/pci0000:00/0000:00:1a.7/usb1/1-3/1-3:1.0/input/input7 [ 13.042427] usbcore: registered new interface driver uvcvideo [ 13.044170] USB Video Class driver (v1.0.0) [ 13.048005] microcode: CPU0 updated to revision 0x95, date = 2010-10-02 [ 13.063748] microcode: CPU1 updated to revision 0x95, date = 2010-10-02 [ 13.106486] iwl3945: Intel(R) PRO/Wireless 3945ABG/BG Network Connection driver for Linux, in-tree:ds [ 13.108252] iwl3945: Copyright(c) 2003-2010 Intel Corporation [ 13.108330] iwl3945 0000:07:00.0: PCI INT A -> GSI 17 (level, low) -> IRQ 17 [ 13.108344] iwl3945 0000:07:00.0: setting latency timer to 64 [ 13.133076] HDA Intel 0000:00:1b.0: PCI INT A -> GSI 22 (level, low) -> IRQ 22 [ 13.134900] HDA Intel 0000:00:1b.0: irq 48 for MSI/MSI-X [ 13.134941] HDA Intel 0000:00:1b.0: setting latency timer to 64 [ 13.164669] iwl3945 0000:07:00.0: Tunable channels: 13 802.11bg, 23 802.11a channels [ 13.166577] iwl3945 0000:07:00.0: Detected Intel Wireless WiFi Link 3945ABG [ 13.168960] iwl3945 0000:07:00.0: irq 49 for MSI/MSI-X [ 13.180056] hda_codec: ALC660-VD: BIOS auto-probing. [ 13.181884] ALSA sound/pci/hda/hda_codec.c:4633: autoconfig: line_outs=1 (0x14/0x0/0x0/0x0/0x0) [ 13.181888] ALSA sound/pci/hda/hda_codec.c:4637: speaker_outs=0 (0x0/0x0/0x0/0x0/0x0) [ 13.181892] ALSA sound/pci/hda/hda_codec.c:4641: hp_outs=1 (0x1b/0x0/0x0/0x0/0x0) [ 13.181896] ALSA sound/pci/hda/hda_codec.c:4642: mono: mono_out=0x0 [ 13.181899] ALSA sound/pci/hda/hda_codec.c:4645: dig-out=0x1e/0x0 [ 13.181902] ALSA sound/pci/hda/hda_codec.c:4646: inputs: [ 13.181905] ALSA sound/pci/hda/hda_codec.c:4652: [ 13.182568] ieee80211 phy0: Selected rate control algorithm 'iwl-3945-rs' [ 13.182791] ALSA sound/pci/hda/patch_realtek.c:1585: realtek: No valid SSID, checking pincfg 0x598301f0 for NID 0x1d [ 13.182796] ALSA sound/pci/hda/patch_realtek.c:1669: realtek: Enable default setup for auto mode as fallback [ 79.600400] systemd[1]: sys-devices-pci0000:00-0000:00:1d.2-usb7-7\x2d2-7\x2d2:1.0-bluetooth-hci0.device changed dead -> plugged [ 79.602248] systemd[1]: Trying to enqueue job bluetooth.target/start/fail [ 79.604178] systemd[1]: systemd-ask-password-plymouth.path/stop would stop a running service. [ 79.606017] systemd[1]: Deleting systemd-ask-password-plymouth.path/stop to minimize impact. [ 79.607884] systemd[1]: Installed new job bluetooth.target/start as 148 [ 79.609708] systemd[1]: Installed new job bluetooth.service/start as 149 [ 79.611531] systemd[1]: Enqueued job bluetooth.target/start as 148 [ 79.613340] systemd[1]: bluetooth.target changed dead -> active [ 79.615142] systemd[1]: Job bluetooth.target/start finished, result=done [ 79.616944] systemd[1]: Running GC... [ 79.618977] systemd[1]: sys-devices-pci0000:00-0000:00:1b.0-sound-card0.device changed dead -> plugged [ 79.620807] systemd[1]: Trying to enqueue job sound.target/start/fail [ 79.622612] systemd[1]: Installed new job sound.target/start as 194 [ 79.624409] systemd[1]: Enqueued job sound.target/start as 194 [ 79.626209] systemd[1]: sound.target changed dead -> active [ 79.627984] systemd[1]: Job sound.target/start finished, result=done [ 79.630360] systemd[1]: Received SIGCHLD from PID 624 (gzip). [ 79.636884] systemd[1]: Got SIGCHLD for process 452 (systemd-vconsol) [ 79.638674] systemd[1]: Child 452 died (code=exited, status=0/SUCCESS) [ 79.640405] systemd[1]: Child 452 belongs to systemd-vconsole-setup.service [ 79.642176] systemd[1]: systemd-vconsole-setup.service: main process exited, code=exited, status=0 [ 79.653044] systemd[1]: systemd-vconsole-setup.service changed start -> exited [ 79.654783] systemd[1]: Job systemd-vconsole-setup.service/start finished, result=done [ 79.657121] systemd[1]: Got SIGCHLD for process 624 (gzip) [ 79.657187] systemd[1]: Child 624 died (code=exited, status=0/SUCCESS) [ 79.657264] systemd[1]: Accepted connection on private bus. [ 79.657643] systemd[1]: Got D-Bus request: org.freedesktop.systemd1.Agent.Released() on /org/freedesktop/systemd1/agent [ 79.657678] systemd[1]: systemd-vconsole-setup.service: cgroup is empty [ 79.657714] systemd[1]: Got D-Bus request: org.freedesktop.DBus.Local.Disconnected() on /org/freedesktop/DBus/Local [ 81.784366] udev[472]: renamed network interface eth0 to em1 [ 81.788641] systemd[1]: sys-devices-pci0000:00-0000:00:1c.2-0000:03:00.0-net-em1.device changed dead -> plugged [ 82.402269] cfg80211: Calling CRDA for country: IT [ 82.408761] cfg80211: Regulatory domain changed to country: IT [ 82.410634] cfg80211: (start_freq - end_freq @ bandwidth), (max_antenna_gain, max_eirp) [ 82.412527] cfg80211: (2402000 KHz - 2482000 KHz @ 40000 KHz), (N/A, 2000 mBm) [ 82.414428] cfg80211: (5170000 KHz - 5250000 KHz @ 40000 KHz), (N/A, 2000 mBm) [ 82.416328] cfg80211: (5250000 KHz - 5330000 KHz @ 40000 KHz), (N/A, 2000 mBm) [ 82.418204] cfg80211: (5490000 KHz - 5710000 KHz @ 40000 KHz), (N/A, 2700 mBm) [ 82.486822] systemd[1]: sys-devices-pci0000:00-0000:00:1c.5-0000:07:00.0-net-wlan0.device changed dead -> plugged Thank you for your time :) Version-Release number of selected component (if applicable): udev 167-4 systemd 26-3 How reproducible: Steps to Reproduce: 1. Install Fedora 15 on a new partition 2. Boot the system 3. Actual results: The boot process hangs at some point and continues after a minute. Expected results: The boot process should not hang.
Created attachment 505935 [details] dmesg
Created attachment 505936 [details] /var/log/messages
Created attachment 505938 [details] systemctl dump
Created attachment 505939 [details] systemd --test --system --log-level=debug
Created attachment 509950 [details] systemd-analyze plot In my case, the waiting time isn't that extreme but I still feel it's rather long (too long), and hopefully this can be optimized.
you could try to add "udev.log-priority=debug" to the kernel command line and see the logs for udev output.
Created attachment 510864 [details] dmesg output with debug logging level for udev Thank you, I've attached the output of dmesg with that option. It seems that udev wastes time when renaming the physical network interface "eth0" to "em1", making this bug report a clone of https://bugzilla.redhat.com/show_bug.cgi?id=700106 but I can't say I'm not missing something else.
Created attachment 510865 [details] /var/log/messages with debug logging level for udev
you could pass "biosdevname=0" on the kernel command line to disable biosdevname, if that is the culprit.
(In reply to comment #9) > you could pass "biosdevname=0" on the kernel command line to disable > biosdevname, if that is the culprit. Thank you, that worked! 'systemd-analyze time' now gives me 28 seconds. I apologize if I didn't figure this out myself, because this information could have been found in the Fedora official wiki. Again, thank you for your time. If you need help looking into the cause of this bug, feel free to ask me to do tests on my systems.
*** This bug has been marked as a duplicate of bug 707583 ***