| Message ID | 20201014091646.4233-1-patrick.delaunay@st.com |
|---|---|
| Headers | show |
| Series | stm32: enable logging features | expand |
Hi Patrick, On Wed, 14 Oct 2020 at 03:16, Patrick Delaunay <patrick.delaunay@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. > > 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 > > > > Patrick Delaunay (33): > arm: stm32mp: migrate trace to log macro > arm: stm32mp: migrate cmd_stm32prog to log macro > arm: stm32mp: bsec: migrate trace to log macro > pinctrl: stm32: migrate trace to log macro > gpio: stm32-gpio: migrate trace to dev and log macro > remoproc: stm32: migrate trace to log macro > ram: stm32: migrate trace to log macro > ram: stm32mp1: migrate trace to dev or log macro > mmc: stm32_sdmmc2: migrate trace to dev and log macro > timer: stm32: migrate trace to log macro > hwspinlock: stm32: migrate trace to log macro > rtc: stm32: migrate trace to log macro > watchdog: stm32mp: migrate trace to dev macro > power: regulator: stm32-verfbuf: define LOG_CATEGORY > misc: rcc: migrate trace to dev macro > misc: rcc: keep the rcc device name for subnode > clk: stm32mp1: migrate trace to dev and log macro > clk: clk_stm32f: migrate trace to dev and log macro > clk: clk_stm32h7: migrate trace to dev and log macro > reset: stm32-reset: migrate trace to dev and log macro > mailbox: stm32-ipcc: migrate trace to dev and log macro > i2c: stm32f7_i2c: migrate trace to dev and log macro > phy: stm32-usbphyc: migrate trace to dev and log macro > spi: stm32_spi: migrate trace to dev and log macro > spi: stm32_qspi: migrate trace to dev and log macro > mtd: stm32_fmc2: migrate trace to dev and log macro > memory: stm32-fmc2: migrate trace to dev and log macro > serial: stm32: define LOG_CATEGORY > video: stm32_ltdc: migrate trace to dev and log macro > video: stm32_dsi: migrate trace to dev and log macro > board: st: stm32mp1: migrate trace to dev and log macro > board: st: common: migrate trace to dev and log macro > configs: stm32mp15: enable LOG features > > arch/arm/mach-stm32mp/boot_params.c | 8 +- > arch/arm/mach-stm32mp/bsec.c | 38 +++-- > arch/arm/mach-stm32mp/cmd_stm32key.c | 3 +- > .../cmd_stm32prog/cmd_stm32prog.c | 4 +- > .../mach-stm32mp/cmd_stm32prog/stm32prog.c | 112 ++++++------- > .../mach-stm32mp/cmd_stm32prog/stm32prog.h | 2 +- > .../cmd_stm32prog/stm32prog_serial.c | 24 +-- > .../cmd_stm32prog/stm32prog_usb.c | 14 +- > arch/arm/mach-stm32mp/cpu.c | 18 ++- > arch/arm/mach-stm32mp/dram_init.c | 8 +- > arch/arm/mach-stm32mp/fdt.c | 17 +- > arch/arm/mach-stm32mp/pwr_regulator.c | 2 + > arch/arm/mach-stm32mp/spl.c | 16 +- > board/st/common/stm32mp_dfu.c | 3 +- > board/st/common/stm32mp_mtdparts.c | 5 +- > board/st/common/stpmic1.c | 5 +- > board/st/common/stusb160x.c | 2 + > board/st/stm32mp1/stm32mp1.c | 134 ++++++++-------- > configs/stm32mp15_basic_defconfig | 2 + > configs/stm32mp15_trusted_defconfig | 1 + > drivers/clk/clk_stm32f.c | 39 ++--- > drivers/clk/clk_stm32h7.c | 70 +++++---- > drivers/clk/clk_stm32mp1.c | 147 +++++++++--------- > drivers/gpio/stm32_gpio.c | 4 +- > drivers/hwspinlock/stm32_hwspinlock.c | 2 + > drivers/i2c/stm32f7_i2c.c | 74 ++++----- > drivers/mailbox/stm32-ipcc.c | 16 +- > drivers/memory/stm32-fmc2-ebi.c | 30 ++-- > drivers/misc/stm32_rcc.c | 10 +- > drivers/mmc/stm32_sdmmc2.c | 85 +++++----- > drivers/mtd/nand/raw/stm32_fmc2_nand.c | 40 +++-- > drivers/phy/phy-stm32-usbphyc.c | 18 ++- > drivers/pinctrl/pinctrl_stm32.c | 30 ++-- > drivers/power/regulator/stm32-vrefbuf.c | 2 + > drivers/ram/stm32_sdram.c | 10 +- > drivers/ram/stm32mp1/stm32mp1_ddr.c | 36 +++-- > drivers/ram/stm32mp1/stm32mp1_interactive.c | 4 +- > drivers/ram/stm32mp1/stm32mp1_ram.c | 37 +++-- > drivers/ram/stm32mp1/stm32mp1_tests.c | 19 ++- > drivers/ram/stm32mp1/stm32mp1_tuning.c | 124 +++++++-------- > drivers/remoteproc/stm32_copro.c | 3 +- > drivers/reset/stm32-reset.c | 13 +- > drivers/rtc/stm32_rtc.c | 3 + > drivers/serial/serial_stm32.c | 3 + > drivers/spi/stm32_qspi.c | 46 +++--- > drivers/spi/stm32_spi.c | 31 ++-- > drivers/timer/stm32_timer.c | 2 + > drivers/video/stm32/stm32_dsi.c | 18 ++- > drivers/video/stm32/stm32_ltdc.c | 33 ++-- > drivers/watchdog/stm32mp_wdt.c | 9 +- > 50 files changed, 731 insertions(+), 645 deletions(-) > > -- > 2.17.1 > Regards, Simon
Hi Simon, > From: Simon Glass <sjg@chromium.org> > Sent: jeudi 15 octobre 2020 17:06 > > Hi Patrick, > > On Wed, 14 Oct 2020 at 03:16, Patrick Delaunay <patrick.delaunay@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 > > > > > > (...)
Hi Patrick, On Thu, 15 Oct 2020 at 09:59, Patrick DELAUNAY <patrick.delaunay@st.com> wrote: > > Hi Simon, > > > From: Simon Glass <sjg@chromium.org> > > Sent: jeudi 15 octobre 2020 17:06 > > > > Hi Patrick, > > > > On Wed, 14 Oct 2020 at 03:16, Patrick Delaunay <patrick.delaunay@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
Hi Simon, > From: Simon Glass <sjg@chromium.org> > Sent: lundi 26 octobre 2020 20:23 > > Hi Patrick, > > On Thu, 15 Oct 2020 at 09:59, Patrick DELAUNAY <patrick.delaunay@st.com> > wrote: > > > > Hi Simon, > > > > > From: Simon Glass <sjg@chromium.org> > > > Sent: jeudi 15 octobre 2020 17:06 > > > > > > Hi Patrick, > > > > > > On Wed, 14 Oct 2020 at 03:16, Patrick Delaunay > > > <patrick.delaunay@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 > > > > 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 > Regards, > Simon Regards Patrick
Hi Patrick, On Wed, 28 Oct 2020 at 05:52, Patrick DELAUNAY <patrick.delaunay@st.com> wrote: > > Hi Simon, > > > From: Simon Glass <sjg@chromium.org> > > Sent: lundi 26 octobre 2020 20:23 > > > > Hi Patrick, > > > > On Thu, 15 Oct 2020 at 09:59, Patrick DELAUNAY <patrick.delaunay@st.com> > > wrote: > > > > > > Hi Simon, > > > > > > > From: Simon Glass <sjg@chromium.org> > > > > Sent: jeudi 15 octobre 2020 17:06 > > > > > > > > Hi Patrick, > > > > > > > > On Wed, 14 Oct 2020 at 03:16, Patrick Delaunay > > > > <patrick.delaunay@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
Hi Simon, > From: Simon Glass <sjg@chromium.org> > Sent: vendredi 30 octobre 2020 19:16 > > Hi Patrick, > > On Wed, 28 Oct 2020 at 05:52, Patrick DELAUNAY <patrick.delaunay@st.com> > wrote: > > > > Hi Simon, > > > > > From: Simon Glass <sjg@chromium.org> > > > Sent: lundi 26 octobre 2020 20:23 > > > > > > Hi Patrick, > > > > > > On Thu, 15 Oct 2020 at 09:59, Patrick DELAUNAY > > > <patrick.delaunay@st.com> > > > wrote: > > > > > > > > Hi Simon, > > > > > > > > > From: Simon Glass <sjg@chromium.org> > > > > > Sent: jeudi 15 octobre 2020 17:06 > > > > > > > > > > Hi Patrick, > > > > > > > > > > On Wed, 14 Oct 2020 at 03:16, Patrick Delaunay > > > > > <patrick.delaunay@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.
Hi Patrick, On Fri, 6 Nov 2020 at 10:45, Patrick DELAUNAY <patrick.delaunay@st.com> wrote: > > Hi Simon, > > > From: Simon Glass <sjg@chromium.org> > > Sent: vendredi 30 octobre 2020 19:16 > > > > Hi Patrick, > > > > On Wed, 28 Oct 2020 at 05:52, Patrick DELAUNAY <patrick.delaunay@st.com> > > wrote: > > > > > > Hi Simon, > > > > > > > From: Simon Glass <sjg@chromium.org> > > > > Sent: lundi 26 octobre 2020 20:23 > > > > > > > > Hi Patrick, > > > > > > > > On Thu, 15 Oct 2020 at 09:59, Patrick DELAUNAY > > > > <patrick.delaunay@st.com> > > > > wrote: > > > > > > > > > > Hi Simon, > > > > > > > > > > > From: Simon Glass <sjg@chromium.org> > > > > > > Sent: jeudi 15 octobre 2020 17:06 > > > > > > > > > > > > Hi Patrick, > > > > > > > > > > > > On Wed, 14 Oct 2020 at 03:16, Patrick Delaunay > > > > > > <patrick.delaunay@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 ?). 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
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). 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 Patrick Delaunay (33): arm: stm32mp: migrate trace to log macro arm: stm32mp: migrate cmd_stm32prog to log macro arm: stm32mp: bsec: migrate trace to log macro pinctrl: stm32: migrate trace to log macro gpio: stm32-gpio: migrate trace to dev and log macro remoproc: stm32: migrate trace to log macro ram: stm32: migrate trace to log macro ram: stm32mp1: migrate trace to dev or log macro mmc: stm32_sdmmc2: migrate trace to dev and log macro timer: stm32: migrate trace to log macro hwspinlock: stm32: migrate trace to log macro rtc: stm32: migrate trace to log macro watchdog: stm32mp: migrate trace to dev macro power: regulator: stm32-verfbuf: define LOG_CATEGORY misc: rcc: migrate trace to dev macro misc: rcc: keep the rcc device name for subnode clk: stm32mp1: migrate trace to dev and log macro clk: clk_stm32f: migrate trace to dev and log macro clk: clk_stm32h7: migrate trace to dev and log macro reset: stm32-reset: migrate trace to dev and log macro mailbox: stm32-ipcc: migrate trace to dev and log macro i2c: stm32f7_i2c: migrate trace to dev and log macro phy: stm32-usbphyc: migrate trace to dev and log macro spi: stm32_spi: migrate trace to dev and log macro spi: stm32_qspi: migrate trace to dev and log macro mtd: stm32_fmc2: migrate trace to dev and log macro memory: stm32-fmc2: migrate trace to dev and log macro serial: stm32: define LOG_CATEGORY video: stm32_ltdc: migrate trace to dev and log macro video: stm32_dsi: migrate trace to dev and log macro board: st: stm32mp1: migrate trace to dev and log macro board: st: common: migrate trace to dev and log macro configs: stm32mp15: enable LOG features arch/arm/mach-stm32mp/boot_params.c | 8 +- arch/arm/mach-stm32mp/bsec.c | 38 +++-- arch/arm/mach-stm32mp/cmd_stm32key.c | 3 +- .../cmd_stm32prog/cmd_stm32prog.c | 4 +- .../mach-stm32mp/cmd_stm32prog/stm32prog.c | 112 ++++++------- .../mach-stm32mp/cmd_stm32prog/stm32prog.h | 2 +- .../cmd_stm32prog/stm32prog_serial.c | 24 +-- .../cmd_stm32prog/stm32prog_usb.c | 14 +- arch/arm/mach-stm32mp/cpu.c | 18 ++- arch/arm/mach-stm32mp/dram_init.c | 8 +- arch/arm/mach-stm32mp/fdt.c | 17 +- arch/arm/mach-stm32mp/pwr_regulator.c | 2 + arch/arm/mach-stm32mp/spl.c | 16 +- board/st/common/stm32mp_dfu.c | 3 +- board/st/common/stm32mp_mtdparts.c | 5 +- board/st/common/stpmic1.c | 5 +- board/st/common/stusb160x.c | 2 + board/st/stm32mp1/stm32mp1.c | 134 ++++++++-------- configs/stm32mp15_basic_defconfig | 2 + configs/stm32mp15_trusted_defconfig | 1 + drivers/clk/clk_stm32f.c | 39 ++--- drivers/clk/clk_stm32h7.c | 70 +++++---- drivers/clk/clk_stm32mp1.c | 147 +++++++++--------- drivers/gpio/stm32_gpio.c | 4 +- drivers/hwspinlock/stm32_hwspinlock.c | 2 + drivers/i2c/stm32f7_i2c.c | 74 ++++----- drivers/mailbox/stm32-ipcc.c | 16 +- drivers/memory/stm32-fmc2-ebi.c | 30 ++-- drivers/misc/stm32_rcc.c | 10 +- drivers/mmc/stm32_sdmmc2.c | 85 +++++----- drivers/mtd/nand/raw/stm32_fmc2_nand.c | 40 +++-- drivers/phy/phy-stm32-usbphyc.c | 18 ++- drivers/pinctrl/pinctrl_stm32.c | 30 ++-- drivers/power/regulator/stm32-vrefbuf.c | 2 + drivers/ram/stm32_sdram.c | 10 +- drivers/ram/stm32mp1/stm32mp1_ddr.c | 36 +++-- drivers/ram/stm32mp1/stm32mp1_interactive.c | 4 +- drivers/ram/stm32mp1/stm32mp1_ram.c | 37 +++-- drivers/ram/stm32mp1/stm32mp1_tests.c | 19 ++- drivers/ram/stm32mp1/stm32mp1_tuning.c | 124 +++++++-------- drivers/remoteproc/stm32_copro.c | 3 +- drivers/reset/stm32-reset.c | 13 +- drivers/rtc/stm32_rtc.c | 3 + drivers/serial/serial_stm32.c | 3 + drivers/spi/stm32_qspi.c | 46 +++--- drivers/spi/stm32_spi.c | 31 ++-- drivers/timer/stm32_timer.c | 2 + drivers/video/stm32/stm32_dsi.c | 18 ++- drivers/video/stm32/stm32_ltdc.c | 33 ++-- drivers/watchdog/stm32mp_wdt.c | 9 +- 50 files changed, 731 insertions(+), 645 deletions(-)