Debugging udevd startup time

Debugging udevd startup time

[Ozan Çağlayan]

Hi,

I wonder how can I debug the possible bottleneck(s) during the startup
of udevd?

I'm writing the $(udevadm --monitor)'s output to a log file during boot
and I have the exact events and timestamps. I really don't understand
why the whole process takes a bunch of seconds.

I'm using 2.6.30_rc6 + udev 141.

It's a typical default udev installation. (compiled with -O2),

Any help or comment on the subject would be really appreciated, I'm also
sending a link to the complete monitor.log:

http://cekirdek.pardus.org.tr/~ozan/udevmonitor.log


Thanks
Ozan Caglayan

http://www.pardus.org.tr/eng

Re: Debugging udevd startup time

[Alan Jenkins]

On 5/19/09, Ozan Çaðlayan <ozan@pardus.org.tr> wrote:
> Hi,
>
> I wonder how can I debug the possible bottleneck(s) during the startup
> of udevd?
>
> I'm writing the $(udevadm --monitor)'s output to a log file during boot
> and I have the exact events and timestamps. I really don't understand
> why the whole process takes a bunch of seconds.
>
> I'm using 2.6.30_rc6 + udev 141.
>
> It's a typical default udev installation. (compiled with -O2),
>
> Any help or comment on the subject would be really appreciated, I'm also
> sending a link to the complete monitor.log:
>
> http://cekirdek.pardus.org.tr/~ozan/udevmonitor.log

One word: bootchart.  It should show you whether the process is
cpu-bound, IO-bound, or something else, AND hopefully see if any other
process has a significant impact.  It's fairly coarse grained, but if
you have some big problems then they should show up on it.

There is also a specific script to analyse the timings in a monitor
log, I haven't tried it myself though.
<https://lists.launchpad.net/ubuntu-boot/msg00002.html>.

Note that it's normal for udev startup to take a few seconds on a
netbook-level processor.  It's fair to say udev still has a little
room for optimisation :-).

Regards
Alan

Re: Debugging udevd startup time

[Kay Sievers]

2009/5/20 Alan Jenkins <sourcejedi.lkml@googlemail.com>:
> On 5/19/09, Ozan Çağlayan <ozan@pardus.org.tr> wrote:
>> I wonder how can I debug the possible bottleneck(s) during the startup
>> of udevd?
>>
>> I'm writing the $(udevadm --monitor)'s output to a log file during boot
>> and I have the exact events and timestamps. I really don't understand
>> why the whole process takes a bunch of seconds.

Do  you use the latest module-init-tools, and created a binary index
with depmod?

How many modules do you need to load during boot (lsmod | wc -l)?

> One word: bootchart.  It should show you whether the process is
> cpu-bound, IO-bound, or something else, AND hopefully see if any other
> process has a significant impact.  It's fairly coarse grained, but if
> you have some big problems then they should show up on it.

The log shows 1.8 seconds, bootchart might not show too much here.

Kay

Re: Debugging udevd startup time

[Ozan Çağlayan]

Kay Sievers wrote On 20-05-2009 03:12:
> Do  you use the latest module-init-tools, and created a binary index
> with depmod?
>
> How many modules do you need to load during boot (lsmod | wc -l)?
>   
36 modules are loaded during boot.

I'm using module-init-tools 3.8 and yes I have the following *.bin files
in /lib/modules:

modules.alias.bin
modules.dep.bin
modules.symbols.bin

>> One word: bootchart.  It should show you whether the process is
>> cpu-bound, IO-bound, or something else, AND hopefully see if any other
>> process has a significant impact.  It's fairly coarse grained, but if
>> you have some big problems then they should show up on it.
>>     
>
> The log shows 1.8 seconds, bootchart might not show too much here.
>   

I've just tried on a tiny sony vaio centrino laptop which loads 71
modules during boot. Its log shows 1.4 seconds between the first and the
last event.

Should I accept those timings and go on or should I be unhappy about
them and try to dig more?

I'll check the bootchart output but fairly I really hate its way of
drawing the booting sequence :)

Thanks a lot
Ozan Caglayan

Re: Debugging udevd startup time

[Ozan Çağlayan]

Ozan Çağlayan wrote:
>> The log shows 1.8 seconds, bootchart might not show too much here.
>>   
>>     
>
> I've just tried on a tiny sony vaio centrino laptop which loads 71
> modules during boot. Its log shows 1.4 seconds between the first and the
> last event.
>   

3.2 seconds on a recent Dual Core MacbookPro5,1 which loads 52 modules
during boot. It seems that the gap can oscillate very brutally from one
system to another one.

Re: Debugging udevd startup time

[Greg KH]

On Wed, May 20, 2009 at 07:25:16PM +0300, Ozan Çağlayan wrote:
> Ozan Çağlayan wrote:
> >> The log shows 1.8 seconds, bootchart might not show too much here.
> >>   
> >>     
> >
> > I've just tried on a tiny sony vaio centrino laptop which loads 71
> > modules during boot. Its log shows 1.4 seconds between the first and the
> > last event.
> >   
> 
> 3.2 seconds on a recent Dual Core MacbookPro5,1 which loads 52 modules
> during boot. It seems that the gap can oscillate very brutally from one
> system to another one.

That sounds like a modprobe issue, not a udev one.

There have been some new kernel changes to make this go faster, perhaps
you need to integrate them.  Also realize that loading 52 modules will
take a lot of time, just due to all of the in-kernel lookups that are
necessary to accomplish this.

Perhaps you might wish to cut down on this large number, if you have
everything as modules, you loose some of the new kernel speedups that
have happened with async probing of devices which can not happen if the
drivers are in modules.

Look at the recent moblin releases for examples of how to speed this up.

good luck,

greg k-h

Re: Debugging udevd startup time

[Kay Sievers]

On Wed, May 20, 2009 at 18:25, Ozan Çağlayan <ozan@pardus.org.tr> wrote:
> Ozan Çağlayan wrote:
>>> The log shows 1.8 seconds, bootchart might not show too much here.
>>
>> I've just tried on a tiny sony vaio centrino laptop which loads 71
>> modules during boot. Its log shows 1.4 seconds between the first and the
>> last event.
>
> 3.2 seconds on a recent Dual Core MacbookPro5,1 which loads 52 modules
> during boot. It seems that the gap can oscillate very brutally from one
> system to another one.

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

How long does udev take on the running box?

Make sure, you kill HAL, it might prevent udev from doing work faster,
if it does not read the messages fast enough:
 $ killall hald

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

How big are the rules you use?
  wc -l /etc/udev/rules.d/* /lib/udev/rules.d/* /dev/.udev/rules.d/*

What does:
  udevadm test foo
print?

Kay

Re: Debugging udevd startup time

[Ozan Çağlayan]

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)