[PATCH 1/1] boot: print the boot stage id in the report

[Simon Glass]

+Michal Simek

Hi Heinrich,

On Wed, 30 Apr 2025 at 03:11, Heinrich Schuchardt
<heinrich.schuchardt at canonical.com> wrote:
>
> An output like the following is not helpful:
>
>     Timer summary in microseconds (40 records):
>            Mark    Elapsed  Stage
>               0          0  reset
>     ...
>      56,448,158      4,845  fit_image_load
>      56,448,186         28  fit_image_load
>      56,448,187          1  fit_image_load
>      56,451,971      3,784  fit_image_load
>      56,483,951     31,980  fit_image_load
>      56,483,956          5  fit_image_load
>      56,483,984         28  fit_image_load
>      56,484,001         17  fit_image_load
>      56,484,008          7  fit_image_load
>
> It provides no clue about what is happening in the fit_image_load stage.
>
> Add the bootstage ID to the report. Now we get:
>
>     Timer summary in microseconds (40 records):
>            Mark    Elapsed    ID Stage
>               0          0   171 reset
>       3,181,017  3,181,017   178 board_init_f
>       3,229,282     48,265   179 board_init_r
>       4,184,866    955,584    64 eth_common_init
>       4,280,304     95,438    65 eth_initialize
>       4,284,509      4,205   186 main_loop
>       4,390,704    106,195   180 usb_start
>       5,694,146  1,303,442   187 cli_loop
>      59,908,029 54,213,883   184 bootm_start
>      59,908,031          2     1 boot_get_kernel
>      59,912,875      4,844   100 fit_image_load
>      59,912,903         28   101 fit_image_load
>      59,912,904          1   102 fit_image_load
>      59,916,688      3,784   110 fit_image_load
>      59,948,668     31,980   105 fit_image_load
>      59,948,673          5   106 fit_image_load
>     ...
>
> Signed-off-by: Heinrich Schuchardt <heinrich.schuchardt at canonical.com>
> ---
>  common/bootstage.c | 4 ++--
>  1 file changed, 2 insertions(+), 2 deletions(-)
>
> diff --git a/common/bootstage.c b/common/bootstage.c
> index 4532100acea..0810c4e5271 100644
> --- a/common/bootstage.c
> +++ b/common/bootstage.c
> @@ -254,7 +254,7 @@ static uint32_t print_time_record(struct bootstage_record *rec, uint32_t prev)
>                 print_grouped_ull(rec->time_us, BOOTSTAGE_DIGITS);
>                 print_grouped_ull(rec->time_us - prev, BOOTSTAGE_DIGITS);
>         }
> -       printf("  %s\n", get_record_name(buf, sizeof(buf), rec));
> +       printf("  %4u %s\n", rec->id, get_record_name(buf, sizeof(buf), rec));
>
>         return rec->time_us;
>  }
> @@ -333,7 +333,7 @@ void bootstage_report(void)
>
>         printf("Timer summary in microseconds (%d records):\n",
>                data->rec_count);
> -       printf("%11s%11s  %s\n", "Mark", "Elapsed", "Stage");
> +       printf("%11s%11s  %4s %s\n", "Mark", "Elapsed", "ID", "Stage");
>
>         prev = print_time_record(rec, 0);
>
> --
> 2.48.1

This is largely a revert of [1] so you should mention that, at least
and cc the author.

When I wrote the bootstage feature[2], Wolfgang asked me to replace
the old show_boot_progress() which used an integer. The whole series
was done with very tight size constraints.

The function name fit_image_load() is not at all useful in the case
you are showing.

In this day and age we should add strings, included if BOOTSTAGE is
enabled, i.e. convert the calls like:

bootstage_mark(bootstage_id + BOOTSTAGE_SUB_CHECK_ARCH);

to

bootstage_mark(bootstage_id, BOOTSTAGE_SUB_CHECK_ARCH)

and have it create a string comprising the base ID and the sub-ID,
e.g. "kernel: check arch"

Regards,
Simon

[1] 55bc22760c3 bootstage: Show func name for bootstage_mark/error
[2] 770605e4f98 bootstage: Replace show_boot_progress/error() with
bootstage_...()