Added option profiling instrumentation which can help determine
string duplicates pool configuration. Added shell command to
read current peak utilization of the pool.
Signed-off-by: Krzysztof Chruscinski <krzysztof.chruscinski@nordicsemi.no>
when building with clang we get the following warning:
log_core.c:358:40: error: use of logical '&&' with constant operand
[-Werror,-Wconstant-logical-operand]
This is because we are mix a constant IS_ENABLED(CONFIG_LOG_IMMEDIATE)
with non-constants.
Split out the check into its own statement to workaround the warning.
Signed-off-by: Kumar Gala <kumar.gala@linaro.org>
If system clock runs fast k_cycle_get_32(), which is the timestamp
source, wraps often (few minutes). This patch changes default
timestamp function to use k_uptime_get_32() if system clock
frequency is higher than 1 MHz and k_cycle_get_32() otherwise.
If system clock runs at 1 MHz, counter will wrap every 71.5 minutes.
Signed-off-by: Krzysztof Chruscinski <krzysztof.chruscinski@nordicsemi.no>
Added an assert in the logger thread in case there
is no backends, instead of having that thread spinning
forever. Disabled log in qemu_xtensa board due to lack
of backends.
Signed-off-by: Alberto Escolar Piedras <alpi@oticon.com>
Signed-off-by: Krzysztof Chruscinski <krzysztof.chruscinski@nordicsemi.no>
Signed-off-by: Anas Nashif <anas.nashif@intel.com>
There was no notification about dropped logs When logger operated
in the mode where message is dropped when logger has no space to
store the message. Notification was printed only if logger operated
in the mode which overwrites oldest log.
Signed-off-by: Krzysztof Chruscinski <krzysztof.chruscinski@nordicsemi.no>
There are issues using lowercase min and max macros when compiling a C++
application with a third-party toolchain such as GNU ARM Embedded when
using some STL headers i.e. <chrono>.
This is because there are actual C++ functions called min and max
defined in some of the STL headers and these macros interfere with them.
By changing the macros to UPPERCASE, which is consistent with almost all
other pre-processor macros this naming conflict is avoided.
All files that use these macros have been updated.
Signed-off-by: Carlos Stuart <carlosstuart1970@gmail.com>
In case log_panic is called from context which can be
interrupted, it is safer to set panic_mode flag after
logs are flushed. If flag was set before flushing and
log_panic was interrupted then another context was
attempting to process log message directly, competing
for log backends.
Signed-off-by: Krzysztof Chruscinski <krzysztof.chruscinski@nordicsemi.no>
Log backends (marked as autostart) are initialized late. By default
in logger thread which has the lowest priority. If log_panic() occurs
earlier no logs is printed because there is no backend enabled.
This patch fixes it by adding log_init() call to log_panic(). Log_init()
can be called multiple times.
This patch ensures that logs are printed if early panic occurs if
backend is configured to auto-start. This is not the case if shell
is acting as log backend.
Signed-off-by: Krzysztof Chruscinski <krzysztof.chruscinski@nordicsemi.no>
Changed 'in place' mode to bypass logger system and directly
call active backends. With this approach memory footprint of
the logger can be significantly reduced in terms of RAM and ROM.
Signed-off-by: Krzysztof Chruscinski <krzysztof.chruscinski@nordicsemi.no>
Dropped logs were not counted if logger has no backend
attached (system startup phase).
Signed-off-by: Krzysztof Chruscinski <krzysztof.chruscinski@nordicsemi.no>
Shell log backends were initialized from shell context. After
lowering logger thread priority order has been flipped. That
revealed a bug where shell logger backend was enabled before
backend ID's has been assigned during logger initialization.
ID assignment is moved to log backend enabling function making
it independent of order of initialization.
Signed-off-by: Krzysztof Chruscinski <krzysztof.chruscinski@nordicsemi.no>
Timestamp function and pool for log_strdup were initialized
in log thread initialization while they should be initialized
in log_core_init() which is performed earliest possible. Log
API was using uninitialized data when called before log thread
was started.
Signed-off-by: Krzysztof Chruscinski <krzysztof.chruscinski@nordicsemi.no>
Extended backend interface to allow notifying backend
that log messages has been dropped due to insufficient
internal buffer size. Notification contains number of
log messages dropped since last notification. It
is optional for a backend to implement handler.
Signed-off-by: Krzysztof Chruscinski <krzysztof.chruscinski@nordicsemi.no>
Removed kconfig option for setting logging thread priority
and fix it to K_LOWEST_APPLICATION_THREAD_PRIO.
Signed-off-by: Krzysztof Chruscinski <krzysztof.chruscinski@nordicsemi.no>
Don't say that pool is empty, say that allocation failed, because
that's what happened (because the pool is full apparently).
Partially addresses #11007.
Signed-off-by: Paul Sokolovsky <paul.sokolovsky@linaro.org>
The function atomic_set return the previous value of the
target. Sometimes this value is irrelevant, e.g when initializing a
variable.
As MISRA-C rule 17.7 requires that the value returned by a non-void
function must be used, we have to explicitly ignore some cases.
MISRA-C rule 17.7
Signed-off-by: Flavio Ceolin <flavio.ceolin@intel.com>
Modified log_filter_set function to limit level if requested
level is not compiled in. Additionally, extended function to
return actually set level. Removed redundant code from log_cmds.
Change fixes shell log backend initialization which was setting
log levels without taking into account compiled in limits.
Signed-off-by: Krzysztof Chruscinski <krzysztof.chruscinski@nordicsemi.no>
Currently, if CONFIG_LOG_PROCESS_THREAD is enabled, log processing
does not start until just before the main() function is called in
the user sample. This means that no real-time logging information
will be sent to the backends while drivers and/or other processes
which are triggered during kernel boot are processing their tasks.
Worse, if they take a longish time to finish, the user is
presented with a blank log backend regardless of the debug levels.
Let's start processing logs earlier to avoid this issue.
NOTE: Since this thread is now triggered specifically rather than
started during static thread init, let's also name it.
Signed-off-by: Michael Scott <mike@foundries.io>
Log_generic() can be used by external logger systems to map to zephyr
logger subsystem. Function has variable number of arguments. So far
logger assumed maximal number of arguments to avoid scanning
string to count number of arguments. In outcome, uninitialized memory
was treated as valid argument in a message (but discarded when actual
string formatting took place). Valgrind complained about that so
log_generic() has been extended to scan the string and count number
of arguments and build message with valid number of arguments.
Signed-off-by: Krzysztof Chruscinski <krzysztof.chruscinski@nordicsemi.no>
log_strdup requested for a piece of memory, with the first 4 bytes as
the number of references and the next used to copy strings. In the
implementation of this function, the memory is managed by user and
is a little hard to understand.
Rewriting this part of code, using structure to manage the memory
requested, make it easier to understand.
Signed-off-by: qianfan Zhao <qianfanguijin@163.com>
log_strdup writes out of bounds of a strdup slab.
e.g: CONFIG_LOG_STRDUP_MAX_STRING=46 and
LOG_STRBUF_STR_SIZE=47 then in the line L:529
sdupl[LOG_STRBUF_STR_SIZE - 1] = '\0';
writes out of bounds because the available buffer space
is only 44 bytes (rounded up to 48 bytes and minus 4 bytes
for the allocated flag).
Signed-off-by: Johann Fischer <j.fischer@phytec.de>
Extended supported number of arguments in log message. Support for
messages consisting of more than 2 chunks had to be added. So far
messages could consist of one chunk (up to 3 args) or two chunks
(2 args in first chunk and 7 in second chunk). Once 2+ chunks
support is added number of arguments is techinically limited to
15 (4 bit field). log_core and log_output extended to suppor 10
arguments.
Signed-off-by: Krzysztof Chruscinski <krzysztof.chruscinski@nordicsemi.no>
In initial state of the system it is possible that no backends are
yet enabled and log processing is triggered. In that case logs were
discarded. A flag has been added to the log core to do processing
only if at least one backend is enabled. It is applicable only to
initial phase. If backends are disabled in application lifetime
logs will be discarded.
Signed-off-by: Krzysztof Chruscinski <krzysztof.chruscinski@nordicsemi.no>
Extended macro to accept flag indicating if given backend must be
initialized and enabled when log subsystem starts. Typically, simple
backends will have autostart flag set. More complex may require
explicit enabling (e.g. shell over BLE can only be enabled when
BLE connection is established).
Signed-off-by: Krzysztof Chruscinski <krzysztof.chruscinski@nordicsemi.no>
We are using a non-32-bit aligned value as the block size
when initializing the strdup mem_slab for Logger.
When the non-aligned pointer is being freed, it's converted
to a u32_t and this generates the following:
***** USAGE FAULT *****
Unaligned memory access
Let's use the aligned buffer size as the block size instead.
Signed-off-by: Michael Scott <mike@foundries.io>
The string parameter needs to be const as otherwise calling this
function using a const string pointer will lead to a warning.
Besides the function does not modify the parameter so should be
const anyway.
Signed-off-by: Jukka Rissanen <jukka.rissanen@linux.intel.com>
Extending logger to support logging transient strings (with %s).
With dedicated call (log_strdup), string is duplicated to a buffer
from internal logger pool. Logger implicitly manages the pool.
Signed-off-by: Krzysztof Chruscinski <krzysztof.chruscinski@nordicsemi.no>
Added commands for getting current status and controlling which log
messages are forwared to available backends.
Signed-off-by: Krzysztof Chruscinski <krzysztof.chruscinski@nordicsemi.no>
When CONFIG_LOG_PROCESS_THREAD was not set the logger
was not initialized.
Register a POST_KERNEL init for that case.
Also added an assert in the logger thread in case there
is no backends, instead of having that thread spinning
forever.
Signed-off-by: Alberto Escolar Piedras <alpi@oticon.com>
The runtime filters (both aggregated and per-backend) are all getting
initialized to the default level CONFIG_LOG_DEFAULT_LEVEL. This is not
correct behavior: the initial runtime setting for each source ID
should match its compile-time level setting.
Otherwise, setting CONFIG_LOG_RUNTIME_FILTERING=y changes the logging
behavior for messages that pass the compile time filter check, but not
the runtime check (this currently happens when LOG_LEVEL=4, since
CONFIG_LOG_DEFAULT_LEVEL=3).
Fix this by initializing all filters to their module's compile time
settings. Also make sure that filters are set up before backends are
activated, to avoid race conditions.
Fix a stray documentation typo while we are here.
Signed-off-by: Marti Bolivar <marti@foundries.io>
The printk family of functions is used elsewhere, so make this
consistent. Also, printk has a smaller stack footprint.
Signed-off-by: Johan Hedberg <johan.hedberg@intel.com>
The CONFIG_LOG_PROCESS_TRIGGER_THRESHOLD option can be used to wake up
the background log processing thread when a given number of messages
have been queued.
Currently, the msg_finalize() routine which is responsible for
queueing a log message for later handling appends messages to the
global list after performing the threshold check and waking up the
thread.
This leads to a race condition with undesirable behavior if the
threshold == 1:
- the msg_finalize() thread is scheduled out by calling k_wakeup()
- the log processing thread wakes up, notice that no messages are
queued, and goes back to sleep
- the msg_finalize() thread is scheduled back in and the message is
queued for processing
This defers the handling of the message until the processing thread
wakes up again after the CONFIG_LOG_PROCESS_THREAD_SLEEP_MS timeout,
which is not what the user wants.
Fix this by queueing the message before waking up the handler thread.
(This also may improve responsiveness for larger threshold values.)
Signed-off-by: Marti Bolivar <marti@foundries.io>
Documenting new logger features: waking up processing thread
and internal logger processing thread.
Signed-off-by: Krzysztof Chruscinski <krzysztof.chruscinski@nordicsemi.no>
When enabled, logger is creating own thread which processes buffered
logs. When no logs to process, thread sleeps for configurable period.
Thread can be waken up if number of buffered log messages exceeds
configured threshold. Logging sample aligned to use new feature.
Signed-off-by: Krzysztof Chruscinski <krzysztof.chruscinski@nordicsemi.no>
Added configurable threshold of number of buffered log messages
on which log wakes up thread which processes buffered logs. Thread
ID is provided during logger initialization. Feature is optional
and can be disabled by setting CONFIG_LOG_PROCESS_TRIGGER_THR to 0.
Signed-off-by: Krzysztof Chruscinski <krzysztof.chruscinski@nordicsemi.no>
Log API can be used before user can explicitly initialize the logger.
In order to ensure that logger core is ready to buffer log messages
it must be initialize as early as possible. Initialization does not
include initialization of default backend since driver may not be
ready and backend is needed only when log messages are processed.
Signed-off-by: Krzysztof Chruscinski <krzysztof.chruscinski@nordicsemi.no>
Adding new implementation of logging subsystem. New features
includes: support for multiple backends, improving performance
by deferring log processing to the known context, adding
timestamps and logs filtering options (compile time, runtime,
module level, instance level). Console backend added as the
example backend.
Signed-off-by: Krzysztof Chruściński <krzysztof.chruscinski@nordicsemi.no>
