Google Groups no longer supports new Usenet posts or subscriptions. Historical content remains viewable.
Dismiss

issue with systemd-udev-settle

470 views
Skip to first unread message

Matthias Bodenbinder

unread,
Apr 28, 2015, 2:10:04 AM4/28/15
to
Hi,

I installed debian 8 on one of my PCs and got into trouble with extra long boot times of > 2 min. I found out that it due to systemd-udev-settle.service. My PC is using lvm and that somehow interferes with systemd-udev-settle.service. The web tells that systemd-udev-settle.service is needed for lvm. Nevertheless I deactivated it with
systemctl mask systemd-udev-settle

The PC is booting fast now and the logical volumne is mounted just fine.

Q1) So what is the thing about systemd-udev-settle being needed for lvm? Do I miss something?
Q2) Is there a way to set a shorter timeout value for systemd-udev-settle.service?

Thanks
Matthias


--
To UNSUBSCRIBE, email to debian-us...@lists.debian.org
with a subject of "unsubscribe". Trouble? Contact listm...@lists.debian.org
Archive: https://lists.debian.org/mhn6vs$hlm$1...@ger.gmane.org

Christian Seiler

unread,
Apr 28, 2015, 6:30:04 AM4/28/15
to
Hi,

Am 2015-04-28 07:48, schrieb Matthias Bodenbinder:
> I installed debian 8 on one of my PCs and got into trouble with extra
> long boot times of > 2 min. I found out that it due to
> systemd-udev-settle.service. My PC is using lvm and that somehow
> interferes with systemd-udev-settle.service. The web tells that
> systemd-udev-settle.service is needed for lvm. Nevertheless I
> deactivated it with
> systemctl mask systemd-udev-settle
>
> The PC is booting fast now and the logical volumne is mounted just
> fine.
>
> Q1) So what is the thing about systemd-udev-settle being needed for
> lvm? Do I miss something?

The problem isn't mounting LVMs, systemd will do that once the devices
appear, so that's not a problem. The problem is rather that the backing
devices for LVM (phyiscal volumes) might not be available when the LVM
startup script is run - and then LVM is not activated at all (vgchange
doesn't work, since the device isn't there yet).

Note that if the LVM PV is on the same device as the root filesystem
(e.g. a different partition on the same drive/SSD or so), this will
never occur, because once the root filesystem is mounted, the drive
has to already have been probed. But if it's on another drive, it just
*might* happen that the LVM startup script is called too early.

So yes, udevadm settle (which is what this service calls) is required
if you have a script that needs devices to be there when it's run. It
is not necessarily required in all cases (e.g. if the root filesystem
is on the same drive/SSD), but if it's not there, it might cause
problems. Also, even if you don't have problems right now, it might
cause problems down the line, if you in a year or so decide to alter
something about your system (and then maybe don't remember you masked
this service). And this can also be hard to track down, because not
using udevadm settle just means that you are open to a potential race
condition, so it may work most of the time but every now and then it
might fail, if for some reason at that time the hardware decides to
take longer to probe or so.

Three additional things:

1. Not only the LVM startup script needs udevadm settle, but also
other things might, so masking it is probably a bad idea right now.

2. You can also use LVM in a different way: don't use the startup
script but rather use lvmetad, which will activate volumes when the
backing devices start to appear, which is much more in line with a
proper dynamic startup. To use that, set use_lvmetad = 1 in
/etc/lvm/lvm.conf. Two caveats: please read the comments and
apparently (I haven't tried it myself), it currently doesn't work in
Jessie, because of Bug #774082 [1].

3. Some other scripts might actually call udevadm settle themselves
regardless of this service, so if that hangs, masking the service
doesn't necessarily help you.

In the long term, udevadm settle should probably die and everything
should be able to pick up stuff dynamically (e.g. using lvmetad and
similar), but we're not quite there yet, so you should NOT mask
that service right now. In some future version it might disappear.

> Q2) Is there a way to set a shorter timeout value for
> systemd-udev-settle.service?

Direct answer to your question:

Create the directory
/etc/systemd/system/systemd-udev-settle.service.d
and create a file
/etc/systemd/system/systemd-udev-settle.service.d/timeout.conf
that contains the following contents:
----------------------------------------------
[Service]
ExecStart=
ExecStart=/bin/udevadm settle --timeout=60
----------------------------------------------
(The first line removes the default command of the service, the
second line sets the new command to be the one with the timeout.)

That said, I think that's a REALLY bad idea to do, because it just
tapers over the real, underlying problem. I've used Jessie with LVM
just fine (even in complicated setups with LVM on iSCSI and such),
so what you are seeing really shouldn't happen. There is some event
in udev's event queue that is not processed in time, which is why
it takes so long for your system to boot. The proper way to fix
this is to figure out what event that is and why that is happening.
Most likely this is a bug in an udev rule that only triggers on
very few systems, also possible is a hardware problem (in which
case you'd want to know about that earlier rather than late).

Therefore, you should try booting with the following kernel
options but with the settle service still enabled:
udev.log-priority=debug udev.children-max=1

Then you should be able to see in the logs (after waiting >2min
for the system to boot ;-)) which event udev couldn't handle. Post
those here and we might be able to find a proper solution to your
problem.

Christian

[1] https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=774082


