Re: [boot-time] [RFC] analyze-initcall-debug.py - a tool to analyze the initcall debug output

[Francesco Valla <francesco@valla.it>]

Hi Tim,

thank you for taking the time to review the tool. My reply too will be splitted in two parts.

On Tuesday, 3 December 2024 at 21:33:06 Bird, Tim <Tim.Bird@sony.com> wrote:
> Hey Francesco,
> 
> I appreciate the new tool, and have some feedback below.
> 
> I'll separate my response and ideas into 2 categories:
>  - issues raised from your sample report
>  - feedback on the tool itself
> 
> and send them as separate emails.
> 
> > -----Original Message-----
> > From: Francesco Valla <francesco@valla.it>
> > Dear fellow boot time optimizers,
> > 
> > following the first boot time SIG meeting, which I lurked with much pleasure
> > (but didn't participate to, as I was a bit in awe among such authorities), I'd
> > like to introduce myself with code rather than a presentation or resume.
> > 
> > Here is a python script which can analyze a dmesg output with initcall_debug
> > option enabled and extract some useful information. It can for example be used
> > to analyze the output of the grab-boot-data.sh tool that Tim presented on this
> > list [1] just a few days ago.
> > 
> > Usage is very simple, as the output of dmesg can be piped directly to it:
> > 
> >     dmesg | analyze-initcall-debug.py
> > 
> > If no option is specified, it outputs a brief summary, like the following one
> > (obtained on my Beagleplay):
> > 
> > 1758 drivers has been initialized, of which 1758 before userspace
> > 119 probes happened outside of the init of their driver
> > 0 deferred probes pending
> > ---
> > Top 10 init/probes durations:
> >  * 30200000.dss -> 523002us
> 
> This call, and a lot of the others are missing function names.  Did you compile the kernel with
> CONFIG_KALLSYMS=y?
> 
> If that's the case, is there a way to use the System.map file for the kernel (used on
> the machine where the dmesg was obtained from) to map these addresses
> to their respective  function names?
> 

These are not in fact addresses, but rather device names. In my understanding, they are printed
when a probe happens outside of the initialization function for their driver. I still don't have an idea
on how to match probes with their original initcall, in order to present the user the complete picture.

> >  * deferred_probe_initcall -> 487483us
> 
> I feel like this function is interfering with the ability to correctly assign
> boot time delays to the correct initcall.
> 
> I would really like to see someone tackle this issue, by studying the deferred_probe_initcall
> function, to see if there's a way to instrument it so that the cost of each
> probe can be reported and then associated with corresponding initcall, when initcall_debug
> is used.
> 
> Does anyone want to look into this issue?

I can take a look, but probably toward the end of the year. Another similar area I'd like to investigate
is related to initcall time vs actual probe time: for drivers instantiated multiple time, I'd like to know
how much time each probe took rather than the overall time.


Regards,
Francesco