2008-08-19 20:51:36

by Daniel Walker

[permalink] [raw]
Subject: slower initcalls in -next


I was testing out todays -next I saw fastboot was included, which got me
interested so I made a list of the slower initcalls. This was an
allyesconfig on 32bit x86, which means these numbers are somewhat
inflated w/ debugging enabled.
The top 25 below,

initcall ub_init+0x0/0x76 returned 0 after 49465 msecs
initcall rtrack_init+0x0/0xec returned 0 after 30529 msecs
initcall net_olddevs_init+0x0/0x129 returned 0 after 25032 msecs
initcall alsa_card_miro_init+0x0/0x19 returned 0 after 11562 msecs
initcall cadet_init+0x0/0x156 returned -1 after 3173 msecs
initcall mousedev_init+0x0/0x7d returned 0 after 2658 msecs
initcall pty_init+0x0/0x449 returned 0 after 1735 msecs
initcall tcpprobe_init+0x0/0xc3 returned 0 after 1388 msecs
initcall sermouse_init+0x0/0x1b returned 0 after 1274 msecs
initcall microcode_intel_module_init+0x0/0x43 returned 0 after 1247 msecs
initcall ipx_init+0x0/0xd7 returned 0 after 1014 msecs
initcall piix_init+0x0/0x29 returned 0 after 747 msecs
initcall raid5_init+0x0/0x37 returned 0 after 648 msecs
initcall init_rfd_ftl+0x0/0x14 returned 0 after 579 msecs
initcall param_sysfs_init+0x0/0x143 returned 0 after 522 msecs
initcall serial8250_init+0x0/0xef returned 0 after 507 msecs
initcall init_sc520cdp+0x0/0x1d8 returned -5 after 415 msecs
initcall isapnp_init+0x0/0xca6 returned 0 after 347 msecs
initcall pci_init+0x0/0x31 returned 0 after 308 msecs
initcall tty_init+0x0/0x19c returned 0 after 305 msecs
initcall ehci_hcd_init+0x0/0x9f returned 0 after 305 msecs
initcall alsa_card_sb8_init+0x0/0x19 returned -19 after 305 msecs
initcall uhci_hcd_init+0x0/0xd4 returned 0 after 297 msecs
initcall com90xx_init+0x0/0xd6f returned -5 after 293 msecs
initcall alsa_card_wavefront_init+0x0/0x52 returned 0 after 286 msecs

I don't know to what degree these are already being investigated, but I
thought the list was interesting ..

Daniel


2008-08-20 07:58:19

by Takashi Iwai

[permalink] [raw]
Subject: Re: slower initcalls in -next

At Tue, 19 Aug 2008 13:51:24 -0700,
Daniel Walker wrote:
>
>
> I was testing out todays -next I saw fastboot was included, which got me
> interested so I made a list of the slower initcalls. This was an
> allyesconfig on 32bit x86, which means these numbers are somewhat
> inflated w/ debugging enabled.
> The top 25 below,
>
> initcall ub_init+0x0/0x76 returned 0 after 49465 msecs
> initcall rtrack_init+0x0/0xec returned 0 after 30529 msecs
> initcall net_olddevs_init+0x0/0x129 returned 0 after 25032 msecs
> initcall alsa_card_miro_init+0x0/0x19 returned 0 after 11562 msecs
> initcall cadet_init+0x0/0x156 returned -1 after 3173 msecs
> initcall mousedev_init+0x0/0x7d returned 0 after 2658 msecs
> initcall pty_init+0x0/0x449 returned 0 after 1735 msecs
> initcall tcpprobe_init+0x0/0xc3 returned 0 after 1388 msecs
> initcall sermouse_init+0x0/0x1b returned 0 after 1274 msecs
> initcall microcode_intel_module_init+0x0/0x43 returned 0 after 1247 msecs
> initcall ipx_init+0x0/0xd7 returned 0 after 1014 msecs
> initcall piix_init+0x0/0x29 returned 0 after 747 msecs
> initcall raid5_init+0x0/0x37 returned 0 after 648 msecs
> initcall init_rfd_ftl+0x0/0x14 returned 0 after 579 msecs
> initcall param_sysfs_init+0x0/0x143 returned 0 after 522 msecs
> initcall serial8250_init+0x0/0xef returned 0 after 507 msecs
> initcall init_sc520cdp+0x0/0x1d8 returned -5 after 415 msecs
> initcall isapnp_init+0x0/0xca6 returned 0 after 347 msecs
> initcall pci_init+0x0/0x31 returned 0 after 308 msecs
> initcall tty_init+0x0/0x19c returned 0 after 305 msecs
> initcall ehci_hcd_init+0x0/0x9f returned 0 after 305 msecs
> initcall alsa_card_sb8_init+0x0/0x19 returned -19 after 305 msecs
> initcall uhci_hcd_init+0x0/0xd4 returned 0 after 297 msecs
> initcall com90xx_init+0x0/0xd6f returned -5 after 293 msecs
> initcall alsa_card_wavefront_init+0x0/0x52 returned 0 after 286 msecs

At least, all alsa_* calls are only for ISA devices, and I don't think
it's worth to optimize. Changing such hardcoded delays could break
the running system easily.

However, some of the above are definitely interesting to investigate
as they are mostly built-in and affect almost all people.


thanks,

Takashi

2008-08-20 15:24:25

by Daniel Walker

[permalink] [raw]
Subject: Re: slower initcalls in -next

On Wed, 2008-08-20 at 09:58 +0200, Takashi Iwai wrote:

> At least, all alsa_* calls are only for ISA devices, and I don't think
> it's worth to optimize. Changing such hardcoded delays could break
> the running system easily.
>
> However, some of the above are definitely interesting to investigate
> as they are mostly built-in and affect almost all people.

I didn't realize it till later , but the list is a little misleading ..
Those times are a mix of execution, and blocking.. I think the top one
(49 seconds!) was blocked most of the time, since ub_init() doesn't look
very complex. I'm not sure if it what it was blocked on, or why ..

Daniel