[arch-general] What causes the 3-5 sec delay before :: running early hooks (udev)?

[David C. Rankin]

On 06/20/2012 03:11 PM, Leonid Isaev wrote:

> No, you need logs much before that. Udev should be noted twice in dmesg: one
> is when initramfs is unpacked (with low PID ~ 40); and you posted another.
>

Thanks Leonid,

   I found the earlier entry, but there is virtually no delay on the earlier 
udev start:

[    1.412277] Write protecting the kernel read-only data: 1120k
[    1.426225] udevd[40]: starting version 185
[    1.494146] usbcore: registered new interface driver usbfs
[    1.494798] usbcore: registered new interface driver hub
[    1.501646] SCSI subsystem initialized

full dmesg at:

http://nirvana.3111skyline.com/dl/arch/bugs/dmesg0620.txt

<snip>

> Yes, everything is in dmesg.log and kernel.log (unless you have reconfigured
> syslog).
>

   The only other brief delays in dmesg that might be it are:

[    4.057038] usbhid: USB HID core driver
[    6.302103] sd 0:0:0:0: [sda] 586114704 512-byte logical blocks: (300 
GB/279 GiB)

[    6.993289] sr 0:0:1:0: Attached scsi CD-ROM sr0
[    7.957888] EXT4-fs (sdc5): mounting ext3 file system using the ext4 subsystem
[    8.016583] EXT4-fs (sdc5): mounted filesystem with ordered data mode. 
Opts: (null)
[   10.236553] udevd[140]: starting version 185
[   11.189242] input: Power Button as 
/devices/LNXSYSTM:00/device:00/PNP0C0C:00/input/input3

   This group of messages taken together is just about 6-7 seconds that would 
correspond to the delay. Is there a way I could figure out where in this 
period of time the boot message of ':: running early hooks (udev)' is 
displayed?  My _guess_ is the delay is the 4.057038 -> 10.236553 time period, 
then the ':: running early hooks (udev)' message pops up. If that is the case, 
then it just looks like the 2.3 secs for usbhid + 3.9 secs for sda,sdc 
initialization is the cause of the delay.

   Anything in the 3.9 sec drive initialization look strange?


-- 
David C. Rankin, J.D.,P.E.