[PATCH 2/2] bootstage: Do not sort records

Wed Aug 28 20:11:00 CEST 2024

Hi again Jonas,

On Wed, 28 Aug 2024 at 11:06, Simon Glass <sjg at chromium.org> wrote:
>
> Hi Jonas,
>
> On Wed, 28 Aug 2024 at 10:15, Jonas Karlman <jonas at kwiboo.se> wrote:
> >
> > Hi Simon,
> >
> > On 2024-08-28 18:01, Simon Glass wrote:
> > > Hi Jonas,
> > >
> > > On Tue, 6 Aug 2024 at 15:50, Simon Glass <sjg at chromium.org> wrote:
> > >>
> > >> Hi Jonas,
> > >>
> > >> On Sat, 3 Aug 2024 at 06:42, Jonas Karlman <jonas at kwiboo.se> wrote:
> > >>>
> > >>> The timer counter on Rockchip SoCs may be reset in TF-A, this may cause
> > >>> the bootstage records to be printed out of order and with an incorrect
> > >>> elapsed time.
> > >>
> > >> Eek can we just fix TF-A? That seems like a bug.
> >
> > TF-A is vendor blob, so we have no control of it.
>
> Can we replace it, or is it one of the ones that has not been released?
>
> Can you file a bug with the vendor?
>
> >
> > >>
> > >>>
> > >>> Fix this by not sorting the bootstage records.
> > >>>
> > >>> Before on a Radxa ZERO 3W (RK3566) board:
> > >>>
> > >>>   => bootstage report
> > >>>   Timer summary in microseconds (12 records):
> > >>>          Mark    Elapsed  Stage
> > >>>             0          0  reset
> > >>>         7,436      7,436  board_init_f
> > >>>       164,826    157,390  SPL
> > >>>       375,392    210,566  end phase
> > >>>       423,909     48,517  board_init_r
> > >>>       472,973     49,064  eth_common_init
> > >>>       476,848      3,875  main_loop
> > >>>       477,003        155  cli_loop
> > >>>
> > >>>   Accumulated time:
> > >>>                    7,181  of_live
> > >>>                   14,739  dm_spl
> > >>>                   15,029  dm_r
> > >>>                  315,150  dm_f
> > >>>
> > >>> With this the records can be printed in chronological order when the
> > >>> counter is reset and SPL and board_init_r records show correct elapsed
> > >>> time.
> > >>>
> > >>>   => bootstage report
> > >>>   Timer summary in microseconds (12 records):
> > >>>          Mark    Elapsed  Stage
> > >>>             0          0  reset
> > >>>       164,437    164,437  SPL
> > >>>       375,023    210,586  end phase
> > >>>         7,437      7,437  board_init_f
> > >>>       424,390    416,953  board_init_r
> > >>>       473,515     49,125  eth_common_init
> > >>>       477,402      3,887  main_loop
> > >>>       477,571        169  cli_loop
> > >>>
> > >>>   Accumulated time:
> > >>>                   14,734  dm_spl
> > >>>                  315,646  dm_f
> > >>>                    7,339  of_live
> > >>>                   14,977  dm_r
> > >>>
> > >>> For the tested board external TPL and BROM take ~164 ms to initialize
> > >>> DRAM and load SPL, SPL take ~210ms to load images from FIT and U-Boot
> > >>> proper take ~477ms to reach cli prompt.
> > >>>
> > >>> Signed-off-by: Jonas Karlman <jonas at kwiboo.se>
> > >>> ---
> > >>>  common/bootstage.c | 12 ++----------
> > >>>  1 file changed, 2 insertions(+), 10 deletions(-)
> > >>>
> > >
> > > To put this more strongly, this breaks the timing output on other boards.
> >
> > Please elaborate, I cannot understand why not sorting would break output
> > on other boards, are other boards adding records out of order?
> >
> > Do you have an example of how this change break other boards?
>
> Oh sure. The original reason was that the array was ordered by ID.
> That was changed in [1], which I forgot about.
>
> The other bit is for coreboot (or potentially other prior phases) we
> receive timestamps as a block and add them into U-Boot. We want these
> to appear in the correct order with respect to the ones already adding
> to U-Boot.
>
> Sadly coreboot uses its own toolchain and I seem to have deleted it,
> but once it finishes building the world I will give it a try.

OK I gave up and just built one toolchain instead of every one known
to man, which is the default.

The code has seriously rotted and is a somewhat fascinating window
into what U-Boot was like 12 years ago...I will send a little series.

Anyway, the start-romstage and device-xxx things below come from coreboot.

=> bootstage repo
Timer summary in microseconds (20 records):
       Mark    Elapsed  Stage
          0          0  reset
     25,322     25,322  board_init_f
     32,175      6,853  start-romstage
    117,158     84,983  board_init_r
    208,409     91,251  device-initialize
    293,286     84,877  device-done
    547,606    254,320  selfboot-jump
    621,050     73,444  eth_common_init
    699,570     78,520  eth_initialize
    744,210     44,640  main_loop
    761,030     16,820  usb_start
  3,988,265  3,227,235  netboot_common
  3,988,330         65  eth_start
  6,316,294  2,327,964  bootp_start
 12,286,385  5,970,091  bootp_stop
 12,297,353     10,968  netboot_common
 12,300,596      3,243  netboot_common
 28,327,263 16,026,667  cli_loop

Accumulated time:
                 8,600  dm_r
                 8,659  dm_f

Without the sort, I see:

Timer summary in microseconds (18 records):
       Mark    Elapsed  Stage
          0          0  reset
     36,582     36,582  board_init_f
    125,775     89,193  board_init_r
    642,577    516,802  eth_common_init
    721,321     78,744  eth_initialize
     31,357429,427,733,2  start-romstage
    247,602    216,245  device-initialize
    333,879     86,277  device-done
    596,043    262,164  selfboot-jump
    765,897    169,854  main_loop
    783,397     17,500  usb_start
  4,043,423  3,260,026  netboot_common
  4,043,489         66  eth_start
  6,371,702  2,328,213  bootp_start
 11,609,247  5,237,545  netboot_common
 15,476,116  3,866,869  cli_loop

Accumulated time:
                 8,639  dm_f
                 8,923  dm_r

>
> >
> > >
> > > At the very least, this should be Kconfig option just enabled for
> > > boards with a broken ATF.
> >
> > I can add a Kconfig option, but would like to understand why other/any
> > board would need to sort the records in the first place.
>
> OK.

Regards,
Simon

>
> [1] 03ecac31498 bootstage: Use rec_count as the array index