Hi Jonas, On Wed, 28 Aug 2024 at 13:01, Jonas Karlman <jo...@kwiboo.se> wrote: > > Hi Simon, > > On 2024-08-28 20:11, Simon Glass wrote: > > 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. > > Interesting, so coreboot is not running before U-Boot on this platform, > is it running in parallel with U-Boot?
It runs before, but U-Boot picks up the timestamps once it is ready to do so, i.e. after bootstage is inited. > > How is timestamp_add_to_bootstage() called in U-Boot, I cannot see any > call to it, what am I missing? Yes, it was deleted. I just sent a series to bring i tback. > > Guessing the records need to be sorted after/during that function call? > > Also look like the sorting is done in bootstage_report() so the report > is possible logged to FDT with an unsorted order. Yes, although that shouldn't really matter. Perhaps it is worth fixing? > > Let me know what you want me to do with this, I will drop this for now > and just keep carry this patch in my local tree. Hmmm step one is to complain about the bug. If it exists in ATF upstream, then it should be fixed. I can have a crack at fixing it if so. If it is a vendor binary, then they should fix it. Step 2, I suggest a Kconfig option enabled for these boards, so it is clear it is a workaround. Regards, Simon > > > > => 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 >