--
To UNSUBSCRIBE, email to debian-us...@lists.debian.org
with a subject of "unsubscribe". Trouble? Contact listm...@lists.debian.org
Archive: https://lists.debian.org/45447c6a05a2d91a...@iwakd.de

Matthias Bodenbinder

unread,
Apr 29, 2015, 2:00:04 AM4/29/15
to
Hello Christian,

first of all many thanks for your very detailed reply. This was excellent!

I activated systemd-udev-settle again and want to debug the situtation
according to your instructions (with udev.log-priority etc.).

Here is the time consumption:

systemd-analyze blame:
######################
56.397s systemd-udev-settle.service
2.735s postfix.service
482ms NetworkManager.service
470ms lvm2-activation-early.service
456ms ModemManager.service
363ms systemd-logind.service
336ms alsa-restore.service
333ms rc-local.service
333ms speech-dispatcher.service
332ms pppd-dns.service
332ms exim4.service
330ms minidlna.service
328ms openvpn.service
326ms dovecot.service
251ms avahi-daemon.service
213ms networking.service
146ms keyboard-setup.service
136ms console-setup.service
126ms kdm.service
125ms systemd-modules-load.service
117ms systemd-fsck@dev-vol\x2dgrp1-lv_1.service
111ms
systemd-fsck@dev-disk-by\x2duuid-68a8248c\x2d38fd\x2d4d5c\x2d83fa\x2da2aff3ff9ce5.service
110ms kbd.service
97ms
systemd-fsck@dev-disk-by\x2duuid-22c1ca3a\x2dc781\x2d46b2\x2d98d3\x2de2a5733d68d2.service
90ms lvm2-monitor.service
84ms packagekit.service
73ms nfs-common.service
71ms saned.service
68ms rpcbind.service
58ms raid5.mount
52ms udisks2.service
44ms polkitd.service
43ms rsyslog.service
40ms systemd-user-sessions.service
38ms us...@1000.service
38ms colord.service
37ms systemd-udev-trigger.service
36ms
systemd-fsck@dev-disk-by\x2duuid-5085c7fb\x2d926d\x2d4f44\x2db8d0\x2d78b571f805d7.service
35ms lvm2-activation.service
28ms systemd-tmpfiles-setup-dev.service
26ms systemd-update-utmp.service
26ms systemd-journal-flush.service
25ms rtkit-daemon.service
24ms upower.service
22ms lvm2-pvscan@8:17.service
22ms media-data.mount
16ms media-data2.mount
15ms systemd-remount-fs.service
15ms dev-mqueue.mount
14ms sys-kernel-debug.mount
13ms systemd-setup-dgram-qlen.service
13ms dev-hugepages.mount
12ms systemd-tmpfiles-setup.service
11ms systemd-random-seed.service
8ms kmod-static-nodes.service
8ms sys-fs-fuse-connections.mount
8ms var-tmp.mount
8ms systemd-update-utmp-runlevel.service
8ms systemd-sysctl.service
7ms
dev-disk-by\x2duuid-13030826\x2d8987\x2d46c9\x2dbc1f\x2d8a9e9a4549c9.swap
7ms tmp.mount
6ms home.mount
5ms systemd-udevd.service
1ms udev-finish.service
################


But I am not really happy with the log since I find the following
statement when doing a journalctl -b:

#### start of log
Apr 29 06:51:55 xxx systemd-journal[164]: Runtime journal is using 8.0M
(max allowed 79.2M, trying to leave 118.8M free of 784.2M available →
current limit 79.2M).

....

Apr 29 06:52:19 xxx systemd-journal[164]: Forwarding to syslog missed
3819 messages.
Apr 29 06:52:25 xxx systemd-journal[164]: Suppressed 2818 messages from
/system.slice/systemd-udevd.service

####


Looks like I am missing plenty of udev log messages during the critical
phase of the boot process. Any idea what to do about it?

Thanks for your help.
Matthias


--
To UNSUBSCRIBE, email to debian-us...@lists.debian.org
with a subject of "unsubscribe". Trouble? Contact listm...@lists.debian.org
Archive: https://lists.debian.org/554068F4...@bodenbinder.de

Christian Seiler

unread,
Apr 29, 2015, 4:50:04 AM4/29/15
to
Am 2015-04-29 07:15, schrieb Matthias Bodenbinder:
> systemd-analyze blame:
> 56.397s systemd-udev-settle.service

Yeah, that shouldn't happen.

> But I am not really happy with the log since I find the following
> statement when doing a journalctl -b:
>
> #### start of log
> Apr 29 06:51:55 xxx systemd-journal[164]: Runtime journal is using
> 8.0M (max allowed 79.2M, trying to leave 118.8M free of 784.2M
> available → current limit 79.2M).
>
> ....
>
> Apr 29 06:52:19 xxx systemd-journal[164]: Forwarding to syslog missed
> 3819 messages.
> Apr 29 06:52:25 xxx systemd-journal[164]: Suppressed 2818 messages
> from /system.slice/systemd-udevd.service
>
> ####
>
>
> Looks like I am missing plenty of udev log messages during the
> critical phase of the boot process. Any idea what to do about it?

