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

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.

  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.

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

- 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

- 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)

Brian