You are not logged in.

#1 2014-10-29 07:00:35

Carl Karl
Member
Registered: 2013-06-12
Posts: 231

[SOLVED] A start job is running for udev wait for Complete Device I...

Since recently boot hangs 1 min and 3s on the message:

A start job is running for udev wait for Complete Device Initialization (..s / 3min)

After 40s, this message is shortly interrupted by the message:

Starting Trigger Flushing of Journal to Persistent Storage....
[ OK ] Started Trigger Flushing of Journal to Persistent Storage.

The problem doesn't happen on every boot, but on about 4 of 5 boots.

Has anyone a hint on how to debug this?

Outputs:

# dmesg | grep udev
[    0.646025] systemd-udevd[57]: starting version 216
[    1.484329] systemd-udevd[163]: starting version 216
[    2.054943] systemd-udevd[176]: renamed network interface eth0 to enp0s25
[    2.241700] systemd-udevd[172]: renamed network interface wlan0 to wlp2s0

# dmesg | grep Device
[    0.171066] ACPI: Added _OSI(Module Device)
[    0.171068] ACPI: Added _OSI(Processor Device)
[    0.171071] ACPI: Added _OSI(Processor Aggregator Device)
[    3.369896] ACPI: Video Device [GFX0] (multi-head: yes  rom: yes  post: no)

I also did the Test described on https://wiki.archlinux.org/index.php/Ud … gs_at_boot , but
1. the boot message doesn't match and
2. everything looks good so far:

 diff -y present_groups udev_groups
adm							      <
audio								audio
avahi							      <
bin							      <
brlapi							      <
colord								colord
daemon							      <
dbus							      <
disk								disk
floppy							      <
ftp							      <
games							      <
gdm							      <
git							      <
http							      <
input								input
kdm							      <
kmem								kmem
locate							      <
lock							      <
log							      <
lp								lp
mail							      <
mem							      <
mysql							      <
network							      <
nobody							      <
ntp							      <
optical								optical
polkitd							      <
power							      <
rfkill							      <
root								root
rtkit							      <
scanner								scanner
smmsp							      <
storage								storage
sys							      <
systemd-bus-proxy					      <
systemd-journal						      <
systemd-journal-gateway					      <
systemd-journal-remote					      <
systemd-journal-upload					      <
systemd-network						      <
systemd-resolve						      <
systemd-timesync					      <
tty								tty
users							      <
utmp							      <
uucp								uucp
uuidd							      <
vboxusers						      <
video								video
wheel							      <

Edit
I found something which may match to the 1 minute waiting gap (between 08:03:01 and 08:04:02; 4th to 5th line):

