[PATCH 00/33] stm32: enable logging features

[Patrick DELAUNAY]

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

2/ time to check for each debug trace: because I increase the log level
   (gd->default_log_level = 6 < MAX_LOG_LEVEL=8)

3/ treatment added in log_console_emit (some printf) and
    log_dispatch (processing_msg / gd->loghead)

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 ?

Patrick

> >
> > STM32MP> bootstage report
> > Timer summary in microseconds (12 records):
> >        Mark    Elapsed  Stage
> >           0          0  reset
> >     230,028    230,028  SPL
> >     996,117    766,089  end SPL
> >     999,082      2,965  board_init_f
> >   1,220,225    221,143  board_init_r
> >   1,718,641    498,416  id=64
> >   1,746,096     27,455  id=65
> >   1,748,202      2,106  main_loop
> >   4,509,271  2,761,069  id=175
> >
> > Accumulated time:
> >                 58,481  dm_f
> >                 68,881  dm_r
> >                 89,385  dm_spl
> >
> >
> >

(...)