[PATCH 00/33] stm32: enable logging features

[Patrick DELAUNAY]

Hi Simon,

> From: Simon Glass <sjg at chromium.org>
> Sent: vendredi 30 octobre 2020 19:16
> 
> Hi Patrick,
> 
> On Wed, 28 Oct 2020 at 05:52, Patrick DELAUNAY <patrick.delaunay at st.com>
> wrote:
> >
> > Hi Simon,
> >
> > > From: Simon Glass <sjg at chromium.org>
> > > Sent: lundi 26 octobre 2020 20:23
> > >
> > > Hi Patrick,
> > >
> > > On Thu, 15 Oct 2020 at 09:59, Patrick DELAUNAY
> > > <patrick.delaunay at st.com>
> > > wrote:
> > > >
> > > > Hi Simon,
> > > >
> > > > > From: Simon Glass <sjg at chromium.org>
> > > > > Sent: jeudi 15 octobre 2020 17:06
> > > > >
> > > > > Hi Patrick,
> > > > >
> > > > > On Wed, 14 Oct 2020 at 03:16, Patrick Delaunay
> > > > > <patrick.delaunay at 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 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 ?).

But I found some improvement on the log features, I will sent booth with
updated values next week.

Patrick.