Ok, so basically you are running into a pathological case of Bug
#762700 [1]. A bit of explanation: journald forwards messages to
syslog by queuing them in the socket for syslog. However, syslog is
only started later in boot (after remote-fs.target, because /var
could be on network filesystems or so) - and thus messages will
only be queued until the kernel reaches a limit, further messages
will be dropped until syslog can actually start and process these
messages. The solution to the aforementioned bug was to increase
the limit from 11 to 513, which covers most cases. However, if at
early boot an uncharacteristic number of messages is generated,
even that limit will be reached.

In this case, because you activated udev debugging, udev will
generate a LOT of messages - and this will exceed the limit, since
udev is early-boot and udevadm-settle.service will have to be done
before syslog is started. (Typically, early-boot shouldn't log
even remotely as much.) Increasing the limit could help here, but
sine this is only for debugging, don't bother, because there's a
much simpler way:

Just use journalctl (without -b) to see all messages (they are
still in RAM in the journal - as per the log you posted, journald
will use up to 80 MiB [2] which is more than enough to keep all
3000 or so messages). Just look through them (there are going to
be a lot of debug messages from udev) and look at the timestamps.
There you'll be able to see where the delay happens - and maybe
you'll have a chance of figuring out, what the problem is. If
it's nothing obvious, just post the last 20 or so udev messages
before the large gap in the timestamps and every udev message
afterwards. If there is no gap and udev is constantly doing
something, take a look at what it's actually doing.

Christian

[1] https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=762700
[2] The limit depends on the amount of RAM you have, so this is
true on your computer, but not necessarily in general.


--
To UNSUBSCRIBE, email to debian-us...@lists.debian.org
with a subject of "unsubscribe". Trouble? Contact listm...@lists.debian.org
Archive: https://lists.debian.org/c0e09974329c8f04...@iwakd.de

Michael Biebl

unread,
Apr 29, 2015, 9:50:03 AM4/29/15
to
Am 29.04.2015 um 10:32 schrieb Christian Seiler:
> Am 2015-04-29 07:15, schrieb Matthias Bodenbinder:
>> systemd-analyze blame:
>> 56.397s systemd-udev-settle.service
>
> Yeah, that shouldn't happen.

Matthias, do you have any custom udev rules in /etc/udev/rules.d/?
Is this an upgraded or freshly installed system?



--
Why is it that all of the instruments seeking intelligent life in the
universe are pointed away from Earth?

signature.asc

Matthias Bodenbinder

unread,
Apr 29, 2015, 1:00:05 PM4/29/15
to
Am 29.04.2015 um 15:28 schrieb Michael Biebl:
> Am 29.04.2015 um 10:32 schrieb Christian Seiler:
>> Am 2015-04-29 07:15, schrieb Matthias Bodenbinder:
>>> systemd-analyze blame:
>>> 56.397s systemd-udev-settle.service
>>
>> Yeah, that shouldn't happen.
>
> Matthias, do you have any custom udev rules in /etc/udev/rules.d/?
> Is this an upgraded or freshly installed system?
>
>
>

This is a clean install. I tried to upgrade from wheezy but could not
boot afterwards. boot eror "init not found" and I was left with and
initramd shell. I could not fix that so I made a clean install.

/etc/udev/rules.d/ has only one file:

xxx - root - /etc/udev/rules.d
17# cat 70-persistent-net.rules
# This file was automatically generated by the /lib/udev/write_net_rules
# program, run by the persistent-net-generator.rules rules file.
#
# You can modify it, as long as you keep each rule on a single
# line, and change only the value of the NAME= key.

# PCI device 0x10ec:0x8168 (r8169)
SUBSYSTEM=="net", ACTION=="add", DRIVERS=="?*",
ATTR{address}=="00:24:1d:d6:df:5f", ATTR{dev_id}=="0x0",
ATTR{type}=="1", KERNEL=="eth*", NAME="eth0"

Matthias


--
To UNSUBSCRIBE, email to debian-us...@lists.debian.org
with a subject of "unsubscribe". Trouble? Contact listm...@lists.debian.org
Archive: https://lists.debian.org/mhr1i8$f41$1...@ger.gmane.org

Matthias Bodenbinder

unread,
Apr 29, 2015, 1:10:05 PM4/29/15
to
Am 29.04.2015 um 10:32 schrieb Christian Seiler:
> Just use journalctl (without -b) to see all messages (they are
> still in RAM in the journal - as per the log you posted, journald
> will use up to 80 MiB [2] which is more than enough to keep all
> 3000 or so messages). Just look through them (there are going to
> be a lot of debug messages from udev) and look at the timestamps.
> There you'll be able to see where the delay happens - and maybe
> you'll have a chance of figuring out, what the problem is. If
> it's nothing obvious, just post the last 20 or so udev messages
> before the large gap in the timestamps and every udev message
> afterwards. If there is no gap and udev is constantly doing
> something, take a look at what it's actually doing.

No way. Just using journalctl makes no difference:

Apr 29 18:45:08 xxx systemd-journal[170]: Forwarding to syslog missed
3819 messages.
Apr 29 18:45:14 xxx systemd-journal[170]: Suppressed 2818 messages from
/system.slice/systemd-udevd.service

And this is exactly the time period where I would expect the issue to
pop up.

Any other idea?
Matthias



