[PATCH v2 0/9] log: don't build the trace buffer when log is not ready

[PATCH v2 0/9] log: don't build the trace buffer when log is not ready

[Patrick Delaunay]

It is the V2 of [1], rebased and with added tests.

To allow test (with console record), I replace the debug uart
function used to display the dropped messages printascii() by
the console generic function puts().

This function allows to support all the features defined in
console.c (as DEBUG_UART, PRE_CONSOLE_BUFFER, CONSOLE_RECORD)
without duplicate them (no more nedd to test CONFIG_DEBUG_UART
for example).

PS: I don't sure that the added trace added for test in
    arch/sandbox/cpu/start.c = "sandbox: starting..."
    is not disturbing.
    see patch 5 = "test: add test for dropped trace before log_init"

[1] http://patchwork.ozlabs.org/project/uboot/list/?series=212739


Changes in v2:
- Add test for LOGL_FORCE_DEBUG (NEW)
- add test to count the dropped messages (NEW)
- replace printascii by console puts, remove test on CONFIG_DEBUG_UART
- Add test of displayed messages requested before log_init (NEW)
- update gd test in console function puts and putc (cosmetic)
- Record all messages in console, even when dropped (NEW)
- added test for content of dropped messages (NEW)

Patrick Delaunay (9):
  test: add LOGL_FORCE_DEBUG flags support in log tests
  log: don't build the trace buffer when log is not ready
  test: log: add test for dropped messages
  log: use console puts to output trace before LOG init
  test: add test for dropped trace before log_init
  console: remove duplicated test on gd value
  console: allow to record console output before ready
  test: log: add test for console output of dropped messages
  log: call vsnprintf only when it is needed to emit trace

 arch/sandbox/cpu/start.c  |  5 +++
 common/console.c          | 32 ++++++++---------
 common/log.c              | 40 +++++++++++++++------
 test/log/log_test.c       | 76 +++++++++++++++++++++++++++++++--------
 test/py/tests/test_log.py | 11 ++++++
 5 files changed, 122 insertions(+), 42 deletions(-)

-- 
2.17.1

[PATCH v2 1/9] test: add LOGL_FORCE_DEBUG flags support in log tests

[Patrick Delaunay]

Add a check of the _log function with LOGL_FORCE_DEBUG flags,
used to force the trace display.

The trace should be displayed for all the level when flags
have LOGL_FORCE_DEBUG bit is set, for any filter.

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

Changes in v2:
- Add test for LOGL_FORCE_DEBUG (NEW)

 test/log/log_test.c | 29 ++++++++++++++++++++---------
 1 file changed, 20 insertions(+), 9 deletions(-)

diff --git a/test/log/log_test.c b/test/log/log_test.c
index ea4fc6bc30..15874751f9 100644
--- a/test/log/log_test.c
+++ b/test/log/log_test.c
@@ -26,6 +26,11 @@ static int do_log_run(int cat, const char *file)
 		_log(log_uc_cat(cat), i, file, 100 + i, "func", "_log %d\n",
 		     i);
 	}
+	/* test with LOGL_COUNT flag */
+	for (i = LOGL_FIRST; i < LOGL_COUNT; i++) {
+		_log(log_uc_cat(cat), i | LOGL_FORCE_DEBUG, file, 100 + i,
+		     "func", "_log force %d\n", i);
+	}
 
 	gd->log_fmt = log_get_default_format();
 	return 0;
@@ -38,6 +43,7 @@ static int do_log_run(int cat, const char *file)
 #define EXPECT_LOG BIT(0)
 #define EXPECT_DIRECT BIT(1)
 #define EXPECT_EXTRA BIT(2)
+#define EXPECT_FORCE BIT(3)
 
 static int do_check_log_entries(struct unit_test_state *uts, int flags, int min,
 				int max)
@@ -54,6 +60,11 @@ static int do_check_log_entries(struct unit_test_state *uts, int flags, int min,
 		for (; i <= LOGL_MAX ; i++)
 			ut_assert_nextline("func() _log %d", i);
 
+	for (i = LOGL_FIRST; i < LOGL_COUNT; i++) {
+		if (flags & EXPECT_FORCE)
+			ut_assert_nextline("func() _log force %d", i);
+	}
+
 	ut_assert_console_end();
 	return 0;
 }