# journaltctl -k
.....
Okt 29 08:03:01 portz30 kernel: snd_hda_intel 0000:00:03.0: irq 48 for MSI/MSI-X
Okt 29 08:03:01 portz30 kernel: input: HDA Intel HDMI HDMI/DP,pcm=3 as /devices/pci0000:00/0000:00:03.0/sound/card0/input12
Okt 29 08:03:01 portz30 kernel: input: HDA Intel HDMI HDMI/DP,pcm=7 as /devices/pci0000:00/0000:00:03.0/sound/card0/input13
Okt 29 08:03:01 portz30 kernel: input: HDA Intel HDMI HDMI/DP,pcm=8 as /devices/pci0000:00/0000:00:03.0/sound/card0/input14
Okt 29 08:04:02 portz30 kernel: iwlwifi 0000:02:00.0: L1 Enabled; Disabling L0S
Okt 29 08:04:02 portz30 kernel: iwlwifi 0000:02:00.0: L1 Enabled; Disabling L0S
Okt 29 08:04:02 portz30 kernel: IPv6: ADDRCONF(NETDEV_UP): wlp2s0: link is not ready
Okt 29 08:04:02 portz30 kernel: e1000e 0000:00:19.0: irq 44 for MSI/MSI-X
Okt 29 08:04:02 portz30 kernel: e1000e 0000:00:19.0: irq 44 for MSI/MSI-X
Okt 29 08:04:02 portz30 kernel: IPv6: ADDRCONF(NETDEV_UP): enp0s25: link is not ready
Okt 29 08:04:03 portz30 kernel: fuse init (API version 7.23)
Okt 29 08:04:03 portz30 kernel: EXT4-fs (sda1): re-mounted. Opts: data=ordered
Okt 29 08:04:06 portz30 kernel: wlp2s0: authenticate with 00:03:c9:43:a1:af
Okt 29 08:04:06 portz30 kernel: wlp2s0: send auth to 00:03:c9:43:a1:af (try 1/3)
Okt 29 08:04:06 portz30 kernel: wlp2s0: authenticated
Okt 29 08:04:06 portz30 kernel: iwlwifi 0000:02:00.0 wlp2s0: disabling HT/VHT due to WEP/TKIP use
Okt 29 08:04:06 portz30 kernel: iwlwifi 0000:02:00.0 wlp2s0: disabling HT as WMM/QoS is not supported by the AP
Okt 29 08:04:06 portz30 kernel: iwlwifi 0000:02:00.0 wlp2s0: disabling VHT as WMM/QoS is not supported by the AP
Okt 29 08:04:06 portz30 kernel: wlp2s0: associate with 00:03:c9:43:a1:af (try 1/3)
Okt 29 08:04:06 portz30 kernel: wlp2s0: RX AssocResp from 00:03:c9:43:a1:af (capab=0x411 status=0 aid=4)
Okt 29 08:04:06 portz30 kernel: wlp2s0: associated
Okt 29 08:04:06 portz30 kernel: IPv6: ADDRCONF(NETDEV_CHANGE): wlp2s0: link becomes ready
Okt 29 08:08:26 portz30 kernel: [drm:ivybridge_set_fifo_underrun_reporting] *ERROR* uncleared fifo underrun on pipe A
Okt 29 08:08:26 portz30 kernel: [drm:ivb_err_int_handler] *ERROR* Pipe A FIFO underrun

So maybe it's something with the iwlwifi?

Edit 2:
this 1:01min gap between

Okt 29 08:03:01 portz30 kernel: input: HDA Intel HDMI HDMI/DP,pcm=8 as /devices/pci0000:00/0000:00:03.0/sound/card0/input14
Okt 29 08:04:02 portz30 kernel: iwlwifi 0000:02:00.0: L1 Enabled; Disabling L0S

is reproduce-able.

Edit 3:

# dmesg | grep iwlwifi
[    1.727503] iwlwifi 0000:02:00.0: irq 45 for MSI/MSI-X
[    1.729560] iwlwifi 0000:02:00.0: Direct firmware load for iwlwifi-3160-10.ucode failed with error -2
[    1.732536] iwlwifi 0000:02:00.0: loaded firmware version 25.222.9.0 op_mode iwlmvm
[    1.770479] iwlwifi 0000:02:00.0: Detected Intel(R) Dual Band Wireless AC 3160, REV=0x164
[    1.770814] iwlwifi 0000:02:00.0: L1 Enabled; Disabling L0S
[    1.771567] iwlwifi 0000:02:00.0: L1 Enabled; Disabling L0S
[    1.902226] iwlwifi 0000:02:00.0 wlp2s0: renamed from wlan0
[   64.877608] iwlwifi 0000:02:00.0: L1 Enabled; Disabling L0S
[   64.878267] iwlwifi 0000:02:00.0: L1 Enabled; Disabling L0S
[  116.061859] iwlwifi 0000:02:00.0 wlp2s0: disabling HT/VHT due to WEP/TKIP use
[  116.061867] iwlwifi 0000:02:00.0 wlp2s0: disabling HT as WMM/QoS is not supported by the AP
[  116.061873] iwlwifi 0000:02:00.0 wlp2s0: disabling VHT as WMM/QoS is not supported by the AP

