Hi Patrick,
On Thu, 15 Oct 2020 at 09:59, Patrick DELAUNAY patrick.delaunay@st.com wrote:
Hi Simon,
From: Simon Glass sjg@chromium.org Sent: jeudi 15 octobre 2020 17:06
Hi Patrick,
On Wed, 14 Oct 2020 at 03:16, Patrick Delaunay patrick.delaunay@st.com wrote:
This patch-set migrates several stm32 drivers to API compatible with logging features (use dev_...() or log_...() function) and activate the logging features in STM32MP15 boards.
The size of U-Boot increased by 19kB (933026 to 952830 on STM32MP157C-EV1 board for basic defconfig) but the boot time don't change
drastically.
For example on STM32MP157C-EV1 board:
1/ Before LOG patchset
Timer summary in microseconds (12 records): Mark Elapsed Stage 0 0 reset 224,514 224,514 SPL 961,170 736,656 end SPL 964,006 2,836 board_init_f 1,186,986 222,980 board_init_r 1,651,379 464,393 id=64 1,674,463 23,084 id=65 1,675,164 701 main_loop 4,025,806 2,350,642 id=175
Accumulated time: 55,064 dm_f 66,749 dm_r 88,796 dm_spl
2/ With LOG activated (after this patchset)
Timer summary in microseconds (12 records): Mark Elapsed Stage 0 0 reset 227,142 227,142 SPL 984,585 757,443 end SPL 987,579 2,994 board_init_f 1,210,091 222,512 board_init_r 1,673,354 463,263 id=64 1,696,073 22,719 id=65 1,696,775 702 main_loop 5,443,104 3,746,329 id=175
Accumulated time: 62,154 dm_f 66,264 dm_r 89,376 dm_spl
For information even with all trace embbeded in U-Boot but not activated, MAX_LOG_LEVEL=8 and LOG_DEFAULT_LEVEL=6
Size increase by 190KB (952830 to 1147918) but boot time is stable (1,748s vs 1,696s).
This seems pretty bad. Is this because of console output, or something else? I understand the size increase, but not the boot time increase.
For this last point I just execute STM32MP157C-EV1 boot with a patch in configs/stm32mp15_basic_defconfig
+CONFIG_LOGLEVEL=8 +CONFIG_LOG_MAX_LEVEL=8 +CONFIG_LOG_DEFAULT_LEVEL=6 +CONFIG_LOGF_FILE=y +CONFIG_LOGF_LINE=y +CONFIG_LOGF_FUNC=y
And execute "bootstage report" after the second boot (the first boot is pertubated by env save)
I think the delta is linked to 1/ size of U-Boot (SPL spent more time to load U-Boot) end of SPL 987,579 => 996,117
OK.
2/ time to check for each debug trace: because I increase the log level (gd->default_log_level = 6 < MAX_LOG_LEVEL=8)
This might be the biggest part. If you look at _log() it always does the vsprintf() even if in fact log_dispatch() does not dispatch it to anything.
I suspect that could be refactored to move the checking to a separate function, and then call it before doing the expensive vsprintf().
3/ treatment added in log_console_emit (some printf) and log_dispatch (processing_msg / gd->loghead)
Likely this is fast.
4/ lower cache performancy as trace code are pesent in memory even they are not used
Can I do some check/experimentation on my side ?
Yes, if you can use the bootstage_start() and bootstage_accum() within the _log() function to measure the total time take in the run.
Regards, Simon