@@ -66,10 +77,10 @@ static int do_check_log_entries(struct unit_test_state *uts, int flags, int min,
 
 #define check_log_entries_flags(flags) \
 	check_log_entries_flags_levels(flags, LOGL_FIRST, _LOG_MAX_LEVEL)
-#define check_log_entries() check_log_entries_flags(EXPECT_LOG | EXPECT_DIRECT)
+#define check_log_entries() check_log_entries_flags(EXPECT_LOG | EXPECT_DIRECT | EXPECT_FORCE)
 #define check_log_entries_extra() \
-	check_log_entries_flags(EXPECT_LOG | EXPECT_DIRECT | EXPECT_EXTRA)
-#define check_log_entries_none() check_log_entries_flags(0)
+	check_log_entries_flags(EXPECT_LOG | EXPECT_DIRECT | EXPECT_EXTRA | EXPECT_FORCE)
+#define check_log_entries_none() check_log_entries_flags(EXPECT_FORCE)
 
 /* Check a category filter using the first category */
 int log_test_cat_allow(struct unit_test_state *uts)
@@ -126,7 +137,7 @@ int log_test_file(struct unit_test_state *uts)
 
 	ut_assertok(console_record_reset_enable());
 	log_run_file("file");
-	check_log_entries_flags(EXPECT_DIRECT | EXPECT_EXTRA);
+	check_log_entries_flags(EXPECT_DIRECT | EXPECT_EXTRA | EXPECT_FORCE);
 
 	ut_assertok(console_record_reset_enable());
 	log_run_file("file2");
@@ -147,7 +158,7 @@ int log_test_file_second(struct unit_test_state *uts)
 
 	ut_assertok(console_record_reset_enable());
 	log_run_file("file2");
-	check_log_entries_flags(EXPECT_DIRECT | EXPECT_EXTRA);
+	check_log_entries_flags(EXPECT_DIRECT | EXPECT_EXTRA | EXPECT_FORCE);
 
 	ut_assertok(log_remove_filter("console", filt));
 	return 0;
@@ -182,8 +193,8 @@ int log_test_level(struct unit_test_state *uts)
 
 	ut_assertok(console_record_reset_enable());
 	log_run();
-	check_log_entries_flags_levels(EXPECT_LOG | EXPECT_DIRECT, LOGL_FIRST,
-				       LOGL_WARNING);
+	check_log_entries_flags_levels(EXPECT_LOG | EXPECT_DIRECT | EXPECT_FORCE,
+				       LOGL_FIRST, LOGL_WARNING);
 
 	ut_assertok(log_remove_filter("console", filt));
 	return 0;
@@ -351,7 +362,7 @@ int log_test_level_deny(struct unit_test_state *uts)
 
 	ut_assertok(console_record_reset_enable());
 	log_run();
-	check_log_entries_flags_levels(EXPECT_LOG | EXPECT_DIRECT,
+	check_log_entries_flags_levels(EXPECT_LOG | EXPECT_DIRECT | EXPECT_FORCE,
 				       LOGL_WARNING + 1, _LOG_MAX_LEVEL);
 
 	ut_assertok(log_remove_filter("console", filt1));
@@ -374,7 +385,7 @@ int log_test_min(struct unit_test_state *uts)
 
 	ut_assertok(console_record_reset_enable());
 	log_run();
-	check_log_entries_flags_levels(EXPECT_LOG | EXPECT_DIRECT,
+	check_log_entries_flags_levels(EXPECT_LOG | EXPECT_DIRECT | EXPECT_FORCE,
 				       LOGL_WARNING, LOGL_INFO - 1);
 
 	ut_assertok(log_remove_filter("console", filt1));
-- 
2.17.1

[PATCH v2 2/9] 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.

Reviewed-by: Simon Glass <sjg@chromium.org>
Signed-off-by: Patrick Delaunay <patrick.delaunay@st.com>
---

(no changes since v1)

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

diff --git a/common/log.c b/common/log.c
index ce39918e04..212789d6b3 100644
--- a/common/log.c
+++ b/common/log.c
@@ -228,6 +228,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;
@@ -240,15 +243,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 v2 3/9] test: log: add test for dropped messages

[Patrick Delaunay]

Add a new test to check the dropped messages when LOG is not ready
with log_drop_count and the result of _log().

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

Changes in v2:
- add test to count the dropped messages (NEW)

 test/log/log_test.c | 43 +++++++++++++++++++++++++++++++++++--------
 1 file changed, 35 insertions(+), 8 deletions(-)

diff --git a/test/log/log_test.c b/test/log/log_test.c
index 15874751f9..6bafc1e315 100644
--- a/test/log/log_test.c
+++ b/test/log/log_test.c
@@ -15,30 +15,38 @@
 DECLARE_GLOBAL_DATA_PTR;
 
 /* emit some sample log records in different ways, for testing */
-static int do_log_run(int cat, const char *file)
+static int do_log_run(struct unit_test_state *uts, int cat, const char *file)
 {
 	int i;
+	int ret, expected_ret;
+
+	if (gd->flags & GD_FLG_LOG_READY)
+		expected_ret = 0;
+	else
+		expected_ret = -ENOSYS;
 
 	gd->log_fmt = LOGF_TEST;
 	debug("debug\n");
 	for (i = LOGL_FIRST; i < LOGL_COUNT; i++) {
 		log(cat, i, "log %d\n", i);
-		_log(log_uc_cat(cat), i, file, 100 + i, "func", "_log %d\n",
-		     i);
+		ret = _log(log_uc_cat(cat), i, file, 100 + i,
+			   "func", "_log %d\n", i);
+		ut_asserteq(ret, expected_ret);
 	}
 	/* test with LOGL_COUNT flag */
 	for (i = LOGL_FIRST; i < LOGL_COUNT; i++) {
-		_log(log_uc_cat(cat), i | LOGL_FORCE_DEBUG, file, 100 + i,
-		     "func", "_log force %d\n", i);
+		ret = _log(log_uc_cat(cat), i | LOGL_FORCE_DEBUG, file, 100 + i,
+			   "func", "_log force %d\n", i);
+		ut_asserteq(ret, expected_ret);
 	}
 
 	gd->log_fmt = log_get_default_format();
 	return 0;
 }
 
-#define log_run_cat(cat) do_log_run(cat, "file")
-#define log_run_file(file) do_log_run(UCLASS_SPI, file)
-#define log_run() do_log_run(UCLASS_SPI, "file")
+#define log_run_cat(cat) do_log_run(uts, cat, "file")
+#define log_run_file(file) do_log_run(uts, UCLASS_SPI, file)
+#define log_run() do_log_run(uts, UCLASS_SPI, "file")
 
 #define EXPECT_LOG BIT(0)
 #define EXPECT_DIRECT BIT(1)
@@ -393,3 +401,22 @@ int log_test_min(struct unit_test_state *uts)
 	return 0;
 }
 LOG_TEST_FLAGS(log_test_min, UT_TESTF_CONSOLE_REC);
+
+/* Check dropped traces */
+int log_test_dropped(struct unit_test_state *uts)
+{
+	/* force LOG not ready */
+	gd->flags &= ~(GD_FLG_LOG_READY);
+	gd->log_drop_count = 0;
+
+	ut_assertok(console_record_reset_enable());
+	log_run();
+
+	ut_asserteq(gd->log_drop_count, 3 * (LOGL_COUNT - LOGL_FIRST - 1));
+
+	gd->flags |= GD_FLG_LOG_READY;
+	gd->log_drop_count = 0;
+
+	return 0;
+}
+LOG_TEST_FLAGS(log_test_dropped, UT_TESTF_CONSOLE_REC);
-- 
2.17.1

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

[Patrick Delaunay]

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);
-- 
2.17.1

[PATCH v2 5/9] test: add test for dropped trace before log_init

[Patrick Delaunay]

Add test for dropped trace before log_init, displayed by debug uart.

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

Changes in v2:
- Add test of displayed messages requested before log_init (NEW)

 arch/sandbox/cpu/start.c  |  5 +++++
 test/py/tests/test_log.py | 11 +++++++++++
 2 files changed, 16 insertions(+)

diff --git a/arch/sandbox/cpu/start.c b/arch/sandbox/cpu/start.c
index a03e5aa0b3..c5184d59be 100644
--- a/arch/sandbox/cpu/start.c
+++ b/arch/sandbox/cpu/start.c
@@ -8,6 +8,7 @@
 #include <dm/root.h>
 #include <errno.h>
 #include <init.h>
+#include <log.h>
 #include <os.h>
 #include <cli.h>
 #include <sort.h>
@@ -465,6 +466,10 @@ int main(int argc, char *argv[])
 	 */
 	gd->reloc_off = (ulong)gd->arch.text_base;
 