--
To UNSUBSCRIBE, email to debian-us...@lists.debian.org
with a subject of "unsubscribe". Trouble? Contact listm...@lists.debian.org
Archive: https://lists.debian.org/mhr2a3$vu4$1...@ger.gmane.org

Christian Seiler

unread,
Apr 29, 2015, 1:40:05 PM4/29/15
to
On 04/29/2015 06:53 PM, Matthias Bodenbinder wrote:
> Am 29.04.2015 um 10:32 schrieb Christian Seiler:
>> Just use journalctl (without -b) to see all messages (they are
>> still in RAM in the journal - as per the log you posted, journald
>> will use up to 80 MiB [2] which is more than enough to keep all
>> 3000 or so messages). Just look through them (there are going to
>> be a lot of debug messages from udev) and look at the timestamps.
>> There you'll be able to see where the delay happens - and maybe
>> you'll have a chance of figuring out, what the problem is. If
>> it's nothing obvious, just post the last 20 or so udev messages
>> before the large gap in the timestamps and every udev message
>> afterwards. If there is no gap and udev is constantly doing
>> something, take a look at what it's actually doing.
>
> No way. Just using journalctl makes no difference:
>
> Apr 29 18:45:08 xxx systemd-journal[170]: Forwarding to syslog missed
> 3819 messages.
> Apr 29 18:45:14 xxx systemd-journal[170]: Suppressed 2818 messages from
> /system.slice/systemd-udevd.service
>
> And this is exactly the time period where I would expect the issue to
> pop up.

Ah, I only noticed the first message about syslog forwarding. The second
message tells us that rate limiting has kicked in, because udev just
generates a TON of messages in a short time.

Just for the purpose of debugging, could you increase RateLimitBurst to
10000 or so (i.e. 10x the default value) in /etc/systemd/journald.conf
and reboot? (Set it back again after you're done deubgging, else your
logs might get flooded.)

Christian


--
To UNSUBSCRIBE, email to debian-us...@lists.debian.org
with a subject of "unsubscribe". Trouble? Contact listm...@lists.debian.org
Archive: https://lists.debian.org/55411381...@iwakd.de

Matthias Bodenbinder

unread,
Apr 30, 2015, 2:20:04 AM4/30/15
to
Am 29.04.2015 um 19:23 schrieb Christian Seiler:
> Just for the purpose of debugging, could you increase RateLimitBurst to
> 10000 or so (i.e. 10x the default value) in /etc/systemd/journald.conf
> and reboot? (Set it back again after you're done deubgging, else your
> logs might get flooded.)

The 10000 value did not help. I deactivated any limits:
RateLimitInterval=0
RateLimitBurst=0


Here is what I found:
Start of log is at Apr 30 07:27:55

Apr 30 07:27:55 xxx systemd-udevd[60]: starting version 215

# then it is working on all partitions.
# sdc is an SSD
# sdc2 is swap
# sdb1 is lvm

Apr 30 07:27:55 xxx systemd-udevd[175]: device 0x7f6bbb28f7b0 has
devpath
'/devices/pci0000:00/0000:00:11.0/ata2/host1/target1:0:0/1:0:0:0/block/sdb/sdb1'
Apr 30 07:27:55 xxx systemd-udevd[175]: restoring old watch on '/dev/sdb1'
Apr 30 07:27:55 xxx systemd-udevd[175]: adding watch on '/dev/sdb1'

....

Apr 30 07:27:55 xxx systemd-udevd[175]: device 0x7f6bbb28f7b0 has
devpath
'/devices/pci0000:00/0000:00:11.0/ata3/host2/target2:0:0/2:0:0:0/block/sdc/sdc3'
Apr 30 07:27:55 xxx systemd-udevd[175]: restoring old watch on '/dev/sdc3'
Apr 30 07:27:55 xxx systemd-udevd[175]: adding watch on '/dev/sdc3'

....

# there are hundreds of udev message for the next 5 sec until 07:28:00
# then there are only a few udev messages for the next 50 sec until 07:28:50
# before hundreds of udev messages start again

....

