Re: RFC[1/2] Common logging infrastructure and API


Chereau, Fabien <fabien.chereau@...>
 

Hello,

FYI, in thunderdome we have also created a log system solving some of the problems you mention in your RFC. Here are my 2 cents following our experience:

- In our implementation we now support only a global log level (INFO, WARNING, ERROR) + a special DEBUG level which is activated at compile time for each module separately. Originally we also had a log level per module but it quickly proved to be mostly unused by the users, while adding some complexity (conflicts between global log levels and per module log level), so we removed it, also to save space.

- Another feature which is critical for Curie, is the support of multi-core logging. One core is the master outputting the log on the log_backend while other slaves cores send their logs to the master using an IPC mechanism. Each log message carries the information from which core it originates, + a unified timestamp.

- Finally, another important feature we implemented is the buffering of incoming logs in a circular buffer in RAM (on both master and slave). This allow very short log time to avoid delaying the caller of the log function. The logs are finally output on the log backend in a low priority task, which reads from the circular buffer. In case there are too many incoming logs, some logs are lost instead of blocking the program execution.

Fabien

________________________________________
From: Kalowsky, Daniel [daniel.kalowsky(a)intel.com]
Sent: Monday, February 29, 2016 18:12
To: Nashif, Anas; Saucedo Tejada, Genaro; devel(a)lists.zephyrproject.org
Subject: [devel] Re: Re: RFC[1/2] Common logging infrastructure and API

-----Original Message-----
From: Nashif, Anas [mailto:anas.nashif(a)intel.com]
Sent: Sunday, February 28, 2016 4:43 AM
To: Saucedo Tejada, Genaro <genaro.saucedo.tejada(a)intel.com>;
devel(a)lists.zephyrproject.org
Subject: [devel] Re: RFC[1/2] Common logging infrastructure and API

Hi,




On 24/02/2016, 17:13, "Saucedo Tejada, Genaro"
<genaro.saucedo.tejada(a)intel.com> wrote:

Hello, please review this proposal and provide feedback if possible.
This email should be followed by a patch containing a prototype
implementation for reference but not meant to be applied.

Background:

Currently several files declare their own logging infrastructure and
sometimes even in the same way, effectively duplicating code, there is
no common logger header or a single interface for logging, this
situation also complicates enhancement of logging functionality.

We want to concentrate logging functionality at a single point to ease
configuration and enhancement while retaining (and reusing) all
existing logging features when decided by developers.

Additional features are proposed anticipating possibly desired
functionality.
This is a much needed enhancement, thanks for making this proposal.



Proposal to implement new logging API:

Create a new header file at include directory, remove all logger macro
definition from .c files and have a single, compatible definition on
the new header. On each .c file that requires logging include the new
header and specify feature/file specific values, such as logging domain
(if any) and per-feature logging switch (view number 2.1 below).

The retained features surveyed on existing implementations of logging
are:

1. Make based identification of output appender, these currently being
stdio printf when console is available and printk as fall back.

2. Optional macro expansion, controlled by Kconfig files and make
menuconfig command. Disabling this helps saving memory on production
when logging is not needed.

2.1. Fine grain per-feature log activation. Allows enabling log at
specific parts of the code on menuconfig.

3. Multilevel log formatting.

3.1 Colored log, when console is active it helps differentiate three
existing log levels. currently in use only on Bluetooth files.

4. Caller thread printing, currently Bluetooth files print the current
thread pointer.

5. Caller function printing, some logging macros print the function
that called them.

All above features are kept by this proposal and most become
configurable. The following new ones are added:

6. Labeled log, helps differentiate log levels by using a tag, useful
if color is not available.

7. Incremental per-level log activation. Orthogonal to existing per-
feature filter, this filter allows to set one logging level out of:
INFO, ERROR, WARNING and DEBUG. The higher the level the more
verbose
the log becomes. Also as levels are hidden by preprocessor decreasing
level also helps reducing footprint. This is set at menuconfig as well.
We need to make sure we support logging for more than debugging and
during development. In most cases logging will be used during development
to assist with debugging and printing information on the console, however,
we need to make sure this design also addresses cases where logging is part
of the application, for example you might want to write to a file-system, send
messages to a remote endpoint or write messages to a connected display.
This basically means we also need to support different backends, the most
immediate and straightforward backend would be printing to the console
using printk and printf.

An application should be able to configure the domains and levels it wants to
log, for example, if I am debugging an issue with I2C and I am only interested
in I2C, I want to be able to select this domain and the logging level, so for
example:

