Re: [boot-time] [SCRIPT v4] analyze-initcall-debug.py

[Francesco Valla <francesco@valla.it>]

Hi Brian,

On Tuesday, 4 February 2025 at 21:23:54 Brian Masney <bmasney@redhat.com> wrote:
> On Tue, Jan 28, 2025 at 06:15:53PM +0100, Francesco Valla wrote:
> > Hello,
> > 
> > this is the fourth version of the analyze-initcall-debug.py script, which can
> > be used to analyze the kernel output when booting with initcall_debug
> > to extract some human-readable data from it.
> > 
> > This version brings a complete bootchart of the kernel-side portion of the
> > boot sequence, showing both the initcalls and the probes.
> 
> Hi Francesco,
> 
> This is a useful script and I have a few suggestions:
> 
> - Report on the probe deferrals, and group them by name. For example,
>   this is one of the probe deferrals on my Thinkpad x13s laptop
>   with a Qualcomm SoC:
> 
>     probe of 3210000.soundwire returned -517 after 3 usecs
> 
>   As a hack, I can group them together with this one liner:
> 
>     x13s:~$ grep 517 dmesg.txt  | grep returned | \
>               awk -F"probe of " '{print $2}' | awk '{print $1" "$5}' | sort \
>               awk '{a[$1]+=$2} END {for (i in a) print i, a[i]}' | sort
>     15000000.iommu 750
>     18200000.rsc:regulators-2 61
>     1c00000.pcie 13458
>     1c10000.pcie 18266
>     1c20000.pcie 250
>     3200000.rxmacro 51
>     3210000.soundwire 18
>     3220000.txmacro 105
>     ...
> 
>   and add the following to the end to get the overall time:
> 
>     | awk '{sum += $2} END {print sum}'
> 
>   493,730 usec in this example.
> 

This is certainly useful and will be added to the next version. It's
partially there for the HTML output, but can be added to the textual one
with virtually no effort.

>   Note I attached the dmesg for my system since it's a pretty extreme
>   example since we have pinctrl drivers set to modules instead of built
>   in on Fedora.
> 
>   I CCed Saravana since he mentioned at the boot SIG meeting last week
>   that this may not be an accurate way to measure probe deferrals. Take
>   a look at the output of 'grep 33c0000.pinctrl' against the
>   dmesg I attached, and see the timestamps are the range
>   2.190008 - 13.358063.
> 

As far as I understood, this is not accurate since also the "forced"
deferrals caused by devlink are accounted for. But that would be fine,
since it's time spent for the given driver nonetheless. I'll let Saravana
comment more, though. 

> - Run pylint against the code and fix up some of the warnings that are
>   reported.

Noted.

> 
> - Add commas to some of the output. For example, change:
> 
>     Top 10 initcall durations:
>      * apm_driver_init -> 804412us
>      * panel_edp_init -> 205809us
> 
>   to:
> 
>     Top 10 probe durations:
>      * gprsvc:service:2:1 -> 5288,273us
>      * 1c10000.pcie -> 1,091,920us
> 

Not a big fan of commas as separators, but I'll give it a thought.

> - Map the return values to their pretty name. For example, change:
> 
>     Failed initcalls/probes:
>      * kvm_arm_init -> ret = -19
>      * test_kstrtox_init -> ret = -22
> 
>   to:
> 
>      * kvm_arm_init -> ret = -ENODEV (-19)
>      * test_kstrtox_init -> ret = -EINVAL (-22)
> 

Will do for sure.

> Brian
> 

Thank you for the feedback!


Francesco