Apr 30 07:28:01 xxx systemd-udevd[175]: seq 1598 queued, 'add' 'input'
Apr 30 07:28:01 xxx systemd-udevd[175]: seq 1599 queued, 'add' 'input'
Apr 30 07:28:01 xxx systemd-udevd[175]: seq 1600 queued, 'add' 'input'
Apr 30 07:28:01 xxx systemd-udevd[175]: seq 1601 queued, 'add' 'input'
Apr 30 07:28:01 xxx systemd-udevd[175]: seq 1602 queued, 'add' 'input'
Apr 30 07:28:04 xxx systemd-udevd[175]: validate module index
Apr 30 07:28:04 xxx systemd-udevd[175]: Check if link configuration
needs reloading.
Apr 30 07:28:07 xxx systemd-udevd[175]: validate module index
Apr 30 07:28:07 xxx systemd-udevd[175]: Check if link configuration
needs reloading.
Apr 30 07:28:10 xxx systemd-udevd[175]: validate module index
Apr 30 07:28:10 xxx systemd-udevd[175]: Check if link configuration
needs reloading.
Apr 30 07:28:13 xxx systemd-udevd[175]: validate module index
Apr 30 07:28:13 xxx systemd-udevd[175]: Check if link configuration
needs reloading.
Apr 30 07:28:16 xxx systemd-udevd[175]: validate module index
Apr 30 07:28:16 xxx systemd-udevd[175]: Check if link configuration
needs reloading.
Apr 30 07:28:19 xxx systemd-udevd[175]: validate module index
Apr 30 07:28:19 xxx systemd-udevd[175]: Check if link configuration
needs reloading.
Apr 30 07:28:19 xxx systemd-journal[170]: Forwarding to syslog missed
3809 messages.
Apr 30 07:28:22 xxx systemd-udevd[175]: validate module index
Apr 30 07:28:22 xxx systemd-udevd[175]: Check if link configuration
needs reloading.
Apr 30 07:28:25 xxx systemd-udevd[175]: validate module index
Apr 30 07:28:25 xxx systemd-udevd[175]: Check if link configuration
needs reloading.
Apr 30 07:28:28 xxx systemd-udevd[175]: validate module index
Apr 30 07:28:28 xxx systemd-udevd[175]: Check if link configuration
needs reloading.
Apr 30 07:28:31 xxx systemd-udevd[175]: worker [196]
/devices/pci0000:00/0000:00:12.2/usb1/1-4/1-4.4/1-4.4:1.0 timeout; kill it
Apr 30 07:28:31 xxx systemd-udevd[175]: seq 1229
'/devices/pci0000:00/0000:00:12.2/usb1/1-4/1-4.4/1-4.4:1.0' killed
Apr 30 07:28:31 xxx systemd-udevd[175]: validate module index
Apr 30 07:28:31 xxx systemd-udevd[175]: Check if link configuration
needs reloading.
Apr 30 07:28:34 xxx systemd-udevd[175]: validate module index
Apr 30 07:28:34 xxx systemd-udevd[175]: Check if link configuration
needs reloading.
Apr 30 07:28:37 xxx systemd-udevd[175]: validate module index
Apr 30 07:28:37 xxx systemd-udevd[175]: Check if link configuration
needs reloading.
Apr 30 07:28:40 xxx systemd-udevd[175]: validate module index
Apr 30 07:28:40 xxx systemd-udevd[175]: Check if link configuration
needs reloading.
Apr 30 07:28:43 xxx systemd-udevd[175]: validate module index
Apr 30 07:28:43 xxx systemd-udevd[175]: Check if link configuration
needs reloading.
Apr 30 07:28:46 xxx systemd-udevd[175]: validate module index
Apr 30 07:28:46 xxx systemd-udevd[175]: Check if link configuration
needs reloading.
Apr 30 07:28:49 xxx systemd-udevd[175]: validate module index
Apr 30 07:28:49 xxx systemd-udevd[175]: Check if link configuration
needs reloading.
Apr 30 07:28:49 xxx systemd-journal[170]: Forwarding to syslog missed 22
messages.
Apr 30 07:28:50 xxx kernel: usbcore: registered new interface driver
snd-usb-audio
Apr 30 07:28:50 xxx systemd-udevd[175]: seq 1603 queued, 'add' 'sound'
Apr 30 07:28:50 xxx systemd-udevd[175]: seq 1604 queued, 'add' 'sound'
Apr 30 07:28:50 xxx systemd-udevd[175]: worker [196] exit
Apr 30 07:28:50 xxx systemd-udevd[175]: worker [196] terminated by
signal 9 (Killed)
Apr 30 07:28:50 xxx systemd-udevd[175]: worker [196] cleaned up
Apr 30 07:28:50 xxx systemd-udevd[175]: seq 1605 queued, 'add' 'sound'
Apr 30 07:28:50 xxx systemd-udevd[175]: seq 1230 forked new worker [269]
Apr 30 07:28:50 xxx systemd-udevd[175]: seq 1606 queued, 'add' 'sound'
Apr 30 07:28:50 xxx systemd-udevd[269]: seq 1230 running
Apr 30 07:28:50 xxx systemd-udevd[269]: no db file to read
/run/udev/data/+usb:1-4.4:1.1: No such file or directory
Apr 30 07:28:50 xxx systemd-udevd[269]: device 0x7f6bbb2bfba0 has
devpath '/devices/pci0000:00/0000:00:12.2/usb1/1-4/1-4.4'
Apr 30 07:28:50 xxx systemd-udevd[269]: device 0x7f6bbb325c00 has
devpath '/devices/pci0000:00/0000:00:12.2/usb1/1-4'
Apr 30 07:28:50 xxx systemd-udevd[269]: device 0x7f6bbb3266d0 has
devpath '/devices/pci0000:00/0000:00:12.2/usb1'
Apr 30 07:28:50 xxx systemd-udevd[269]: device 0x7f6bbb3270e0 has
devpath '/devices/pci0000:00/0000:00:12.2'
Apr 30 07:28:50 xxx systemd-udevd[269]: device 0x7f6bbb327e20 has
devpath '/devices/pci0000:00'
Apr 30 07:28:50 xxx systemd-udevd[269]: IMPORT builtin 'hwdb'
/lib/udev/rules.d/50-udev-default.rules:11

####

udev seems to pause for a long time with very few messages until it
kicks in again at about 07:28:50. One of first message before it kicks
in again is:

Apr 30 07:28:50 xxx kernel: usbcore: registered new interface driver
snd-usb-audio
Apr 30 07:28:50 xxx systemd-udevd[175]: seq 1603 queued, 'add' 'sound'
Apr 30 07:28:50 xxx systemd-udevd[175]: seq 1604 queued, 'add' 'sound'

