[v2,4/9] log: use console puts to output trace before LOG init

Use the console puts functions to output the traces before
the log initialization (when CONFIG_LOG is not activated).

This patch allows to display the first U-Boot traces
(with macro debug) when CONFIG_DEBUG_UART is activated
and not only drop them.

For example for traces in board_f.c requested by the macro debug,
when LOG_DEBUG is defined and CONFIG_LOG is activated.

Signed-off-by: Patrick Delaunay <patrick.delaunay@st.com>
---

Changes in v2:
- replace printascii by console puts, remove test on CONFIG_DEBUG_UART

 common/log.c | 9 +++++++++
 1 file changed, 9 insertions(+)

On 11/27/20 5:20 AM, Patrick Delaunay wrote:
> Use the console puts functions to output the traces before
> the log initialization (when CONFIG_LOG is not activated).
> 
> This patch allows to display the first U-Boot traces
> (with macro debug) when CONFIG_DEBUG_UART is activated
> and not only drop them.
> 
> For example for traces in board_f.c requested by the macro debug,
> when LOG_DEBUG is defined and CONFIG_LOG is activated.
> 
> Signed-off-by: Patrick Delaunay <patrick.delaunay@st.com>
> ---
> 
> Changes in v2:
> - replace printascii by console puts, remove test on CONFIG_DEBUG_UART
> 
>   common/log.c | 9 +++++++++
>   1 file changed, 9 insertions(+)
> 
> diff --git a/common/log.c b/common/log.c
> index 212789d6b3..a4ed7d79f8 100644
> --- a/common/log.c
> +++ b/common/log.c
> @@ -246,6 +246,15 @@ int _log(enum log_category_t cat, enum log_level_t level, const char *file,
>   
>   	if (!(gd->flags & GD_FLG_LOG_READY)) {
>   		gd->log_drop_count++;
> +
> +		/* display dropped traces with console puts and DEBUG_UART */
> +		if (rec.level <= CONFIG_LOG_DEFAULT_LEVEL || rec.force_debug) {
> +			va_start(args, fmt);
> +			vsnprintf(buf, sizeof(buf), fmt, args);
> +			puts(buf);
> +			va_end(args);
> +		}
> +
>   		return -ENOSYS;
>   	}
>   	va_start(args, fmt);
> 

Couldn't this be done like

  	va_start(args, fmt);
  	vsnprintf(buf, sizeof(buf), fmt, args);
  	va_end(args);
  	rec.msg = buf;
	if (!gd || !(gd->flags & GD_FLG_LOG_READY)) {
		if (gd)
			gd->log_drop_count++;
		if (rec.level < CONFIG_LOG_DEFAULT_LEVEL ||
		    rec.force_debug)
			puts(buf);
		return -ENOSYS;
	}

I don't see the optimization of not doing the vsnprintf() coming up very
often. Also, shouldn't this return 0 instead of ENOSYS if something is
actually printed?

--Sean

Hi Sean,

> From: Sean Anderson <seanga2@gmail.com>
> Sent: vendredi 27 novembre 2020 16:02
> 
> On 11/27/20 5:20 AM, Patrick Delaunay wrote:
> > Use the console puts functions to output the traces before the log
> > initialization (when CONFIG_LOG is not activated).
> >
> > This patch allows to display the first U-Boot traces (with macro
> > debug) when CONFIG_DEBUG_UART is activated and not only drop them.
> >
> > For example for traces in board_f.c requested by the macro debug, when
> > LOG_DEBUG is defined and CONFIG_LOG is activated.
> >
> > Signed-off-by: Patrick Delaunay <patrick.delaunay@st.com>
> > ---
> >
> > Changes in v2:
> > - replace printascii by console puts, remove test on CONFIG_DEBUG_UART
> >
> >   common/log.c | 9 +++++++++
> >   1 file changed, 9 insertions(+)
> >
> > diff --git a/common/log.c b/common/log.c index 212789d6b3..a4ed7d79f8
> > 100644
> > --- a/common/log.c
> > +++ b/common/log.c
> > @@ -246,6 +246,15 @@ int _log(enum log_category_t cat, enum
> > log_level_t level, const char *file,
> >
> >   	if (!(gd->flags & GD_FLG_LOG_READY)) {
> >   		gd->log_drop_count++;
> > +
> > +		/* display dropped traces with console puts and DEBUG_UART */
> > +		if (rec.level <= CONFIG_LOG_DEFAULT_LEVEL ||
> rec.force_debug) {
> > +			va_start(args, fmt);
> > +			vsnprintf(buf, sizeof(buf), fmt, args);
> > +			puts(buf);
> > +			va_end(args);
> > +		}
> > +
> >   		return -ENOSYS;
> >   	}
> >   	va_start(args, fmt);
> >
> 
> Couldn't this be done like
> 
>   	va_start(args, fmt);
>   	vsnprintf(buf, sizeof(buf), fmt, args);
>   	va_end(args);
>   	rec.msg = buf;
> 	if (!gd || !(gd->flags & GD_FLG_LOG_READY)) {
> 		if (gd)
> 			gd->log_drop_count++;
> 		if (rec.level < CONFIG_LOG_DEFAULT_LEVEL ||
> 		    rec.force_debug)
> 			puts(buf);
> 		return -ENOSYS;
> 	}
> 
> I don't see the optimization of not doing the vsnprintf() coming up very often.

In normal use case, I agree it should be occurs often, with default LOGLEVEL.

But it is not the case if LOGLEVEL increase => all the debug existing in
U-boot code will call the log function and then the vsnprintf can cost few us
(I make measurement on stm32mp157 board)

This patch at be done after Simon remarks in
http://u-boot.10912.n7.nabble.com/PATCH-00-33-stm32-enable-logging-features-tt429439.html#none

The better optimization found is to execute the vsnprintf only before the log message is really dispatched 
(patch 2/9 of the serie),

I reduce drastically the log overhead when MAX_LOG_LEVEL=8 and when
all log messages > CONFIG_LOG_DEFAULT_LEVEL= 6 are filtered
=> with patch 2/9: all debug messages in U-Boot are build but not displayed. 

This patch is not elegant, but it is a consequence of this optimization.

> Also, shouldn't this return 0 instead of ENOSYS if something is actually printed?

I hesitate about the return value, but I choose to keep the ENOSYS because 
even if the trace can be displayed (but not is all the case, only if DEBUG_UART is activated)

The real LOG feature failed => LOG trace is dropped, the string with added information
(filename , line, function name) is not build and not send to all LOG backend
(console et/or in network et/or other support log backend)

But return value of _log() is not important because is never used except in cmd_log.c
(not used in log() macro).

But to be more clear I can add trace for dropped trace:

 		if (rec.level < CONFIG_LOG_DEFAULT_LEVEL ||
 		    rec.force_debug) {
+ 			puts("log dropped:");
 			puts(buf);
		}

> 
> --Sean

Patrick

On Fri, Nov 27, 2020 at 11:20:54AM +0100, Patrick Delaunay wrote:

> Use the console puts functions to output the traces before
> the log initialization (when CONFIG_LOG is not activated).
> 
> This patch allows to display the first U-Boot traces
> (with macro debug) when CONFIG_DEBUG_UART is activated
> and not only drop them.
> 
> For example for traces in board_f.c requested by the macro debug,
> when LOG_DEBUG is defined and CONFIG_LOG is activated.
> 
> Signed-off-by: Patrick Delaunay <patrick.delaunay@st.com>

Applied to u-boot/master, thanks!