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