+	/* sandbox test: log functions called before log_init in board_init_f */
+	log_info("sandbox: starting...\n");
+	log_debug("debug: %s\n", __func__);
+
 	/* Do pre- and post-relocation init */
 	board_init_f(0);
 
diff --git a/test/py/tests/test_log.py b/test/py/tests/test_log.py
index 387b392ce9..f889120f2b 100644
--- a/test/py/tests/test_log.py
+++ b/test/py/tests/test_log.py
@@ -36,3 +36,14 @@ def test_log_format(u_boot_console):
         run_with_format('FLfm', 'file.c:123-func() msg')
         run_with_format('lm', 'NOTICE. msg')
         run_with_format('m', 'msg')
+
+ at pytest.mark.buildconfigspec('debug_uart')
+ at pytest.mark.boardspec('sandbox')
+def test_log_dropped(u_boot_console):
+    """Test dropped 'log' message when debug_uart is activated"""
+
+    cons = u_boot_console
+    cons.restart_uboot()
+    output = cons.get_spawn_output().replace('\r', '')
+    assert 'sandbox: starting...' in output
+    assert (not 'debug: main' in output)
-- 
2.17.1

[PATCH v2 6/9] console: remove duplicated test on gd value

[Patrick Delaunay]

Reorder test on gd value and remove the duplicated test (!gd)
in putc and puts function.

This patch is a preliminary step for rework of this function.

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

Changes in v2:
- update gd test in console function puts and putc (cosmetic)

 common/console.c | 16 ++++++++--------
 1 file changed, 8 insertions(+), 8 deletions(-)