Last edited by Carl Karl (2014-11-02 09:42:45)

Offline

#2 2014-10-29 16:50:26

Carl Karl
Member
Registered: 2013-06-12
Posts: 231

Re: [SOLVED] A start job is running for udev wait for Complete Device I...

By running systemd-analyze blame I found out systemd-udev-settle.service is responsible for that delay. After reading in the internets that that service is not necessary if no LVM are used, I tried to disable that service which didn't worked.
So I masked it instead:

# systemctl mask systemd-udev-settle

and now booting is fast again, the 1m3s delay is gone.

But I'm still not sure whether this is a clean solution, so if you have better knowledge about this, please let me know....

Offline

#3 2014-10-29 19:43:46

brettski
Member
Registered: 2013-06-21
Posts: 18
Website

Re: [SOLVED] A start job is running for udev wait for Complete Device I...

For the past 3 days, I have been suffering from an identical problem but only on my laptop (Intel CPU, 1 ssd). Not sure what triggered it. Often these kinds of problems seem to follow an update although I have not yet tracked down the guilty package (if any).

Offline

#4 2014-10-29 21:46:10

Carl Karl
Member
Registered: 2013-06-12
Posts: 231

Re: [SOLVED] A start job is running for udev wait for Complete Device I...

brettski wrote:

laptop (Intel CPU, 1 ssd).

Same configuration here. And good to know I'm not the only one, thanks for your answer.

Offline

#5 2014-10-29 22:07:40

toz
Member
Registered: 2011-10-28
Posts: 494

Re: [SOLVED] A start job is running for udev wait for Complete Device I...

Same here, Intel + ssd. Thanks for the fix/workaround. It solves the boot delay issue.

Offline

#6 2014-11-02 09:18:19

OdinEidolon
Member
From: Belluno - Italy
Registered: 2011-01-31
Posts: 498

Re: [SOLVED] A start job is running for udev wait for Complete Device I...

Same problem here since systemd update 216-3. My configuration is in my sig.
Thanks for the fix. I'd mark the thread as solved, masking a service is not a bad workaround.


Hardware: 2016 Dell XPS15 - matte FullHD - i5-6300HQ - 32GB DDR4 - Nvidia GTX960M - Samsung 840EVO 250GB SSD - 56Wh
Software: Plasma 5 - rEFInd - linux-ck - preload - prelink - verynice - psd - bumblebee

Offline

#7 2014-11-02 09:41:53

Carl Karl
Member
Registered: 2013-06-12
Posts: 231

Re: [SOLVED] A start job is running for udev wait for Complete Device I...

OK, thanks for your feedback.

Offline

#8 2014-11-03 22:34:12

seb0w
Member
Registered: 2013-03-18
Posts: 4

Re: [SOLVED] A start job is running for udev wait for Complete Device I...

Same problem here. The suggest soultion fixed my boot time. But still shouldn't be that reported as a bug?

Offline

#9 2014-12-06 07:28:19

Carl Karl
Member
Registered: 2013-06-12
Posts: 231

Re: [SOLVED] A start job is running for udev wait for Complete Device I...

As this happens still if I don't mask systemd-udev-settle, I reported a bug:
https://bugs.archlinux.org/task/43023

Offline

#10 2014-12-07 13:07:29

Carl Karl
Member
Registered: 2013-06-12
Posts: 231

Re: [SOLVED] A start job is running for udev wait for Complete Device I...

https://bugs.archlinux.org/task/43023#comment130570 :

seblu - Sunday, 07 December 2014, 01:56 GMT wrote:

On the acpid side, I pushed a new version acpid-2.0.23-4, which doesn't require udev to complete for starting.

With that new version of acpi, masking systemd-udev-settle is no longer necessary.

Offline

Board footer

Powered by FluxBB