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

[Heinrich Schuchardt]

On 30.04.25 15:54, Simon Glass wrote:
+Michal Simek
Hi Heinrich,

On Wed, 30 Apr 2025 at 03:11, Heinrich Schuchardt
<heinrich.schucha...@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.schucha...@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.

There isn't anything reverting [1] in my patch.


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.

Booting via bootm is not very exotic.


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)

If the ID is not meant to be accessible to the user, why would we write 
it to the records at all?

Best regards

Heinrich


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_...()