From mboxrd@z Thu Jan 1 00:00:00 1970 From: Simon Glass Date: Mon, 26 Oct 2020 13:22:43 -0600 Subject: [PATCH 00/33] stm32: enable logging features In-Reply-To: <88a21c960cc248af9cd08e2fc5681a69@SFHDAG2NODE3.st.com> References: <20201014091646.4233-1-patrick.delaunay@st.com> <88a21c960cc248af9cd08e2fc5681a69@SFHDAG2NODE3.st.com> Message-ID: List-Id: MIME-Version: 1.0 Content-Type: text/plain; charset="us-ascii" Content-Transfer-Encoding: 7bit To: u-boot@lists.denx.de Hi Patrick, On Thu, 15 Oct 2020 at 09:59, Patrick DELAUNAY wrote: > > Hi Simon, > > > From: Simon Glass > > Sent: jeudi 15 octobre 2020 17:06 > > > > Hi Patrick, > > > > On Wed, 14 Oct 2020 at 03:16, Patrick Delaunay > > 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@_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