diff --git a/common/console.c b/common/console.c
index 3348436da6..70579af042 100644
--- a/common/console.c
+++ b/common/console.c
@@ -517,22 +517,22 @@ static inline void print_pre_console_buffer(int flushpoint) {}
 
 void putc(const char c)
 {
+	if (!gd)
+		return;
 #ifdef CONFIG_SANDBOX
 	/* sandbox can send characters to stdout before it has a console */
-	if (!gd || !(gd->flags & GD_FLG_SERIAL_READY)) {
+	if (!(gd->flags & GD_FLG_SERIAL_READY)) {
 		os_putc(c);
 		return;
 	}
 #endif
 #ifdef CONFIG_DEBUG_UART
 	/* if we don't have a console yet, use the debug UART */
-	if (!gd || !(gd->flags & GD_FLG_SERIAL_READY)) {
+	if (!(gd->flags & GD_FLG_SERIAL_READY)) {
 		printch(c);
 		return;
 	}
 #endif
-	if (!gd)
-		return;
 #ifdef CONFIG_CONSOLE_RECORD
 	if ((gd->flags & GD_FLG_RECORD) && gd->console_out.start)
 		membuff_putbyte((struct membuff *)&gd->console_out, c);
@@ -565,15 +565,17 @@ void putc(const char c)
 
 void puts(const char *s)
 {
+	if (!gd)
+		return;
 #ifdef CONFIG_SANDBOX
 	/* sandbox can send characters to stdout before it has a console */
-	if (!gd || !(gd->flags & GD_FLG_SERIAL_READY)) {
+	if (!(gd->flags & GD_FLG_SERIAL_READY)) {
 		os_puts(s);
 		return;
 	}
 #endif
 #ifdef CONFIG_DEBUG_UART
-	if (!gd || !(gd->flags & GD_FLG_SERIAL_READY)) {
+	if (!(gd->flags & GD_FLG_SERIAL_READY)) {
 		while (*s) {
 			int ch = *s++;
 
@@ -582,8 +584,6 @@ void puts(const char *s)
 		return;
 	}
 #endif
-	if (!gd)
-		return;
 #ifdef CONFIG_CONSOLE_RECORD
 	if ((gd->flags & GD_FLG_RECORD) && gd->console_out.start)
 		membuff_put((struct membuff *)&gd->console_out, s, strlen(s));
-- 
2.17.1

[PATCH v2 7/9] console: allow to record console output before ready

[Patrick Delaunay]

Allow to record the console output before before U-Boot
has a console ready.

This patch allows to test the console output in sandbox test
based on console record.

It is possible because GD_FLG_RECORD and GD_FLG_SERIAL_READY
are 2 independent flags.

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

Changes in v2:
- Record all messages in console, even when dropped (NEW)

 common/console.c | 16 ++++++++--------
 1 file changed, 8 insertions(+), 8 deletions(-)

diff --git a/common/console.c b/common/console.c
index 70579af042..c3d552bb3e 100644
--- a/common/console.c
+++ b/common/console.c
@@ -519,6 +519,10 @@ void putc(const char c)
 {
 	if (!gd)
 		return;
+#ifdef CONFIG_CONSOLE_RECORD
+	if ((gd->flags & GD_FLG_RECORD) && gd->console_out.start)
+		membuff_putbyte((struct membuff *)&gd->console_out, c);
+#endif
 #ifdef CONFIG_SANDBOX
 	/* sandbox can send characters to stdout before it has a console */
 	if (!(gd->flags & GD_FLG_SERIAL_READY)) {
@@ -533,10 +537,6 @@ void putc(const char c)
 		return;
 	}
 #endif
-#ifdef CONFIG_CONSOLE_RECORD
-	if ((gd->flags & GD_FLG_RECORD) && gd->console_out.start)
-		membuff_putbyte((struct membuff *)&gd->console_out, c);
-#endif
 #ifdef CONFIG_SILENT_CONSOLE
 	if (gd->flags & GD_FLG_SILENT) {
 		if (!(gd->flags & GD_FLG_DEVINIT))
@@ -567,6 +567,10 @@ void puts(const char *s)
 {
 	if (!gd)
 		return;
+#ifdef CONFIG_CONSOLE_RECORD
+	if ((gd->flags & GD_FLG_RECORD) && gd->console_out.start)
+		membuff_put((struct membuff *)&gd->console_out, s, strlen(s));
+#endif
 #ifdef CONFIG_SANDBOX
 	/* sandbox can send characters to stdout before it has a console */
 	if (!(gd->flags & GD_FLG_SERIAL_READY)) {
@@ -584,10 +588,6 @@ void puts(const char *s)
 		return;
 	}
 #endif
-#ifdef CONFIG_CONSOLE_RECORD
-	if ((gd->flags & GD_FLG_RECORD) && gd->console_out.start)
-		membuff_put((struct membuff *)&gd->console_out, s, strlen(s));
-#endif
 #ifdef CONFIG_SILENT_CONSOLE
 	if (gd->flags & GD_FLG_SILENT) {
 		if (!(gd->flags & GD_FLG_DEVINIT))
-- 
2.17.1

[PATCH v2 8/9] test: log: add test for console output of dropped messages

[Patrick Delaunay]

Add a new test to check the content of the dropped messages
sent to console puts function.

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

Changes in v2:
- added test for content of dropped messages (NEW)

 test/log/log_test.c | 8 ++++++++
 1 file changed, 8 insertions(+)

diff --git a/test/log/log_test.c b/test/log/log_test.c
index 6bafc1e315..82234a6994 100644
--- a/test/log/log_test.c
+++ b/test/log/log_test.c
@@ -52,6 +52,7 @@ static int do_log_run(struct unit_test_state *uts, int cat, const char *file)
 #define EXPECT_DIRECT BIT(1)
 #define EXPECT_EXTRA BIT(2)
 #define EXPECT_FORCE BIT(3)
+#define EXPECT_DEBUG BIT(4)
 
 static int do_check_log_entries(struct unit_test_state *uts, int flags, int min,
 				int max)
@@ -63,6 +64,10 @@ static int do_check_log_entries(struct unit_test_state *uts, int flags, int min,
 			ut_assert_nextline("do_log_run() log %d", i);
 		if (flags & EXPECT_DIRECT)
 			ut_assert_nextline("func() _log %d", i);
+		if (flags & EXPECT_DEBUG) {
+			ut_assert_nextline("log %d", i);
+			ut_assert_nextline("_log %d", i);
+		}
 	}
 	if (flags & EXPECT_EXTRA)
 		for (; i <= LOGL_MAX ; i++)
@@ -71,6 +76,8 @@ static int do_check_log_entries(struct unit_test_state *uts, int flags, int min,
 	for (i = LOGL_FIRST; i < LOGL_COUNT; i++) {
 		if (flags & EXPECT_FORCE)
 			ut_assert_nextline("func() _log force %d", i);
+		if (flags & EXPECT_DEBUG)
+			ut_assert_nextline("_log force %d", i);
 	}
 
 	ut_assert_console_end();
@@ -413,6 +420,7 @@ int log_test_dropped(struct unit_test_state *uts)
 	log_run();
 
 	ut_asserteq(gd->log_drop_count, 3 * (LOGL_COUNT - LOGL_FIRST - 1));
+	check_log_entries_flags_levels(EXPECT_DEBUG, LOGL_FIRST, CONFIG_LOG_DEFAULT_LEVEL);
 
 	gd->flags |= GD_FLG_LOG_READY;
 	gd->log_drop_count = 0;
-- 
2.17.1

[PATCH v2 9/9] 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.

Reviewed-by: Simon Glass <sjg@chromium.org>
Signed-off-by: Patrick Delaunay <patrick.delaunay@st.com>
---

(no changes since v1)

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

diff --git a/common/log.c b/common/log.c
index a4ed7d79f8..767f0febc5 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,12 +248,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;
+	rec.msg = NULL;
 
 	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) {
+			char buf[CONFIG_SYS_CBSIZE];
+
 			va_start(args, fmt);
 			vsnprintf(buf, sizeof(buf), fmt, args);
 			puts(buf);
@@ -258,13 +266,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 v2 2/9] log: don't build the trace buffer when log is not ready

[Sean Anderson]

On 11/27/20 5:20 AM, Patrick Delaunay 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.
> 
> Reviewed-by: Simon Glass <sjg@chromium.org>
> Signed-off-by: Patrick Delaunay <patrick.delaunay@st.com>
> ---
> 
> (no changes since v1)
> 
>   common/log.c | 13 ++++++++-----
>   1 file changed, 8 insertions(+), 5 deletions(-)
> 
> diff --git a/common/log.c b/common/log.c
> index ce39918e04..212789d6b3 100644
> --- a/common/log.c
> +++ b/common/log.c
> @@ -228,6 +228,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;

How early are you expecting this function to get called? AFAIK this will
only return true before board_init_f_init_reserve. Shouldn't functions
that early just not call log in the first place?

--Sean

> +
>   	/* Check for message continuation */
>   	if (cat == LOGC_CONT)
>   		cat = gd->logc_prev;
> @@ -240,15 +243,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;
> 

[PATCH v2 1/9] test: add LOGL_FORCE_DEBUG flags support in log tests

[Sean Anderson]

On 11/27/20 5:20 AM, Patrick Delaunay wrote:
> Add a check of the _log function with LOGL_FORCE_DEBUG flags,
> used to force the trace display.
> 
> The trace should be displayed for all the level when flags
> have LOGL_FORCE_DEBUG bit is set, for any filter.
> 
> Signed-off-by: Patrick Delaunay <patrick.delaunay@st.com>
> ---
> 
> Changes in v2:
> - Add test for LOGL_FORCE_DEBUG (NEW)
> 
>   test/log/log_test.c | 29 ++++++++++++++++++++---------
>   1 file changed, 20 insertions(+), 9 deletions(-)
> 
> diff --git a/test/log/log_test.c b/test/log/log_test.c
> index ea4fc6bc30..15874751f9 100644
> --- a/test/log/log_test.c
> +++ b/test/log/log_test.c
> @@ -26,6 +26,11 @@ static int do_log_run(int cat, const char *file)
>   		_log(log_uc_cat(cat), i, file, 100 + i, "func", "_log %d\n",
>   		     i);
>   	}
> +	/* test with LOGL_COUNT flag */
> +	for (i = LOGL_FIRST; i < LOGL_COUNT; i++) {
> +		_log(log_uc_cat(cat), i | LOGL_FORCE_DEBUG, file, 100 + i,
> +		     "func", "_log force %d\n", i);
> +	}
>   
>   	gd->log_fmt = log_get_default_format();
>   	return 0;
> @@ -38,6 +43,7 @@ static int do_log_run(int cat, const char *file)
>   #define EXPECT_LOG BIT(0)
>   #define EXPECT_DIRECT BIT(1)
>   #define EXPECT_EXTRA BIT(2)
> +#define EXPECT_FORCE BIT(3)
>   
>   static int do_check_log_entries(struct unit_test_state *uts, int flags, int min,
>   				int max)
> @@ -54,6 +60,11 @@ static int do_check_log_entries(struct unit_test_state *uts, int flags, int min,
>   		for (; i <= LOGL_MAX ; i++)
>   			ut_assert_nextline("func() _log %d", i);
>   
> +	for (i = LOGL_FIRST; i < LOGL_COUNT; i++) {
> +		if (flags & EXPECT_FORCE)
> +			ut_assert_nextline("func() _log force %d", i);
> +	}
> +
>   	ut_assert_console_end();
>   	return 0;
>   }
> @@ -66,10 +77,10 @@ static int do_check_log_entries(struct unit_test_state *uts, int flags, int min,
>   
>   #define check_log_entries_flags(flags) \
>   	check_log_entries_flags_levels(flags, LOGL_FIRST, _LOG_MAX_LEVEL)
> -#define check_log_entries() check_log_entries_flags(EXPECT_LOG | EXPECT_DIRECT)
> +#define check_log_entries() check_log_entries_flags(EXPECT_LOG | EXPECT_DIRECT | EXPECT_FORCE)
>   #define check_log_entries_extra() \
> -	check_log_entries_flags(EXPECT_LOG | EXPECT_DIRECT | EXPECT_EXTRA)
> -#define check_log_entries_none() check_log_entries_flags(0)
> +	check_log_entries_flags(EXPECT_LOG | EXPECT_DIRECT | EXPECT_EXTRA | EXPECT_FORCE)
> +#define check_log_entries_none() check_log_entries_flags(EXPECT_FORCE)
>   
>   /* Check a category filter using the first category */
>   int log_test_cat_allow(struct unit_test_state *uts)
> @@ -126,7 +137,7 @@ int log_test_file(struct unit_test_state *uts)
>   
>   	ut_assertok(console_record_reset_enable());
>   	log_run_file("file");
> -	check_log_entries_flags(EXPECT_DIRECT | EXPECT_EXTRA);
> +	check_log_entries_flags(EXPECT_DIRECT | EXPECT_EXTRA | EXPECT_FORCE);
>   
>   	ut_assertok(console_record_reset_enable());
>   	log_run_file("file2");
> @@ -147,7 +158,7 @@ int log_test_file_second(struct unit_test_state *uts)
>   
>   	ut_assertok(console_record_reset_enable());
>   	log_run_file("file2");
> -	check_log_entries_flags(EXPECT_DIRECT | EXPECT_EXTRA);
> +	check_log_entries_flags(EXPECT_DIRECT | EXPECT_EXTRA | EXPECT_FORCE);
>   
>   	ut_assertok(log_remove_filter("console", filt));
>   	return 0;
> @@ -182,8 +193,8 @@ int log_test_level(struct unit_test_state *uts)
>   
>   	ut_assertok(console_record_reset_enable());
>   	log_run();
> -	check_log_entries_flags_levels(EXPECT_LOG | EXPECT_DIRECT, LOGL_FIRST,
> -				       LOGL_WARNING);
> +	check_log_entries_flags_levels(EXPECT_LOG | EXPECT_DIRECT | EXPECT_FORCE,
> +				       LOGL_FIRST, LOGL_WARNING);
>   
>   	ut_assertok(log_remove_filter("console", filt));
>   	return 0;
> @@ -351,7 +362,7 @@ int log_test_level_deny(struct unit_test_state *uts)
>   
>   	ut_assertok(console_record_reset_enable());
>   	log_run();
> -	check_log_entries_flags_levels(EXPECT_LOG | EXPECT_DIRECT,
> +	check_log_entries_flags_levels(EXPECT_LOG | EXPECT_DIRECT | EXPECT_FORCE,
>   				       LOGL_WARNING + 1, _LOG_MAX_LEVEL);
>   
>   	ut_assertok(log_remove_filter("console", filt1));
> @@ -374,7 +385,7 @@ int log_test_min(struct unit_test_state *uts)
>   
>   	ut_assertok(console_record_reset_enable());
>   	log_run();
> -	check_log_entries_flags_levels(EXPECT_LOG | EXPECT_DIRECT,
> +	check_log_entries_flags_levels(EXPECT_LOG | EXPECT_DIRECT | EXPECT_FORCE,
>   				       LOGL_WARNING, LOGL_INFO - 1);
>   
>   	ut_assertok(log_remove_filter("console", filt1));
> 

Reviewed-by: Sean Anderson <seanga2@gmail.com>

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

[Sean Anderson]

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

[PATCH v2 6/9] console: remove duplicated test on gd value

[Sean Anderson]

On 11/27/20 5:20 AM, Patrick Delaunay wrote:
> Reorder test on gd value and remove the duplicated test (!gd)
> in putc and puts function.
> 
> This patch is a preliminary step for rework of this function.
> 
> Signed-off-by: Patrick Delaunay <patrick.delaunay@st.com>
> ---
> 
> Changes in v2:
> - update gd test in console function puts and putc (cosmetic)
> 
>   common/console.c | 16 ++++++++--------
>   1 file changed, 8 insertions(+), 8 deletions(-)
> 
> diff --git a/common/console.c b/common/console.c
> index 3348436da6..70579af042 100644
> --- a/common/console.c
> +++ b/common/console.c
> @@ -517,22 +517,22 @@ static inline void print_pre_console_buffer(int flushpoint) {}
>   
>   void putc(const char c)
>   {
> +	if (!gd)
> +		return;
>   #ifdef CONFIG_SANDBOX
>   	/* sandbox can send characters to stdout before it has a console */
> -	if (!gd || !(gd->flags & GD_FLG_SERIAL_READY)) {
> +	if (!(gd->flags & GD_FLG_SERIAL_READY)) {
>   		os_putc(c);
>   		return;
>   	}
>   #endif
>   #ifdef CONFIG_DEBUG_UART
>   	/* if we don't have a console yet, use the debug UART */
> -	if (!gd || !(gd->flags & GD_FLG_SERIAL_READY)) {
> +	if (!(gd->flags & GD_FLG_SERIAL_READY)) {
>   		printch(c);
>   		return;
>   	}
>   #endif
> -	if (!gd)
> -		return;
>   #ifdef CONFIG_CONSOLE_RECORD
>   	if ((gd->flags & GD_FLG_RECORD) && gd->console_out.start)
>   		membuff_putbyte((struct membuff *)&gd->console_out, c);
> @@ -565,15 +565,17 @@ void putc(const char c)
>   
>   void puts(const char *s)
>   {
> +	if (!gd)
> +		return;
>   #ifdef CONFIG_SANDBOX
>   	/* sandbox can send characters to stdout before it has a console */
> -	if (!gd || !(gd->flags & GD_FLG_SERIAL_READY)) {
> +	if (!(gd->flags & GD_FLG_SERIAL_READY)) {
>   		os_puts(s);
>   		return;
>   	}
>   #endif
>   #ifdef CONFIG_DEBUG_UART
> -	if (!gd || !(gd->flags & GD_FLG_SERIAL_READY)) {
> +	if (!(gd->flags & GD_FLG_SERIAL_READY)) {
>   		while (*s) {
>   			int ch = *s++;
>   
> @@ -582,8 +584,6 @@ void puts(const char *s)
>   		return;
>   	}
>   #endif
> -	if (!gd)
> -		return;
>   #ifdef CONFIG_CONSOLE_RECORD
>   	if ((gd->flags & GD_FLG_RECORD) && gd->console_out.start)
>   		membuff_put((struct membuff *)&gd->console_out, s, strlen(s));
> 

Reviewed-by: Sean Anderson <seanga2@gmail.com>

[PATCH v2 3/9] test: log: add test for dropped messages

[Simon Glass]

On Fri, 27 Nov 2020 at 03:21, Patrick Delaunay <patrick.delaunay@st.com> wrote:
>
> Add a new test to check the dropped messages when LOG is not ready
> with log_drop_count and the result of _log().
>
> Signed-off-by: Patrick Delaunay <patrick.delaunay@st.com>
> ---
>
> Changes in v2:
> - add test to count the dropped messages (NEW)
>
>  test/log/log_test.c | 43 +++++++++++++++++++++++++++++++++++--------
>  1 file changed, 35 insertions(+), 8 deletions(-)

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

[PATCH v2 5/9] test: add test for dropped trace before log_init

[Simon Glass]

On Fri, 27 Nov 2020 at 03:21, Patrick Delaunay <patrick.delaunay@st.com> wrote:
>
> Add test for dropped trace before log_init, displayed by debug uart.
>
> Signed-off-by: Patrick Delaunay <patrick.delaunay@st.com>
> ---
>
> Changes in v2:
> - Add test of displayed messages requested before log_init (NEW)
>
>  arch/sandbox/cpu/start.c  |  5 +++++
>  test/py/tests/test_log.py | 11 +++++++++++
>  2 files changed, 16 insertions(+)

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

[PATCH v2 7/9] console: allow to record console output before ready

[Simon Glass]

Hi Patrick,

On Fri, 27 Nov 2020 at 03:21, Patrick Delaunay <patrick.delaunay@st.com> wrote:
>
> Allow to record the console output before before U-Boot
> has a console ready.
>
> This patch allows to test the console output in sandbox test
> based on console record.
>
> It is possible because GD_FLG_RECORD and GD_FLG_SERIAL_READY
> are 2 independent flags.
>
> Signed-off-by: Patrick Delaunay <patrick.delaunay@st.com>
> ---
>
> Changes in v2:
> - Record all messages in console, even when dropped (NEW)
>
>  common/console.c | 16 ++++++++--------
>  1 file changed, 8 insertions(+), 8 deletions(-)
>
> diff --git a/common/console.c b/common/console.c
> index 70579af042..c3d552bb3e 100644
> --- a/common/console.c
> +++ b/common/console.c
> @@ -519,6 +519,10 @@ void putc(const char c)
>  {
>         if (!gd)
>                 return;
> +#ifdef CONFIG_CONSOLE_RECORD

Can we use CONFIG_IS_ENABLED() here and avoid the #ifdef? We might
need to add some inline functions for the case where console_out is
not available. See global_data.h for some examples.

> +       if ((gd->flags & GD_FLG_RECORD) && gd->console_out.start)
> +               membuff_putbyte((struct membuff *)&gd->console_out, c);
> +#endif
>  #ifdef CONFIG_SANDBOX
>         /* sandbox can send characters to stdout before it has a console */
>         if (!(gd->flags & GD_FLG_SERIAL_READY)) {
> @@ -533,10 +537,6 @@ void putc(const char c)
>                 return;
>         }
>  #endif
> -#ifdef CONFIG_CONSOLE_RECORD
> -       if ((gd->flags & GD_FLG_RECORD) && gd->console_out.start)
> -               membuff_putbyte((struct membuff *)&gd->console_out, c);
> -#endif
>  #ifdef CONFIG_SILENT_CONSOLE
>         if (gd->flags & GD_FLG_SILENT) {
>                 if (!(gd->flags & GD_FLG_DEVINIT))
> @@ -567,6 +567,10 @@ void puts(const char *s)
>  {
>         if (!gd)
>                 return;
> +#ifdef CONFIG_CONSOLE_RECORD
> +       if ((gd->flags & GD_FLG_RECORD) && gd->console_out.start)
> +               membuff_put((struct membuff *)&gd->console_out, s, strlen(s));
> +#endif
>  #ifdef CONFIG_SANDBOX
>         /* sandbox can send characters to stdout before it has a console */
>         if (!(gd->flags & GD_FLG_SERIAL_READY)) {
> @@ -584,10 +588,6 @@ void puts(const char *s)
>                 return;
>         }
>  #endif
> -#ifdef CONFIG_CONSOLE_RECORD
> -       if ((gd->flags & GD_FLG_RECORD) && gd->console_out.start)
> -               membuff_put((struct membuff *)&gd->console_out, s, strlen(s));
> -#endif
>  #ifdef CONFIG_SILENT_CONSOLE
>         if (gd->flags & GD_FLG_SILENT) {
>                 if (!(gd->flags & GD_FLG_DEVINIT))
> --
> 2.17.1
>

Regards,
Simon

[PATCH v2 8/9] test: log: add test for console output of dropped messages

[Simon Glass]

On Fri, 27 Nov 2020 at 03:21, Patrick Delaunay <patrick.delaunay@st.com> wrote:
>
> Add a new test to check the content of the dropped messages
> sent to console puts function.
>
> Signed-off-by: Patrick Delaunay <patrick.delaunay@st.com>
> ---
>
> Changes in v2:
> - added test for content of dropped messages (NEW)
>
>  test/log/log_test.c | 8 ++++++++
>  1 file changed, 8 insertions(+)

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

[PATCH v2 2/9] log: don't build the trace buffer when log is not ready

[Simon Glass]

Hi Sean,

On Fri, 27 Nov 2020 at 07:50, Sean Anderson <seanga2@gmail.com> wrote:
>
> On 11/27/20 5:20 AM, Patrick Delaunay 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.
> >
> > Reviewed-by: Simon Glass <sjg@chromium.org>
> > Signed-off-by: Patrick Delaunay <patrick.delaunay@st.com>
> > ---
> >
> > (no changes since v1)
> >
> >   common/log.c | 13 ++++++++-----
> >   1 file changed, 8 insertions(+), 5 deletions(-)
> >
> > diff --git a/common/log.c b/common/log.c
> > index ce39918e04..212789d6b3 100644
> > --- a/common/log.c
> > +++ b/common/log.c
> > @@ -228,6 +228,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;
>
> How early are you expecting this function to get called? AFAIK this will
> only return true before board_init_f_init_reserve. Shouldn't functions
> that early just not call log in the first place?

Heinrich may have some thoughts here.

I think we will end up using log very early, since it is sort-of the
replacement for printf() and debug().

Regards,
Simon

[PATCH v2 1/9] test: add LOGL_FORCE_DEBUG flags support in log tests

[Simon Glass]

On Fri, 27 Nov 2020 at 03:21, Patrick Delaunay <patrick.delaunay@st.com> wrote:
>
> Add a check of the _log function with LOGL_FORCE_DEBUG flags,
> used to force the trace display.
>
> The trace should be displayed for all the level when flags
> have LOGL_FORCE_DEBUG bit is set, for any filter.
>
> Signed-off-by: Patrick Delaunay <patrick.delaunay@st.com>
> ---
>
> Changes in v2:
> - Add test for LOGL_FORCE_DEBUG (NEW)
>
>  test/log/log_test.c | 29 ++++++++++++++++++++---------
>  1 file changed, 20 insertions(+), 9 deletions(-)

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

[PATCH v2 6/9] console: remove duplicated test on gd value

[Simon Glass]

On Fri, 27 Nov 2020 at 03:21, Patrick Delaunay <patrick.delaunay@st.com> wrote:
>
> Reorder test on gd value and remove the duplicated test (!gd)
> in putc and puts function.
>
> This patch is a preliminary step for rework of this function.
>
> Signed-off-by: Patrick Delaunay <patrick.delaunay@st.com>
> ---
>
> Changes in v2:
> - update gd test in console function puts and putc (cosmetic)
>
>  common/console.c | 16 ++++++++--------
>  1 file changed, 8 insertions(+), 8 deletions(-)

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

[PATCH v2 2/9] log: don't build the trace buffer when log is not ready

[Patrick DELAUNAY]

Hi Sean,

> From: Sean Anderson <seanga2@gmail.com>
> Sent: vendredi 27 novembre 2020 15:51
> 
> On 11/27/20 5:20 AM, Patrick Delaunay 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.
> >
> > Reviewed-by: Simon Glass <sjg@chromium.org>
> > Signed-off-by: Patrick Delaunay <patrick.delaunay@st.com>
> > ---
> >
> > (no changes since v1)
> >
> >   common/log.c | 13 ++++++++-----
> >   1 file changed, 8 insertions(+), 5 deletions(-)
> >
> > diff --git a/common/log.c b/common/log.c index ce39918e04..212789d6b3
> > 100644
> > --- a/common/log.c
> > +++ b/common/log.c
> > @@ -228,6 +228,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;
> 
> How early are you expecting this function to get called? AFAIK this will only return
> true before board_init_f_init_reserve. Shouldn't functions that early just not call log
> in the first place?

I don't change the existing behavior, this test exists since the first commit on log.c, done
by Simon.

Patch 8/15 of
http://patchwork.ozlabs.org/project/uboot/list/?series=16677&state=*

I check, this line exist since the first version of this serie....

But I think you are right, log/debug fucntions should not called before C runtime is ready
(including gd configuration in board_init_f_alloc_reserve), it seens as over-protection.

> --Sean
> 
> > +
> >   	/* Check for message continuation */
> >   	if (cat == LOGC_CONT)
> >   		cat = gd->logc_prev;
> > @@ -240,15 +243,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;
> >

Patrick

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

[Patrick DELAUNAY]

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

[Uboot-stm32] [PATCH v2 7/9] console: allow to record console output before ready

[Patrick DELAUNAY]

Hi Simon,

> From: Uboot-stm32 <uboot-stm32-bounces@st-md-mailman.stormreply.com> On
> Behalf Of Simon Glass
> 
> Hi Patrick,
> 
> On Fri, 27 Nov 2020 at 03:21, Patrick Delaunay <patrick.delaunay@st.com>
> wrote:
> >
> > Allow to record the console output before before U-Boot has a console
> > ready.
> >
> > This patch allows to test the console output in sandbox test based on
> > console record.
> >
> > It is possible because GD_FLG_RECORD and GD_FLG_SERIAL_READY are 2
> > independent flags.
> >
> > Signed-off-by: Patrick Delaunay <patrick.delaunay@st.com>
> > ---
> >
> > Changes in v2:
> > - Record all messages in console, even when dropped (NEW)
> >
> >  common/console.c | 16 ++++++++--------
> >  1 file changed, 8 insertions(+), 8 deletions(-)
> >
> > diff --git a/common/console.c b/common/console.c index
> > 70579af042..c3d552bb3e 100644
> > --- a/common/console.c
> > +++ b/common/console.c
> > @@ -519,6 +519,10 @@ void putc(const char c)  {
> >         if (!gd)
> >                 return;
> > +#ifdef CONFIG_CONSOLE_RECORD
> 
> Can we use CONFIG_IS_ENABLED() here and avoid the #ifdef? We might need to
> add some inline functions for the case where console_out is not available. See
> global_data.h for some examples.
...
> 
> Regards,
> Simon

I see this warning when I push this patchset but I preferred sent the path as it,
to easy the review as I just move existing line.

But in parallel I prepare a other patchset to remove all (or almost all) the #if def CONFIG in console.c

I don't sent it yet as I am still solving some compilation issues, but it is solved now....

https://gitlab.denx.de/u-boot/custodians/u-boot-stm/-/pipelines/5431

So I will sent it I few days, after a last review / test.

Patrick

[Uboot-stm32] [PATCH v2 7/9] console: allow to record console output before ready

[Simon Glass]

On Wed, 2 Dec 2020 at 03:55, Patrick DELAUNAY <patrick.delaunay@st.com> wrote:
>
> Hi Simon,
>
> > From: Uboot-stm32 <uboot-stm32-bounces@st-md-mailman.stormreply.com> On
> > Behalf Of Simon Glass
> >
> > Hi Patrick,
> >
> > On Fri, 27 Nov 2020 at 03:21, Patrick Delaunay <patrick.delaunay@st.com>
> > wrote:
> > >
> > > Allow to record the console output before before U-Boot has a console
> > > ready.
> > >
> > > This patch allows to test the console output in sandbox test based on
> > > console record.
> > >
> > > It is possible because GD_FLG_RECORD and GD_FLG_SERIAL_READY are 2
> > > independent flags.
> > >
> > > Signed-off-by: Patrick Delaunay <patrick.delaunay@st.com>
> > > ---
> > >
> > > Changes in v2:
> > > - Record all messages in console, even when dropped (NEW)
> > >
> > >  common/console.c | 16 ++++++++--------
> > >  1 file changed, 8 insertions(+), 8 deletions(-)
> > >
> > > diff --git a/common/console.c b/common/console.c index
> > > 70579af042..c3d552bb3e 100644
> > > --- a/common/console.c
> > > +++ b/common/console.c
> > > @@ -519,6 +519,10 @@ void putc(const char c)  {
> > >         if (!gd)
> > >                 return;
> > > +#ifdef CONFIG_CONSOLE_RECORD
> >
> > Can we use CONFIG_IS_ENABLED() here and avoid the #ifdef? We might need to
> > add some inline functions for the case where console_out is not available. See
> > global_data.h for some examples.
> ...
> >
> > Regards,
> > Simon
>
> I see this warning when I push this patchset but I preferred sent the path as it,
> to easy the review as I just move existing line.
>
> But in parallel I prepare a other patchset to remove all (or almost all) the #if def CONFIG in console.c
>
> I don't sent it yet as I am still solving some compilation issues, but it is solved now....
>
> https://gitlab.denx.de/u-boot/custodians/u-boot-stm/-/pipelines/5431
>
> So I will sent it I few days, after a last review / test.

OK thanks.

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

[PATCH v2 1/9] test: add LOGL_FORCE_DEBUG flags support in log tests

[Tom Rini]

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

> Add a check of the _log function with LOGL_FORCE_DEBUG flags,
> used to force the trace display.
> 
> The trace should be displayed for all the level when flags
> have LOGL_FORCE_DEBUG bit is set, for any filter.
> 
> Signed-off-by: Patrick Delaunay <patrick.delaunay@st.com>
> Reviewed-by: Sean Anderson <seanga2@gmail.com>
> Reviewed-by: Simon Glass <sjg@chromium.org>

Applied to u-boot/master, thanks!

-- 
Tom
-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 659 bytes
Desc: not available
URL: <https://lists.denx.de/pipermail/u-boot/attachments/20210116/ca5a881c/attachment.sig>

[PATCH v2 2/9] log: don't build the trace buffer when log is not ready

[Tom Rini]

On Fri, Nov 27, 2020 at 11:20:52AM +0100, Patrick Delaunay 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.
> 
> Reviewed-by: Simon Glass <sjg@chromium.org>
> Signed-off-by: Patrick Delaunay <patrick.delaunay@st.com>

Applied to u-boot/master, thanks!

-- 
Tom
-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 659 bytes
Desc: not available
URL: <https://lists.denx.de/pipermail/u-boot/attachments/20210116/42ac5ea6/attachment.sig>

[PATCH v2 3/9] test: log: add test for dropped messages

[Tom Rini]

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

> Add a new test to check the dropped messages when LOG is not ready
> with log_drop_count and the result of _log().
> 
> Signed-off-by: Patrick Delaunay <patrick.delaunay@st.com>
> Reviewed-by: Simon Glass <sjg@chromium.org>

Applied to u-boot/master, thanks!

-- 
Tom
-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 659 bytes
Desc: not available
URL: <https://lists.denx.de/pipermail/u-boot/attachments/20210116/252d1e3e/attachment.sig>

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

[Tom Rini]

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!

-- 
Tom
-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 659 bytes
Desc: not available
URL: <https://lists.denx.de/pipermail/u-boot/attachments/20210116/9b279ab0/attachment.sig>

[PATCH v2 5/9] test: add test for dropped trace before log_init

[Tom Rini]

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

> Add test for dropped trace before log_init, displayed by debug uart.
> 
> Signed-off-by: Patrick Delaunay <patrick.delaunay@st.com>
> Reviewed-by: Simon Glass <sjg@chromium.org>

Applied to u-boot/master, thanks!

-- 
Tom
-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 659 bytes
Desc: not available
URL: <https://lists.denx.de/pipermail/u-boot/attachments/20210116/f1947d10/attachment.sig>

[PATCH v2 6/9] console: remove duplicated test on gd value

[Tom Rini]

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

> Reorder test on gd value and remove the duplicated test (!gd)
> in putc and puts function.
> 
> This patch is a preliminary step for rework of this function.
> 
> Signed-off-by: Patrick Delaunay <patrick.delaunay@st.com>
> Reviewed-by: Sean Anderson <seanga2@gmail.com>
> Reviewed-by: Simon Glass <sjg@chromium.org>

Applied to u-boot/master, thanks!

-- 
Tom
-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 659 bytes
Desc: not available
URL: <https://lists.denx.de/pipermail/u-boot/attachments/20210116/0eb7234f/attachment.sig>

[PATCH v2 7/9] console: allow to record console output before ready

[Tom Rini]

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

> Allow to record the console output before before U-Boot
> has a console ready.
> 
> This patch allows to test the console output in sandbox test
> based on console record.
> 
> It is possible because GD_FLG_RECORD and GD_FLG_SERIAL_READY
> are 2 independent flags.
> 
> Signed-off-by: Patrick Delaunay <patrick.delaunay@st.com>
> Reviewed-by: Simon Glass <sjg@chromium.org>

Applied to u-boot/master, thanks!

-- 
Tom
-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 659 bytes
Desc: not available
URL: <https://lists.denx.de/pipermail/u-boot/attachments/20210116/92811320/attachment.sig>

[PATCH v2 8/9] test: log: add test for console output of dropped messages

[Tom Rini]

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

> Add a new test to check the content of the dropped messages
> sent to console puts function.
> 
> Signed-off-by: Patrick Delaunay <patrick.delaunay@st.com>
> Reviewed-by: Simon Glass <sjg@chromium.org>

Applied to u-boot/master, thanks!

-- 
Tom
-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 659 bytes
Desc: not available
URL: <https://lists.denx.de/pipermail/u-boot/attachments/20210116/b05de17b/attachment.sig>

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

[Tom Rini]

On Fri, Nov 27, 2020 at 11:20:59AM +0100, Patrick Delaunay 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.
> 
> Reviewed-by: Simon Glass <sjg@chromium.org>
> Signed-off-by: Patrick Delaunay <patrick.delaunay@st.com>

Applied to u-boot/master, thanks!

-- 
Tom
-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 659 bytes
Desc: not available
URL: <https://lists.denx.de/pipermail/u-boot/attachments/20210116/25c10957/attachment.sig>