Re: Debugging udevd startup time

["Ozan Çağlayan" <ozan@pardus.org.tr>]

Kay Sievers wrote:
> In many cases it's the loading of modules which is pretty expensive.
> Sometimes rules are doing weird things. Sometimes just a single device
> blocks the wait-for-all settle call.
>
> On the box with the 3 seconds, what devices are left when you limit the timeout?
>   udevadm trigger; udevadm settle --timeout=2
>   

The above command outputs nothing,

> How long does udev take on the running box?
>   

I captured the output of the monitor during the above command, here's
the first KERNEL event and the last UDEV event on the running system:

KERNEL[1242835745.179673] add      /devices/LNXSYSTM:00 (acpi)
UDEV  [1242835748.458242] add     
/devices/pci0000:00/0000:00:06.0/usb4/4-1/4-1.1/4-1.1:1.0/bluetooth/hci0
(bluetooth)

> What does:
>  $ time (udevadm trigger -Snet; udevadm settle)
> print? That should show the time while no more modules need to be loaded.
>   

mecbuk cups # time (udevadm trigger; udevadm settle)

real    0m2.579s
user    0m0.013s
sys     0m0.011s

Subsequent calls shows 1.7~, 1.5~, 1.9~, 2.0~ seconds.

> How big are the rules you use?
>   wc -l /etc/udev/rules.d/* /lib/udev/rules.d/* /dev/.udev/rules.d/*
>   
mecbuk cups # wc -l /lib/udev/rules.d/* /etc/udev/rules.d/*
/dev/.udev/rules.d/* | tail -n1
wc: /dev/.udev/rules.d/*: No such file or directory
  1817 total

A typical udev, udev-extras installation + 1-2 extra rules like gphoto2,
wacom, bluez, etc.

> What does:
>   udevadm test foo
> print?
>   

mecbuk cups # udevadm test
foo                                                            
run_command: calling:
test                                                                
udevadm_test: version
142                                                                 
This program is for debugging only, it does not run any program,
specified by a RUN key. It may show incorrect results, because
some values may be different, or not available at a simulation run.

parse_file: reading '/lib/udev/rules.d/10-lirc.rules' as rules file
parse_file: reading '/lib/udev/rules.d/40-alsa.rules' as rules file
parse_file: reading '/lib/udev/rules.d/40-gentoo.rules' as rules file
parse_file: reading '/lib/udev/rules.d/40-ia64.rules' as rules file
parse_file: reading '/lib/udev/rules.d/40-infiniband.rules' as rules file
parse_file: reading '/lib/udev/rules.d/40-isdn.rules' as rules file
parse_file: reading '/lib/udev/rules.d/40-pilot-links.rules' as rules file
parse_file: reading '/lib/udev/rules.d/40-zaptel.rules' as rules file
parse_file: reading '/lib/udev/rules.d/50-firmware.rules' as rules file
parse_file: reading '/lib/udev/rules.d/50-udev-default.rules' as rules file
parse_file: reading '/lib/udev/rules.d/60-cdrom_id.rules' as rules file
parse_file: reading '/etc/udev/rules.d/60-libgphoto2.rules' as rules file
parse_file: reading '/lib/udev/rules.d/60-logitechmouse.rules' as rules file
parse_file: reading '/lib/udev/rules.d/60-pcmcia.rules' as rules file
parse_file: reading '/lib/udev/rules.d/60-persistent-input.rules' as
rules file
parse_file: reading '/lib/udev/rules.d/60-persistent-serial.rules' as
rules file
parse_file: reading '/lib/udev/rules.d/60-persistent-storage-tape.rules'
as rules file
parse_file: reading '/lib/udev/rules.d/60-persistent-storage.rules' as
rules file
parse_file: reading '/lib/udev/rules.d/60-persistent-v4l.rules' as rules
file
parse_file: reading '/lib/udev/rules.d/60-wacom.rules' as rules file
parse_file: reading '/lib/udev/rules.d/61-mobile-action.rules' as rules file
parse_file: reading '/lib/udev/rules.d/61-option-modem-modeswitch.rules'
as rules file
parse_file: reading '/lib/udev/rules.d/61-persistent-storage-edd.rules'
as rules file
parse_file: reading '/lib/udev/rules.d/64-device-mapper.rules' as rules file
parse_file: reading '/lib/udev/rules.d/64-md-raid.rules' as rules file
parse_file: reading '/lib/udev/rules.d/70-acl.rules' as rules file
parse_file: reading '/lib/udev/rules.d/70-bluetooth.rules' as rules file
parse_file: reading '/etc/udev/rules.d/70-persistent-cd.rules' as rules file
parse_file: reading '/etc/udev/rules.d/70-persistent-net.rules' as rules
file
parse_file: reading '/lib/udev/rules.d/75-cd-aliases-generator.rules' as
rules file
parse_file: reading
'/lib/udev/rules.d/75-persistent-net-generator.rules' as rules file
parse_file: reading '/lib/udev/rules.d/78-sound-card.rules' as rules file
parse_file: reading '/lib/udev/rules.d/80-drivers.rules' as rules file
parse_file: reading '/lib/udev/rules.d/90-hal.rules' as rules file
parse_file: reading '/lib/udev/rules.d/91-drm-modeset.rules' as rules file
parse_file: reading '/lib/udev/rules.d/95-udev-late.rules' as rules file
parse_file: reading '/lib/udev/rules.d/97-bluetooth-pcmcia.rules' as
rules file
parse_file: reading '/lib/udev/rules.d/99-comar-ethernet.rules' as rules
file
parse_file: reading '/lib/udev/rules.d/99-comar-wireless.rules' as rules
file
parse_file: reading '/lib/udev/rules.d/99-fuse.rules' as rules file
udev_rules_new: rules use 78048 bytes tokens (6504 * 12 bytes), 17584
bytes buffer
udev_rules_new: temporary index used 28500 bytes (1425 * 20 bytes)