[PATCH 1/3] log: don't build the trace buffer when log is not ready

[PATCH 1/3] log: don't build the trace buffer when log is not ready

[Patrick Delaunay]

Update _log function to drop any traces when log is yet initialized:
vsnprintf is no more executed in this case.

This patch allows to reduce the cost for the dropped early debug trace.

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

 common/log.c | 13 ++++++++-----
 1 file changed, 8 insertions(+), 5 deletions(-)

diff --git a/common/log.c b/common/log.c
index 4b6f3fcd04..aadf533fb2 100644
--- a/common/log.c
+++ b/common/log.c
@@ -227,6 +227,9 @@ int _log(enum log_category_t cat, enum log_level_t level, const char *file,
 	struct log_rec rec;
 	va_list args;
 
+	if (!gd)
+		return -ENOSYS;
+
 	/* Check for message continuation */
 	if (cat == LOGC_CONT)
 		cat = gd->logc_prev;
@@ -239,15 +242,15 @@ int _log(enum log_category_t cat, enum log_level_t level, const char *file,
 	rec.file = file;
 	rec.line = line;
 	rec.func = func;
+
+	if (!(gd->flags & GD_FLG_LOG_READY)) {
+		gd->log_drop_count++;
+		return -ENOSYS;
+	}
 	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++;
-		return -ENOSYS;
-	}
 	if (!log_dispatch(&rec)) {
 		gd->logc_prev = cat;
 		gd->logl_prev = level;
-- 
2.17.1

[PATCH 2/3] log: use debug uart to output trace before LOG init

[Patrick Delaunay]

Use the debug uart functions to output the traces before
the log initialization (when CONFIG_LOG is not activated)
as it is done in puts/putc function in console.c.

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

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

diff --git a/common/log.c b/common/log.c
index aadf533fb2..aa5505943f 100644
--- a/common/log.c
+++ b/common/log.c
@@ -7,6 +7,7 @@
  */
 
 #include <common.h>
+#include <debug_uart.h>
 #include <log.h>
 #include <malloc.h>
 #include <dm/uclass.h>
@@ -245,6 +246,16 @@ 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++;
+
+		/* manage droppped trace at default level with debug uart */
+		if (IS_ENABLED(CONFIG_DEBUG_UART) &&
+		    (rec.level <= CONFIG_LOG_DEFAULT_LEVEL || rec.force_debug)) {
+			va_start(args, fmt);
+			vsnprintf(buf, sizeof(buf), fmt, args);
+			printascii(buf);
+			va_end(args);
+		}
+
 		return -ENOSYS;
 	}
 	va_start(args, fmt);
-- 
2.17.1

[PATCH 2/3] log: use debug uart to output trace before LOG init

[Simon Glass]

+Heinrich Schuchardt

On Fri, 6 Nov 2020 at 10:55, Patrick Delaunay <patrick.delaunay@st.com> wrote:
>
> Use the debug uart functions to output the traces before
> the log initialization (when CONFIG_LOG is not activated)
> as it is done in puts/putc function in console.c.
>
> 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>
> ---
>
>  common/log.c | 11 +++++++++++
>  1 file changed, 11 insertions(+)

Reviewed-by: Simon Glass <sjg@chromium.org>

Again this needs a sandbox test

>
> diff --git a/common/log.c b/common/log.c
> index aadf533fb2..aa5505943f 100644
> --- a/common/log.c
> +++ b/common/log.c
> @@ -7,6 +7,7 @@
>   */
>
>  #include <common.h>
> +#include <debug_uart.h>
>  #include <log.h>
>  #include <malloc.h>
>  #include <dm/uclass.h>
> @@ -245,6 +246,16 @@ 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++;
> +
> +               /* manage droppped trace at default level with debug uart */

dropped


> +               if (IS_ENABLED(CONFIG_DEBUG_UART) &&
> +                   (rec.level <= CONFIG_LOG_DEFAULT_LEVEL || rec.force_debug)) {
> +                       va_start(args, fmt);
> +                       vsnprintf(buf, sizeof(buf), fmt, args);
> +                       printascii(buf);
> +                       va_end(args);
> +               }
> +
>                 return -ENOSYS;
>         }
>         va_start(args, fmt);
> --
> 2.17.1
>

