logging: add minimal implementation #19322

andrewboie · 2019-09-22T23:59:12Z

The log mechanism, even in immediate mode, adds somewhere
between 1K-2K of footprint to applications that use it.

We want to standardize the logging APIs for all logging
within the kernel, but need to not let platforms with
very constrained RAM/ROM in the dust.

This patch introduces CONFIG_LOG_MINIMAL, which is a very
thin wrapper to printk(). It supports the APIs expressed
in logging/log.h.

This will be the new default for test cases.

log_printk()'s return value was removed to make it more like Zephyr printk().

Some code in shell and bluetooth monitor which assumed that the backend code existed has been adjusted.

Fixes: #19317

zephyrbot · 2019-09-23T00:02:48Z

All checks are passing now.

Tip: The bot edits this comment instead of posting a new one, so you can check the comment's history to see earlier messages.

ulfalizer · 2019-09-23T04:37:46Z

Would be nice to refactor the console stuff to do less selecting at some point. Those dependency loops get pretty hairy.

Also saw a bunch of select-with-unsatisfied-deps. issues there earlier, but maybe most of them have gotten fixed.

andrewboie · 2019-09-23T06:15:17Z

Would be nice to refactor the console stuff to do less selecting at some point. Those dependency loops get pretty hairy.

@ulfalizer I ran into this. If I change the "imply PRINTK" to "depends-on PRINTK" for CONFIG_LOG_MINIMAL, it all goes up in flames with a circular dependency.

Also saw a bunch of select-with-unsatisfied-deps. issues there earlier, but maybe most of them have gotten fixed.

Think I've seen these at times, but might because I modfied some Kconfig and needed to do a clean build.

ulfalizer · 2019-09-23T06:39:53Z

@ulfalizer I ran into this. If I change the "imply PRINTK" to "depends-on PRINTK" for CONFIG_LOG_MINIMAL, it all goes up in flames with a circular dependency.

Yeah, honestly those errors are a pain to figure out for me too. Usually, it helps to try to stick to depends on everywhere you can, so that all dependencies go in the same direction, and only select/imply very "locally" if you must (except for simple helper symbols).

Unrelated to this PR though.

include/logging/log.h

joerchan · 2019-09-25T07:26:33Z

Could this minimal implementation be used instead of LOG_IMMEDIATE?
It seems to be a lot of problems with LOG_IMMEDIATE, and it would be nice to reduce the amount of functionality that we have to maintain.

nordic-krch · 2019-09-25T10:50:30Z

It seems to be a lot of problems with LOG_IMMEDIATE

