From mboxrd@z Thu Jan 1 00:00:00 1970 From: Simon Glass Date: Fri, 6 Nov 2020 11:50:35 -0700 Subject: [PATCH 00/33] stm32: enable logging features In-Reply-To: References: <20201014091646.4233-1-patrick.delaunay@st.com> <88a21c960cc248af9cd08e2fc5681a69@SFHDAG2NODE3.st.com> <8a219eb12a6446999545b375827980d8@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 Fri, 6 Nov 2020 at 10:45, Patrick DELAUNAY wrote: > > Hi Simon, > > > From: Simon Glass > > Sent: vendredi 30 octobre 2020 19:16 > > > > Hi Patrick, > > > > On Wed, 28 Oct 2020 at 05:52, Patrick DELAUNAY > > wrote: > > > > > > Hi Simon, > > > > > > > From: Simon Glass > > > > Sent: lundi 26 octobre 2020 20:23 > > > > > > > > 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 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. > > > > > > Yes, log_dispatch / log_passes_filter are called after vsnprintf > > > > > > > I suspect that could be refactored to move the checking to a > > > > separate function, and then call it before doing the expensive vsprintf(). > > > > > > Or save va_list, fmt in log_rec and call vsnprintf allow when needed > > > in log_dispatch, just before emit > > > > Yes that sounds better to me. > > > > > > > > > > > > > > > 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. > > > > > > Ok, I add it in my TODO list > > > > OK. We really should make logging add the least overhead possible. > > > > Regards, > > Simon > > I rebase my patchset, tested on stm32mp15_trusted_defconfig (with TF-A load) > and no more stm32_basic_defconfgi (with SPL load) > > And the cost is now more limited.... (perhaps I made some error in my last tests or > I activate too many trace ?). Definitely tracing adds to the time. But that's good news! > > But I found some improvement on the log features, I will sent booth with > updated values next week. Great, thanks. More people will use logging if the overhead is small. Regards, Simon