[PATCH 00/33] stm32: enable logging features

[Simon Glass]

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 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