Hi again Jonas,
On Wed, 28 Aug 2024 at 11:06, Simon Glass <s...@chromium.org> wrote:
>
> Hi Jonas,
>
> On Wed, 28 Aug 2024 at 10:15, Jonas Karlman <jo...@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 <s...@chromium.org> wrote:
> > >>
> > >> Hi Jonas,
> > >>
> > >> On Sat, 3 Aug 2024 at 06:42, Jonas Karlman <jo...@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 <jo...@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