I am wondering if this can have something to do with my usb keyboard
which happens to have a sound module with audio in and out for headset
and mic. And it is also a USB hub where the mouse is connected:

52: USB 00.0: 10503 USB Mouse
[Created at usb.122]
Unique ID: __6e.ykItPQs8ue8
Parent ID: Uc5H.TI3vE1oZtwF
SysFS ID: /devices/pci0000:00/0000:00:12.2/usb1/1-4/1-4.1/1-4.1:1.0
SysFS BusID: 1-4.1:1.0
Hardware Class: mouse
Model: "KYE NetScroll+ Traveler"
Hotplug: USB
Vendor: usb 0x0458 "KYE Systems"
Device: usb 0x002e "NetScroll+ Traveler"
Compatible to: int 0x0200 0x0001 "Generic USB Mouse"
Driver: "usbhid"
Driver Modules: "usbhid"
Speed: 1.5 Mbps
Module Alias: "usb:v0458p002Ed0000dc00dsc00dp00ic03isc01ip02in00"
Driver Info #0:
XFree86 Protocol: explorerps/2
GPM Protocol: exps2
Config Status: cfg=new, avail=yes, need=no, active=unknown
Attached to: #62 (Hub)

53: USB 00.0: 10800 Keyboard
[Created at usb.122]
Unique ID: sFNz.BMubaYkkWv5
Parent ID: Uc5H.TI3vE1oZtwF
SysFS ID: /devices/pci0000:00/0000:00:12.2/usb1/1-4/1-4.3/1-4.3:1.0
SysFS BusID: 1-4.3:1.0
Hardware Class: keyboard
Model: "Monterey International Keyboard"
Hotplug: USB
Vendor: usb 0x0566 "Monterey International Corp."
Device: usb 0x3108
Revision: "3.01"
Driver: "usbhid"
Driver Modules: "usbhid"
Speed: 1.5 Mbps
Module Alias: "usb:v0566p3108d0301dc00dsc00dp00ic03isc01ip01in00"
Driver Info #0:
XkbRules: xfree86
XkbModel: pc104
Config Status: cfg=new, avail=yes, need=no, active=unknown
Attached to: #62 (Hub)

54: USB 00.1: 0000 Unclassified device
[Created at usb.122]
Unique ID: JRd1.wSzlx4YKRyF
Parent ID: Uc5H.TI3vE1oZtwF
SysFS ID: /devices/pci0000:00/0000:00:12.2/usb1/1-4/1-4.3/1-4.3:1.1
SysFS BusID: 1-4.3:1.1
Hardware Class: unknown
Model: "Monterey International Unclassified device"
Hotplug: USB
Vendor: usb 0x0566 "Monterey International Corp."
Device: usb 0x3108
Revision: "3.01"
Driver: "usbhid"
Driver Modules: "usbhid"
Speed: 1.5 Mbps
Module Alias: "usb:v0566p3108d0301dc00dsc00dp00ic03isc00ip00in01"
Driver Info #0:
Driver Status: usbhid is active
Driver Activation Cmd: "modprobe usbhid"
Config Status: cfg=new, avail=yes, need=no, active=unknown
Attached to: #62 (Hub)

55: USB 00.0: 0401 Multimedia audio controller
[Created at usb.122]
Unique ID: IO+7.DGe+0l9GPv1
Parent ID: Uc5H.TI3vE1oZtwF
SysFS ID: /devices/pci0000:00/0000:00:12.2/usb1/1-4/1-4.4/1-4.4:1.0
SysFS BusID: 1-4.4:1.0
Hardware Class: sound
Model: "Elan Microelectronics USB Audio"
Hotplug: USB
Vendor: usb 0x04f3 "Elan Microelectronics Corp."
Device: usb 0x0a11 "USB Audio"
Revision: "1.00"
Driver: "snd-usb-audio"
Driver Modules: "snd_usb_audio"
Speed: 12 Mbps
Module Alias: "usb:v04F3p0A11d0100dc00dsc00dp00ic01isc01ip00in00"
Driver Info #0:
Driver Status: snd_usb_audio is active
Driver Activation Cmd: "modprobe snd_usb_audio"
Config Status: cfg=new, avail=yes, need=no, active=unknown
Attached to: #62 (Hub)

58: USB 00.3: 0000 Unclassified device
[Created at usb.122]
Unique ID: fwlK.e6_dCN4Dx+9
Parent ID: Uc5H.TI3vE1oZtwF
SysFS ID: /devices/pci0000:00/0000:00:12.2/usb1/1-4/1-4.4/1-4.4:1.3
SysFS BusID: 1-4.4:1.3
Hardware Class: unknown
Model: "Elan Microelectronics USB Audio"
Hotplug: USB
Vendor: usb 0x04f3 "Elan Microelectronics Corp."
Device: usb 0x0a11 "USB Audio"
Revision: "1.00"
Driver: "usbhid"
Driver Modules: "usbhid"
Speed: 12 Mbps
Module Alias: "usb:v04F3p0A11d0100dc00dsc00dp00ic03isc00ip00in03"
Driver Info #0:
Driver Status: usbhid is active
Driver Activation Cmd: "modprobe usbhid"
Config Status: cfg=new, avail=yes, need=no, active=unknown
Attached to: #62 (Hub)


