[PATCH 2/2] bootstage: Do not sort records
Jonas Karlman
jonas at kwiboo.se
Wed Aug 28 21:01:47 CEST 2024
Hi Simon,
On 2024-08-28 20:11, Simon Glass wrote:
> 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.
Interesting, so coreboot is not running before U-Boot on this platform,
is it running in parallel with U-Boot?
How is timestamp_add_to_bootstage() called in U-Boot, I cannot see any
call to it, what am I missing?
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.
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.
Regards,
Jonas
>
> => 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
More information about the U-Boot
mailing list