This service will be undergoing maintenance at 00:00 UTC, 2016-08-01. It is expected to last about 1 hours
Bug 715204 - udev-settle.service takes more than one minute in the boot process
udev-settle.service takes more than one minute in the boot process
Status: CLOSED DUPLICATE of bug 707583
Product: Fedora
Classification: Fedora
Component: udev (Show other bugs)
15
Unspecified Linux
unspecified Severity unspecified
: ---
: ---
Assigned To: Harald Hoyer
Fedora Extras Quality Assurance
:
Depends On:
Blocks:
  Show dependency treegraph
 
Reported: 2011-06-22 03:58 EDT by Enrico
Modified: 2011-07-07 10:44 EDT (History)
3 users (show)

See Also:
Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: 707583
Environment:
Last Closed: 2011-07-07 10:44:03 EDT
Type: ---
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:


Attachments (Terms of Use)
systemd-analyze plot (335.71 KB, image/svg+xml)
2011-06-22 03:58 EDT, Enrico
no flags Details
dmesg (213.44 KB, text/plain)
2011-06-22 04:00 EDT, Enrico
no flags Details
/var/log/messages (279.72 KB, text/plain)
2011-06-22 04:00 EDT, Enrico
no flags Details
systemctl dump (467.69 KB, text/plain)
2011-06-22 04:04 EDT, Enrico
no flags Details
systemd --test --system --log-level=debug (502.91 KB, text/plain)
2011-06-22 04:04 EDT, Enrico
no flags Details
systemd-analyze plot (310.79 KB, image/svg+xml)
2011-06-26 04:22 EDT, Sebastian Krämer
no flags Details
dmesg output with debug logging level for udev (1.75 MB, text/plain)
2011-07-01 09:39 EDT, Enrico
no flags Details
/var/log/messages with debug logging level for udev (2.55 MB, text/plain)
2011-07-01 09:41 EDT, Enrico
no flags Details

  None (edit)
Description Enrico 2011-06-22 03:58:54 EDT
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.
Comment 1 Enrico 2011-06-22 04:00:15 EDT
Created attachment 505935 [details]
dmesg
Comment 2 Enrico 2011-06-22 04:00:47 EDT
Created attachment 505936 [details]
/var/log/messages
Comment 3 Enrico 2011-06-22 04:04:05 EDT
Created attachment 505938 [details]
systemctl dump
Comment 4 Enrico 2011-06-22 04:04:52 EDT
Created attachment 505939 [details]
systemd --test --system --log-level=debug
Comment 5 Sebastian Krämer 2011-06-26 04:22:30 EDT
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.
Comment 6 Harald Hoyer 2011-06-30 09:24:05 EDT
you could try to add "udev.log-priority=debug" to the kernel command line and see the logs for udev output.
Comment 7 Enrico 2011-07-01 09:39:55 EDT
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.
Comment 8 Enrico 2011-07-01 09:41:24 EDT
Created attachment 510865 [details]
/var/log/messages with debug logging level for udev
Comment 9 Harald Hoyer 2011-07-07 04:54:15 EDT
you could pass "biosdevname=0" on the kernel command line to disable biosdevname, if that is the culprit.
Comment 10 Enrico 2011-07-07 10:17:09 EDT
(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.
Comment 11 Enrico 2011-07-07 10:44:03 EDT

*** This bug has been marked as a duplicate of bug 707583 ***

Note You need to log in before you can comment on or make changes to this bug.