[PATCH 2/3] log: use debug uart to output trace before LOG init

[Patrick DELAUNAY]

Hi Simon,

> From: Simon Glass <sjg@chromium.org>
> Sent: mercredi 11 novembre 2020 15:32
> To: Patrick DELAUNAY <patrick.delaunay@st.com>; Heinrich Schuchardt
> 
> +Heinrich Schuchardt

OK

> On Fri, 6 Nov 2020 at 10:55, Patrick Delaunay <patrick.delaunay@st.com> wrote:
> >
> > Use the debug uart functions to output the traces before the log
> > initialization (when CONFIG_LOG is not activated) as it is done in
> > puts/putc function in console.c.
> >
> > 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>
> > ---
> >
> >  common/log.c | 11 +++++++++++
> >  1 file changed, 11 insertions(+)
> 
> Reviewed-by: Simon Glass <sjg@chromium.org>
> 
> Again this needs a sandbox test

I am preparing a sandbox test for v2.
But I think I will replace printascii() by console function, puts()

To use all supported feature of console.c

=> DEBUG_UART / PRE_CONSOLE_BUFFER / CONSOLE_RECORD

CONSOLE_RECORD is needed by unitary test...
 
> >
> > diff --git a/common/log.c b/common/log.c index aadf533fb2..aa5505943f
> > 100644
> > --- a/common/log.c
> > +++ b/common/log.c
> > @@ -7,6 +7,7 @@
> >   */
> >
> >  #include <common.h>
> > +#include <debug_uart.h>
> >  #include <log.h>
> >  #include <malloc.h>
> >  #include <dm/uclass.h>
> > @@ -245,6 +246,16 @@ 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++;
> > +
> > +               /* manage droppped trace at default level with debug
> > + uart */
> 
> dropped
> 

OK

 
> > +               if (IS_ENABLED(CONFIG_DEBUG_UART) &&
> > +                   (rec.level <= CONFIG_LOG_DEFAULT_LEVEL ||
> rec.force_debug)) {
> > +                       va_start(args, fmt);
> > +                       vsnprintf(buf, sizeof(buf), fmt, args);
> > +                       printascii(buf);
> > +                       va_end(args);
> > +               }
> > +
> >                 return -ENOSYS;
> >         }
> >         va_start(args, fmt);
> > --
> > 2.17.1
> >

Thanks for the review

Patrick

[PATCH 3/3] log: call vsnprintf only when it is needed to emit trace

[Patrick Delaunay]

Reduce the log overhead when the traces are filtered,
by moving the vsnprintf call from _log() to log_dispatch().

This patch avoids the printf treatment when LOG features is
activated, but trace is filtered, for example when
MAX_LOG_LEVEL=8 and LOG_DEFAULT_LEVEL=6.

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

# Conflicts:
#	common/log.c
---

 common/log.c | 22 ++++++++++++++--------
 1 file changed, 14 insertions(+), 8 deletions(-)

diff --git a/common/log.c b/common/log.c
index aa5505943f..e5681ab323 100644
--- a/common/log.c
+++ b/common/log.c
@@ -198,9 +198,10 @@ static bool log_passes_filters(struct log_device *ldev, struct log_rec *rec)
  * @rec:	log record to dispatch
  * Return:	0 msg sent, 1 msg not sent while already dispatching another msg
  */