the defaults:
CONFIG_LOG=y
CONFIG_LOG_BACKEND=“printk”
CONFIG_LOG_DOMAINS=“*”

CONFIG_LOG_LEVEL=“INFO”


would enable logging (INFO) for everything using printk

For the case above I would change the following in my application .config:

CONFIG_LOG_DOMAINS=“I2C”
CONFIG_LOG_LEVEL=“DEBUG”
So this works for a simple case. Can you expand on this for a more complex case? For example, let's take debugging the Galileo 2 pinmux, which has dependencies on I2C, GPIO, and the Pinmux. How would you setup the DOMAINs value then and parse it?








Design decisions and rationale:

It was decided to implement this API preferring macros instead of run-
time functions (except for thread retrieval) in an attempt to minimize
overhead introduced by logging.

Also, within this macro implementation, two extreme sides can be
discerned, these are concatenate compile time values with preprocessor
## versus using printf format arguments (%s). Preferring formatting
slightly impacts run-time overhead while preferring preprocessor
concatenation produces longer strings that duplicate substrings. In
this case none of the extremes was reached, instead something closer to
formatting was picked seeking to keep the prototype code simpler. Final
patch can be tuned likewise or one of the two extreme approaches can be
taken.

Implementation details:

The patch following this email is meant as proof-of-concept prototype.
It might compile but has not been thoughtfully tested and it only
covers Bluetooth and lcd_rgb.c files.

In this example path configuration is done through menuconfig, new
options need to be enabled in addition to existing ones, for modified
files CONFIG_BLUETOOTH_CONN, CONFIG_BLUETOOTH_DEBUG,
CONFIG_BLUETOOTH_DEBUG_HCI_CORE and CONFIG_GROVE_DEBUG.

A "logging domain" can be specified, it helps filter a log output in
case several features are enabled, domain is specified by:
LOG_DMN: short for log domain.

Example:
#define LOG_DMN "bt"
Just use LOG_DOMAIN, no need to abbreviate this



The macros at logging.h get enabled by two definitions:
CONFIG_USE_COMPILE_LOG: This is the global Kconfig switch for logging.
Keep it simple, CONFIG_LOG, the COMPILE wording can be misleading, In
Kconfig we compile almost everything that is enabled, i.e. y means
USE_COMPILE...


LOG_THIS_MODULE: This is an additional switch intended to bridge the
generic definitions on the header to a feature-specific logging switch
from Kconfig.

Example usage of LOG_THIS_MODULE:
#define LOG_THIS_MODULE CONFIG_BLUETOOTH_DEBUG_HCI_CORE
#include
<logging.h>
I think this is were things will get confusing, we do need to change all of
those existing DEBUG variables and make them work with the new model
instead of keeping them in the code. See my example above, using the right
domains and level, the same will be achieved.



That way logging.h will know that if
CONFIG_BLUETOOTH_DEBUG_HCI_CORE
was not set by menuconfig it should not log at all (at current
compilation unit).

This requires an additional line to be included by files that use
logging but could be made optional, doing so requires deciding default
behavior between having unfiltered features (on 2.1 filter mentioned
above) or allowing developer to included logging.h file with no effect.
On current prototype this line requirement is enforced by #error
directive.

Future work:

* Final patch needs to unify system wide the macro naming and such
naming should be less likely to collide.
* An alternative run-time implementation could be later developed to
provide more features.
* Compare footprint between different degrees of ## usage over printf
format.

We should implement backends and clean up all the custom DEBUG usage in
Kconfig and move everything to the new model reducing complexity and
making things more consistent.

Please make sure we have a JIRA story to track this and add the final proposal
to that JIRA once we have reached consensus.

Anas



Example macro expansions:

printf("" "%s%s\t%p: %s" "Grove LCD: background set to white\n" "%s\n",
"DBG ", __func__, sys_thread_self_get(), "", ""); (messages were left
unchaged so domain is still repeated as part of the
message)
printf("bt" ":\t" "%s%s\t%p: %s" "Unable to allocate new HCI command"
"%s\n", "", __func__, sys_thread_self_get(), "\x1B[0;31m", "\x1B[0m");
(domain is defined through macro, color and thread are in use)
printf("bt" ":\t" "%s%s\t: %s" "No HCI driver registered" "%s\n", "",
__func__, "\x1B[0;31m", "\x1B[0m"); (same but without thread)

Join devel@lists.zephyrproject.org to automatically receive all group messages.