Does that help?

Matthias







--
To UNSUBSCRIBE, email to debian-us...@lists.debian.org
with a subject of "unsubscribe". Trouble? Contact listm...@lists.debian.org
Archive: https://lists.debian.org/mhsg4m$uo5$1...@ger.gmane.org

Michael Biebl

unread,
Apr 30, 2015, 9:30:05 AM4/30/15
to
Am 30.04.2015 um 07:55 schrieb Matthias Bodenbinder:
> Apr 30 07:28:31 xxx systemd-udevd[175]: worker [196]
> /devices/pci0000:00/0000:00:12.2/usb1/1-4/1-4.4/1-4.4:1.0 timeout; kill it
> Apr 30 07:28:31 xxx systemd-udevd[175]: seq 1229
> '/devices/pci0000:00/0000:00:12.2/usb1/1-4/1-4.4/1-4.4:1.0' killed


> 55: USB 00.0: 0401 Multimedia audio controller
> [Created at usb.122]
> Unique ID: IO+7.DGe+0l9GPv1
> Parent ID: Uc5H.TI3vE1oZtwF
> SysFS ID: /devices/pci0000:00/0000:00:12.2/usb1/1-4/1-4.4/1-4.4:1.0


> ####
>
> udev seems to pause for a long time with very few messages until it
> kicks in again at about 07:28:50. One of first message before it kicks
> in again is:
>
> Apr 30 07:28:50 xxx kernel: usbcore: registered new interface driver
> snd-usb-audio
> Apr 30 07:28:50 xxx systemd-udevd[175]: seq 1603 queued, 'add' 'sound'
> Apr 30 07:28:50 xxx systemd-udevd[175]: seq 1604 queued, 'add' 'sound'
>
> I am wondering if this can have something to do with my usb keyboard
> which happens to have a sound module with audio in and out for headset
> and mic. And it is also a USB hub where the mouse is connected:

As you can see above, systemd-udevd timeouts processing the events from
that device and is eventually killed. The internal timeout for udev is
90s. If you add the the remaining time to boot the system, that would
explain the 2min boot times.

This looks like either buggy hardware or a bug in the kernel.

Can you try with a different keyboard and mouse directly attached to
your computer, not via a hub?
signature.asc

Matthias Bodenbinder

unread,
Apr 30, 2015, 11:20:05 AM4/30/15
to
Am 30.04.2015 um 15:09 schrieb Michael Biebl:
> As you can see above, systemd-udevd timeouts processing the events from
> that device and is eventually killed. The internal timeout for udev is
> 90s. If you add the the remaining time to boot the system, that would
> explain the 2min boot times.
>
> This looks like either buggy hardware or a bug in the kernel.
>
> Can you try with a different keyboard and mouse directly attached to
> your computer, not via a hub?

Yes, that is it.

It is the keyboard! I tried a different one and the computer boots fast.

The keyboard is not new. I had it running on the same computer for
several years. All with debian wheezy. No problems. Why is that now? I
doubt that this is a hw issue although I have never tested the sound
module in that keyboard.

What can I do about it? I like this keyboard. I do not want to replace
it. Can I deactivate probing for usb sound?

Matthias





--
To UNSUBSCRIBE, email to debian-us...@lists.debian.org
with a subject of "unsubscribe". Trouble? Contact listm...@lists.debian.org
Archive: https://lists.debian.org/mhtfs7$r27$1...@ger.gmane.org

Matthias Bodenbinder

unread,
Apr 30, 2015, 1:50:05 PM4/30/15
to
Am 30.04.2015 um 16:57 schrieb Matthias Bodenbinder:
> Am 30.04.2015 um 15:09 schrieb Michael Biebl:
>> As you can see above, systemd-udevd timeouts processing the events from
>> that device and is eventually killed. The internal timeout for udev is
>> 90s. If you add the the remaining time to boot the system, that would
>> explain the 2min boot times.
>>
>> This looks like either buggy hardware or a bug in the kernel.
>>
>> Can you try with a different keyboard and mouse directly attached to
>> your computer, not via a hub?
>
> Yes, that is it.
>
> It is the keyboard! I tried a different one and the computer boots fast.
>
> The keyboard is not new. I had it running on the same computer for several years. All with debian wheezy. No problems. Why is that now? I doubt that this is a hw issue although I have never tested the sound module in that keyboard.
>
> What can I do about it? I like this keyboard. I do not want to replace it. Can I deactivate probing for usb sound?
>
> Matthias

I tested the keyboard on a different PC with a current debian testing instalation and the issue is more or less the same. Except for the waiting time. On the debian testing machine I have to wait less than 50% of the time than on the other PC. Strange? Is that CPU performance dependent or was the timing changed between Jessie and debian testing?

Anyways, I would like to deactivate the sound device in that keyboard so that udev is not waiting anymore. But how?

Matthias



--
To UNSUBSCRIBE, email to debian-us...@lists.debian.org
with a subject of "unsubscribe". Trouble? Contact listm...@lists.debian.org
Archive: https://lists.debian.org/mhtolt$m4o$1...@ger.gmane.org

Ric Moore