The main issue (once #19339 gets in) is the fact that when log immediate is enabled then thread stack usage increases and that will lead to mpu faults since stacks are tuned for deferred logging. Minimal logging won't help with that since main stack contributor is string formatting.

By switching to log minimal we safe ~2k of ROM compared to log_immediate but we lose things like pretty output (timestamp, module name/log level/function name prefix), support for multiple backends, integration with shell. Imo, the difference is significant enough to have both options.

nordic-krch · 2019-09-25T10:52:39Z

include/logging/log_core.h

+
+#define Z_LOG(_level, fmt, ...) do { \
+		if (Z_LOG_CONST_LEVEL_CHECK(_level)) { \
+			printk(fmt "\n", ##__VA_ARGS__); \


there is no locking here. Won't it crash if one log interrupts another? I guess that simple console like uart may survive but what about console over cdc acm?

it doesn't. these emit to the console drivers one character at a time.

LeiW000

For the code itself, I don't see anything wrong.

joerchan

log_strdup has an issue if it is called twice in the same call to LOG_INFO. I would really like to see this fixed, as there are instances where this happens in the stack at the moment. And using minimal logging would yield very confusing logging info when this happens. (see my earlier comment https://github.com/zephyrproject-rtos/zephyr/pull/19322/files#r327967725)

andrewboie · 2019-09-27T18:07:19Z

log_strdup has an issue if it is called twice in the same call to LOG_INFO.

I'm not seeing how this is related to my patch?
Seems a problem with the log system in general.
[edit] I see it now. Can we just document in log_strdup() that they shouldn't use it in this way? The problem here is that with minimal logging we can't start bringing in heap allocations as required. It will be extra code, and FuSa/MISRA-C both discourage runtime heap allocations in functionally safe applications -- and at the same time these log_strdup() calls are required for the standard frontend.

joerchan · 2019-09-30T12:08:15Z

@andrewboie We have discussed this offline and reached the conclusion that we can leave log_strdup like this. (although for the record the name is misleading and could possible lead to the same confusion for others).

andrewboie · 2019-09-30T21:10:40Z

Updated PR:

LOG_MINIMAL logic folded into __LOG and __LOG_HEXDUMP instead of Z_LOG/Z_LOG_HEXDUMP per @nordic-krch suggestion
Error type codes now printed for minimal logging
log_strdup() doc string updated to not rely on duplication behavior

Similar to how LOG_INIT(), LOG_PANIC(), etc are wrapped. Signed-off-by: Andrew Boie <andrew.p.boie@intel.com>

The same function should not be defined in two different headers. Signed-off-by: Andrew Boie <andrew.p.boie@intel.com>

printk() doesn't return a value, this doesn't need to either. Signed-off-by: Andrew Boie <andrew.p.boie@intel.com>

These checks should be against CONFIG_SHELL_LOG_BACKEND, and not against CONFIG_LOG, since it's possible to enable logging without building this particular backend. Signed-off-by: Andrew Boie <andrew.p.boie@intel.com>

Log backends don't exist with minimal logging enabled, don't compile this code. Signed-off-by: Andrew Boie <andrew.p.boie@intel.com>

The log mechanism, even in immediate mode, adds somewhere between 1K-2K of footprint to applications that use it. We want to standardize the logging APIs for all logging within the kernel, but need to not let platforms with very constrained RAM/ROM in the dust. This patch introduces CONFIG_LOG_MINIMAL, which is a very thin wrapper to printk(). It supports the APIs expressed in logging/log.h. This will be the new default for test cases. Signed-off-by: Andrew Boie <andrew.p.boie@intel.com>

joerchan · 2019-10-01T06:56:23Z

log_strdup() doc string updated to not rely on duplication behavior

Thank you.

andrewboie requested review from nashif, nordic-krch and aescolar September 22, 2019 23:59

andrewboie requested a review from andyross as a code owner September 22, 2019 23:59

zephyrbot added area: Logging area: Test Framework Issues related not to a particular test, but to the framework instead area: API Changes to public APIs area: Kernel labels Sep 23, 2019

andrewboie force-pushed the minimal-logging branch 2 times, most recently from 25cb604 to f9a144b Compare September 23, 2019 00:20

andrewboie requested a review from jakub-uC as a code owner September 23, 2019 00:20

zephyrbot added the area: Shell Shell subsystem label Sep 23, 2019

andrewboie force-pushed the minimal-logging branch from f9a144b to d991064 Compare September 23, 2019 00:42

andrewboie requested review from galak, carlescufi and pfalcon September 23, 2019 00:52

andrewboie force-pushed the minimal-logging branch from d991064 to 6298b9a Compare September 23, 2019 02:47

andrewboie requested review from jhedberg, joerchan and Vudentz as code owners September 23, 2019 02:47

zephyrbot added the area: Bluetooth label Sep 23, 2019

andrewboie force-pushed the minimal-logging branch from 6298b9a to c888ef1 Compare September 23, 2019 03:11

andrewboie requested review from dcpleung, a user and LeiW000 September 23, 2019 06:16

andrewboie force-pushed the minimal-logging branch from c888ef1 to 2d7491c Compare September 23, 2019 06:26

joerchan reviewed Sep 25, 2019

View reviewed changes

include/logging/log.h Show resolved Hide resolved

nashif approved these changes Sep 25, 2019

View reviewed changes

nordic-krch reviewed Sep 25, 2019

View reviewed changes

LeiW000 approved these changes Sep 27, 2019

View reviewed changes

carlescufi mentioned this pull request Sep 27, 2019

logging: Add log_output flushing to synchronous processing #19339

Merged

joerchan requested changes Sep 27, 2019

View reviewed changes

joerchan approved these changes Sep 30, 2019

View reviewed changes

andrewboie force-pushed the minimal-logging branch from 2d7491c to 2673d30 Compare September 30, 2019 21:09

andrewboie force-pushed the minimal-logging branch 3 times, most recently from 443c97c to d25ac9c Compare September 30, 2019 23:43

Andrew Boie added 6 commits September 30, 2019 16:51

logging: abstract log_core_init()

8790cbc

Similar to how LOG_INIT(), LOG_PANIC(), etc are wrapped. Signed-off-by: Andrew Boie <andrew.p.boie@intel.com>

log: remove duplicate log_printk() definition

94cb854

The same function should not be defined in two different headers. Signed-off-by: Andrew Boie <andrew.p.boie@intel.com>

logging: remove return value from log_printk()

a7a1b82

printk() doesn't return a value, this doesn't need to either. Signed-off-by: Andrew Boie <andrew.p.boie@intel.com>

shell: fix configuration issue

c0d2e7d

These checks should be against CONFIG_SHELL_LOG_BACKEND, and not against CONFIG_LOG, since it's possible to enable logging without building this particular backend. Signed-off-by: Andrew Boie <andrew.p.boie@intel.com>

bluetooth: monitor: don't build backend if minimal

c2ac974

Log backends don't exist with minimal logging enabled, don't compile this code. Signed-off-by: Andrew Boie <andrew.p.boie@intel.com>

andrewboie force-pushed the minimal-logging branch from d25ac9c to 73f0257 Compare September 30, 2019 23:51

nashif closed this Oct 1, 2019

nashif reopened this Oct 1, 2019

andrewboie requested a review from nordic-krch October 1, 2019 06:58

nashif merged commit 7e29c9d into zephyrproject-rtos:master Oct 1, 2019

pfalcon mentioned this pull request Oct 1, 2019

Alleged multiple design and implementation issues with logging #11655

Closed

andrewboie deleted the minimal-logging branch October 2, 2019 18:50

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

logging: add minimal implementation #19322

logging: add minimal implementation #19322

andrewboie commented Sep 22, 2019 •

edited

Loading

zephyrbot commented Sep 23, 2019 •

edited

Loading

ulfalizer commented Sep 23, 2019

andrewboie commented Sep 23, 2019 •

edited

Loading

ulfalizer commented Sep 23, 2019 •

edited

Loading

joerchan commented Sep 25, 2019

nordic-krch commented Sep 25, 2019

nordic-krch Sep 25, 2019

andrewboie Sep 27, 2019 •

edited

Loading

LeiW000 left a comment

joerchan left a comment

andrewboie commented Sep 27, 2019 •

edited

Loading

joerchan commented Sep 30, 2019

andrewboie commented Sep 30, 2019 •

edited

Loading

joerchan commented Oct 1, 2019

logging: add minimal implementation #19322

logging: add minimal implementation #19322

Conversation

andrewboie commented Sep 22, 2019 • edited Loading

zephyrbot commented Sep 23, 2019 • edited Loading

ulfalizer commented Sep 23, 2019

andrewboie commented Sep 23, 2019 • edited Loading

ulfalizer commented Sep 23, 2019 • edited Loading

joerchan commented Sep 25, 2019

nordic-krch commented Sep 25, 2019

nordic-krch Sep 25, 2019

Choose a reason for hiding this comment

andrewboie Sep 27, 2019 • edited Loading

Choose a reason for hiding this comment

LeiW000 left a comment

Choose a reason for hiding this comment

joerchan left a comment

Choose a reason for hiding this comment

andrewboie commented Sep 27, 2019 • edited Loading

joerchan commented Sep 30, 2019

andrewboie commented Sep 30, 2019 • edited Loading

joerchan commented Oct 1, 2019

andrewboie commented Sep 22, 2019 •

edited

Loading

zephyrbot commented Sep 23, 2019 •

edited

Loading

andrewboie commented Sep 23, 2019 •

edited

Loading

ulfalizer commented Sep 23, 2019 •

edited

Loading

andrewboie Sep 27, 2019 •

edited

Loading

andrewboie commented Sep 27, 2019 •

edited

Loading

andrewboie commented Sep 30, 2019 •

edited

Loading