-static int log_dispatch(struct log_rec *rec)
+static int log_dispatch(struct log_rec *rec, const char *fmt, va_list args)
 {
 	struct log_device *ldev;
+	char buf[CONFIG_SYS_CBSIZE];
 
 	/*
 	 * When a log driver writes messages (e.g. via the network stack) this
@@ -214,8 +215,13 @@ static int log_dispatch(struct log_rec *rec)
 	gd->processing_msg = true;
 	list_for_each_entry(ldev, &gd->log_head, sibling_node) {
 		if ((ldev->flags & LOGDF_ENABLE) &&
-		    log_passes_filters(ldev, rec))
+		    log_passes_filters(ldev, rec)) {
+			if (!rec->msg) {
+				vsnprintf(buf, sizeof(buf), fmt, args);
+				rec->msg = buf;
+			}
 			ldev->drv->emit(ldev, rec);
+		}
 	}
 	gd->processing_msg = false;
 	return 0;
@@ -224,7 +230,6 @@ static int log_dispatch(struct log_rec *rec)
 int _log(enum log_category_t cat, enum log_level_t level, const char *file,
 	 int line, const char *func, const char *fmt, ...)
 {
-	char buf[CONFIG_SYS_CBSIZE];
 	struct log_rec rec;
 	va_list args;
 
@@ -243,13 +248,16 @@ int _log(enum log_category_t cat, enum log_level_t level, const char *file,
 	rec.file = file;
 	rec.line = line;
 	rec.func = func;
+	rec.msg = NULL;
 
 	if (!(gd->flags & GD_FLG_LOG_READY)) {
 		gd->log_drop_count++;
 
-		/* manage droppped trace at default level with debug uart */
+		/* manage droppped traces at default level with debug uart */
 		if (IS_ENABLED(CONFIG_DEBUG_UART) &&
 		    (rec.level <= CONFIG_LOG_DEFAULT_LEVEL || rec.force_debug)) {
+			char buf[CONFIG_SYS_CBSIZE];
+
 			va_start(args, fmt);
 			vsnprintf(buf, sizeof(buf), fmt, args);
 			printascii(buf);
@@ -259,13 +267,11 @@ int _log(enum log_category_t cat, enum log_level_t level, const char *file,
 		return -ENOSYS;
 	}
 	va_start(args, fmt);
-	vsnprintf(buf, sizeof(buf), fmt, args);
-	va_end(args);
-	rec.msg = buf;
-	if (!log_dispatch(&rec)) {
+	if (!log_dispatch(&rec, fmt, args)) {
 		gd->logc_prev = cat;
 		gd->logl_prev = level;
 	}
+	va_end(args);
 
 	return 0;
 }
-- 
2.17.1

[PATCH 3/3] log: call vsnprintf only when it is needed to emit trace

[Simon Glass]

On Fri, 6 Nov 2020 at 10:55, Patrick Delaunay <patrick.delaunay@st.com> wrote:
>
> Reduce the log overhead when the traces are filtered,
> by moving the vsnprintf call from _log() to log_dispatch().
>
> This patch avoids the printf treatment when LOG features is
> activated, but trace is filtered, for example when
> MAX_LOG_LEVEL=8 and LOG_DEFAULT_LEVEL=6.
>
> Signed-off-by: Patrick Delaunay <patrick.delaunay@st.com>
>
> # Conflicts:
> #       common/log.c
> ---
>
>  common/log.c | 22 ++++++++++++++--------
>  1 file changed, 14 insertions(+), 8 deletions(-)

Reviewed-by: Simon Glass <sjg@chromium.org>

[PATCH 1/3] log: don't build the trace buffer when log is not ready

[Simon Glass]

Hi Patrick,

On Fri, 6 Nov 2020 at 10:55, Patrick Delaunay <patrick.delaunay@st.com> wrote:
>
> Update _log function to drop any traces when log is yet initialized:
> vsnprintf is no more executed in this case.
>
> This patch allows to reduce the cost for the dropped early debug trace.
>
> Signed-off-by: Patrick Delaunay <patrick.delaunay@st.com>
> ---
>
>  common/log.c | 13 ++++++++-----
>  1 file changed, 8 insertions(+), 5 deletions(-)

Reviewed-by: Simon Glass <sjg@chromium.org>

But this needs a test.