unread,
Apr 30, 2015, 4:50:04 PM4/30/15
to
On 04/30/2015 01:27 PM, Matthias Bodenbinder wrote:
> Am 30.04.2015 um 16:57 schrieb Matthias Bodenbinder:
>> Am 30.04.2015 um 15:09 schrieb Michael Biebl:
>>> As you can see above, systemd-udevd timeouts processing the events from
>>> that device and is eventually killed. The internal timeout for udev is
>>> 90s. If you add the the remaining time to boot the system, that would
>>> explain the 2min boot times.
>>>
>>> This looks like either buggy hardware or a bug in the kernel.
>>>
>>> Can you try with a different keyboard and mouse directly attached to
>>> your computer, not via a hub?
>>
>> Yes, that is it.
>>
>> It is the keyboard! I tried a different one and the computer boots fast.
>>
>> The keyboard is not new. I had it running on the same computer for several years. All with debian wheezy. No problems. Why is that now? I doubt that this is a hw issue although I have never tested the sound module in that keyboard.
>>
>> What can I do about it? I like this keyboard. I do not want to replace it. Can I deactivate probing for usb sound?
>>
>> Matthias
>
> I tested the keyboard on a different PC with a current debian testing instalation and the issue is more or less the same. Except for the waiting time. On the debian testing machine I have to wait less than 50% of the time than on the other PC. Strange? Is that CPU performance dependent or was the timing changed between Jessie and debian testing?
>
> Anyways, I would like to deactivate the sound device in that keyboard so that udev is not waiting anymore. But how?

Didja try using alsamixer to mute it? ...and see if that helps? Maybe
someone can post how to blacklist the device completely? Ric


--
My father, Victor Moore (Vic) used to say:
"There are two Great Sins in the world...
..the Sin of Ignorance, and the Sin of Stupidity.
Only the former may be overcome." R.I.P. Dad.
http://linuxcounter.net/user/44256.html


--
To UNSUBSCRIBE, email to debian-us...@lists.debian.org
with a subject of "unsubscribe". Trouble? Contact listm...@lists.debian.org
Archive: https://lists.debian.org/5542907...@gmail.com

Michael Biebl

unread,
Apr 30, 2015, 6:20:05 PM4/30/15
to
Am 30.04.2015 um 16:57 schrieb Matthias Bodenbinder:

> It is the keyboard! I tried a different one and the computer boots fast.
>
> The keyboard is not new. I had it running on the same computer for
> several years. All with debian wheezy. No problems. Why is that now? I
> doubt that this is a hw issue although I have never tested the sound
> module in that keyboard.

Maybe the wheezy kernel didn't support that particular kind of hardware
yet, so simply ignored it.

> What can I do about it? I like this keyboard. I do not want to replace
> it. Can I deactivate probing for usb sound?

Can you deactivate the sound functionality in your keyboard? Maybe there
is a hardware switch for this.

You could try blacklisting "snd-usb-audio" via
$ echo "blacklist snd-usb-audio" > /etc/modprobe.d/no-usb-audio.conf

Maybe that helps (you might need to rebuild your initramfs as well)
signature.asc

Matthias Bodenbinder

unread,
May 1, 2015, 1:30:04 AM5/1/15
to
Am 01.05.2015 um 00:00 schrieb Michael Biebl:
> You could try blacklisting "snd-usb-audio" via
> $ echo "blacklist snd-usb-audio" > /etc/modprobe.d/no-usb-audio.conf
>
> Maybe that helps (you might need to rebuild your initramfs as well)


This did the trick. The sound is disabled, the boot is fast and the usb
hub in the keyboard is still working. Perfect!.

Thank you all so much for your support.

Matthias


--
To UNSUBSCRIBE, email to debian-us...@lists.debian.org
with a subject of "unsubscribe". Trouble? Contact listm...@lists.debian.org
Archive: https://lists.debian.org/mhv1r0$afe$1...@ger.gmane.org

Michael Biebl

unread,
May 1, 2015, 3:00:04 AM5/1/15
to
Am 01.05.2015 um 07:09 schrieb Matthias Bodenbinder:
> Am 01.05.2015 um 00:00 schrieb Michael Biebl:
>> You could try blacklisting "snd-usb-audio" via
>> $ echo "blacklist snd-usb-audio" > /etc/modprobe.d/no-usb-audio.conf
>>
>> Maybe that helps (you might need to rebuild your initramfs as well)
>
>
> This did the trick. The sound is disabled, the boot is fast and the usb
> hub in the keyboard is still working. Perfect!.

It's a workaround.
So it might still be worth a bug report against the linux kernel.
signature.asc

Matthias Bodenbinder

unread,
May 1, 2015, 9:10:05 AM5/1/15
to
Am 01.05.2015 um 08:36 schrieb Michael Biebl:
> It's a workaround.
> So it might still be worth a bug report against the linux kernel.

I did that:

Bug#783934: Acknowledgement (linux-image-3.16.0-4-amd64:
systemd-udev-settle waiting 50 s during boot for snd-usb-audio)

https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=783934

Matthias


--
To UNSUBSCRIBE, email to debian-us...@lists.debian.org
with a subject of "unsubscribe". Trouble? Contact listm...@lists.debian.org
Archive: https://lists.debian.org/mhvsu2$7oi$1...@ger.gmane.org
0 new messages