[PATCH v2 0/9] log: don't build the trace buffer when log is not ready
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(-)
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));
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
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
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!
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;
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;
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
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
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!
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);
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
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!
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);
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-...
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!
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') + +@pytest.mark.buildconfigspec('debug_uart') +@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)
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
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!
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));
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;
- 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;@@ -565,15 +565,17 @@ void putc(const char c)
void puts(const char *s) {
- if (!gd)
return;
- 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;
Reviewed-by: Sean Anderson seanga2@gmail.com
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
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!
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))
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
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
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
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!
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;
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
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!
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; }
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!
participants (5)
-
Patrick DELAUNAY -
Patrick Delaunay
-
Sean Anderson -
Simon Glass -
Tom Rini