logging: Refactoring 'in place' mode to reduce memory footprint

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>
This commit is contained in:
Krzysztof Chruscinski 2019-01-10 08:37:15 +01:00 committed by Carles Cufí
commit 1d9e5ee108
13 changed files with 276 additions and 119 deletions

View file

@ -52,10 +52,10 @@ config LOG_BACKEND_NATIVE_POSIX
# For native_posix we can log immediately without any problem
# Doing so will be nicer for debugging
config LOG_INPLACE_PROCESS
config LOG_IMMEDIATE
default y
# If we set LOG_INPLACE_PROCESS, there is no need to have the logging thread
# If we set LOG_IMMEDIATE, there is no need to have the logging thread
# running
config LOG_PROCESS_THREAD
default n

View file

@ -28,10 +28,10 @@ config LOG_BACKEND_NATIVE_POSIX
# For this board we can log immediately without any problem
# Doing so will be nicer for debugging
config LOG_INPLACE_PROCESS
config LOG_IMMEDIATE
default y
# If we set LOG_INPLACE_PROCESS, there is no need to have the logging thread
# If we set LOG_IMMEDIATE, there is no need to have the logging thread
# running
config LOG_PROCESS_THREAD
default n

View file

@ -24,7 +24,7 @@ Summary of logger features:
- Timestamping with user provided function.
- Dedicated API for dumping data
- Dedicated API for handling transient strings
- Panic support - in panic mode logger switches to blocking, in-place
- Panic support - in panic mode logger switches to blocking, synchronous
processing.
- Printk support - printk message can be redirected to the logger.
- Design ready for multi-domain/multi-processor system
@ -121,9 +121,9 @@ function name.
:option:`CONFIG_LOG_PRINTK_MAX_STRING_LENGTH`: Maximal string length that can
be processed by printk. Longer strings are trimmed.
:option:`CONFIG_LOG_INPLACE_PROCESS`: Messages are processed in the context of
the log macro call. Note that it can lead to errors when logger is used in the
interrupt context.
:option:`CONFIG_LOG_IMMEDIATE`: Messages are processed in the context
of the log macro call. Note that it can lead to errors when logger is used in
the interrupt context.
:option:`CONFIG_LOG_PROCESS_TRIGGER_THRESHOLD`: When number of buffered log
messages reaches the threshold dedicated thread (see :cpp:func:`log_thread_set`)

View file

@ -28,6 +28,12 @@ struct log_backend;
struct log_backend_api {
void (*put)(const struct log_backend *const backend,
struct log_msg *msg);
void (*put_sync_string)(const struct log_backend *const backend,
struct log_msg_ids src_level, u32_t timestamp,
const char *fmt, va_list ap);
void (*put_sync_hexdump)(const struct log_backend *const backend,
struct log_msg_ids src_level, u32_t timestamp,
const char *metadata, const u8_t *data, u32_t len);
void (*dropped)(const struct log_backend *const backend, u32_t cnt);
void (*panic)(const struct log_backend *const backend);
@ -94,6 +100,53 @@ static inline void log_backend_put(const struct log_backend *const backend,
backend->api->put(backend, msg);
}
/**
* @brief Synchronously process log message.
*
* @param[in] backend Pointer to the backend instance.
* @param[in] src_level Message details.
* @param[in] timestamp Timestamp.
* @param[in] fmt Log string.
* @param[in] ap Log string arguments.
*/
static inline void log_backend_put_sync_string(
const struct log_backend *const backend,
struct log_msg_ids src_level,
u32_t timestamp, const char *fmt,
va_list ap)
{
__ASSERT_NO_MSG(backend);
if (backend->api->put_sync_string) {
backend->api->put_sync_string(backend, src_level,
timestamp, fmt, ap);
}
}
/**
* @brief Synchronously process log hexdump_message.
*
* @param[in] backend Pointer to the backend instance.
* @param[in] src_level Message details.
* @param[in] timestamp Timestamp.
* @param[in] metadata Raw string associated with the data.
* @param[in] data Data.
* @param[in] len Data length.
*/
static inline void log_backend_put_sync_hexdump(
const struct log_backend *const backend,
struct log_msg_ids src_level,
u32_t timestamp, const char *metadata,
const u8_t *data, u32_t len)
{
__ASSERT_NO_MSG(backend);
if (backend->api->put_sync_hexdump) {
backend->api->put_sync_hexdump(backend, src_level, timestamp,
metadata, data, len);
}
}
/**
* @brief Notify backend about dropped log messages.
*

View file

@ -161,9 +161,15 @@ extern "C" {
#define _LOG_INTERNAL_X(N, ...) UTIL_CAT(_LOG_INTERNAL_, N)(__VA_ARGS__)
#define __LOG_INTERNAL(_src_level, ...) \
_LOG_INTERNAL_X(_LOG_NARGS_POSTFIX(__VA_ARGS__), \
_src_level, __VA_ARGS__)
#define __LOG_INTERNAL(_src_level, ...) \
do { \
if (IS_ENABLED(CONFIG_LOG_IMMEDIATE)) { \
log_string_sync(_src_level, __VA_ARGS__); \
} else { \
_LOG_INTERNAL_X(_LOG_NARGS_POSTFIX(__VA_ARGS__), \
_src_level, __VA_ARGS__);\
} \
} while (0)
#define _LOG_INTERNAL_0(_src_level, _str) \
log_0(_str, _src_level)
@ -246,17 +252,23 @@ extern "C" {
/******************************************************************************/
/****************** Macros for hexdump logging ********************************/
/******************************************************************************/
#define __LOG_HEXDUMP(_level, _id, _filter, _data, _length, _str) \
do { \
if (_LOG_CONST_LEVEL_CHECK(_level) && \
(_level <= LOG_RUNTIME_FILTER(_filter))) { \
struct log_msg_ids src_level = { \
.level = _level, \
.source_id = _id, \
.domain_id = CONFIG_LOG_DOMAIN_ID \
}; \
log_hexdump(_str, _data, _length, src_level); \
} \
#define __LOG_HEXDUMP(_level, _id, _filter, _data, _length, _str) \
do { \
if (_LOG_CONST_LEVEL_CHECK(_level) && \
(_level <= LOG_RUNTIME_FILTER(_filter))) { \
struct log_msg_ids src_level = { \
.level = _level, \
.source_id = _id, \
.domain_id = CONFIG_LOG_DOMAIN_ID \
}; \
\
if (IS_ENABLED(CONFIG_LOG_IMMEDIATE)) { \
log_hexdump_sync(src_level, _str, \
_data, _length); \
} else { \
log_hexdump(_str, _data, _length, src_level); \
} \
} \
} while (false)
#define _LOG_HEXDUMP(_level, _data, _length, _str) \
@ -322,6 +334,11 @@ extern "C" {
#define LOG_RUNTIME_FILTER(_filter) LOG_LEVEL_DBG
#endif
/** @brief Log level value used to indicate log entry that should not be
* formatted (raw string).
*/
#define LOG_LEVEL_INTERNAL_RAW_STRING LOG_LEVEL_NONE
extern struct log_source_const_data __log_const_start[0];
extern struct log_source_const_data __log_const_end[0];
@ -484,6 +501,24 @@ void log_hexdump(const char *str,
*/
int log_printk(const char *fmt, va_list ap);
/** @brief Process log message synchronously.
*
* @param src_level Log message details.
* @param fmt String to format.
* @param ... Variable list of arguments.
*/
void log_string_sync(struct log_msg_ids src_level, const char *fmt, ...);
/** @brief Process log hexdump message synchronously.
*
* @param src_level Log message details.
* @param metadata Raw string associated with the data.
* @param data Data.
* @param len Data length.
*/
void log_hexdump_sync(struct log_msg_ids src_level, const char *metadata,
const u8_t *data, u32_t len);
/**
* @brief Writes a generic log message to the log.
*

View file

@ -65,7 +65,7 @@ extern "C" {
u16_t ext : 1
/** @brief Number of bits used for storing length of hexdump log message. */
#define LOG_MSG_HEXDUMP_LENGTH_BITS 13
#define LOG_MSG_HEXDUMP_LENGTH_BITS 14
/** @brief Maximum length of log hexdump message. */
#define LOG_MSG_HEXDUMP_MAX_LENGTH ((1 << LOG_MSG_HEXDUMP_LENGTH_BITS) - 1)
@ -102,7 +102,6 @@ BUILD_ASSERT_MSG((sizeof(struct log_msg_std_hdr) == sizeof(u16_t)),
/** Part of log message header specific to hexdump log message. */
struct log_msg_hexdump_hdr {
COMMON_PARAM_HDR();
u16_t raw_string : 1;
u16_t length : LOG_MSG_HEXDUMP_LENGTH_BITS;
};
@ -234,20 +233,6 @@ static inline u32_t log_msg_timestamp_get(struct log_msg *msg)
return msg->hdr.timestamp;
}
/** @brief Check if message is a raw string (see CONFIG_LOG_PRINTK).
*
* @param msg Message
*
* @retval true Message contains raw string.
* @retval false Message does not contain raw string.
*/
static inline bool log_msg_is_raw_string(struct log_msg *msg)
{
return (msg->hdr.params.generic.type == LOG_MSG_TYPE_HEXDUMP) &&
(msg->hdr.params.hexdump.raw_string == 1);
}
/** @brief Check if message is of standard type.
*
* @param msg Message

View file

@ -123,17 +123,6 @@ config LOG_RUNTIME_FILTERING
Allow runtime configuration of maximal, independent severity
level for instance.
choice
prompt "Log full strategy"
config LOG_MODE_OVERFLOW
bool "Oldest logs are discarded"
config LOG_MODE_NO_OVERFLOW
bool "New logs are dropped"
endchoice
config LOG_DEFAULT_LEVEL
int "Default log level"
default 3
@ -208,20 +197,33 @@ config LOG_PRINTK
config LOG_PRINTK_MAX_STRING_LENGTH
int "Maximum string length supported by LOG_PRINTK"
depends on LOG_PRINTK
depends on !LOG_IMMEDIATE
default 128
help
Array is allocated on the stack.
config LOG_INPLACE_PROCESS
bool "Enable in place processing"
config LOG_IMMEDIATE
bool "Enable synchronous processing"
help
When enabled log is processed in the context of the call. It impacts
performance of the system since time consuming operations are
performed in the context of the log entry (e.g. high priority
interrupt). When enabled LOG_BUFFER_SIZE can be reduced. Logger
backends must support exclusive access to work flawlessly in that mode
because one log operation can be interrupted by another one in higher
priority context.
interrupt).Logger backends must support exclusive access to work
flawlessly in that mode because one log operation can be interrupted
by another one in the higher priority context.
if !LOG_IMMEDIATE
choice
prompt "Log full strategy"
config LOG_MODE_OVERFLOW
bool "Oldest logs are discarded"
config LOG_MODE_NO_OVERFLOW
bool "New logs are dropped"
endchoice
config LOG_PROCESS_TRIGGER_THRESHOLD
int "Amount of buffered logs which triggers processing thread."
@ -258,7 +260,7 @@ config LOG_PROCESS_THREAD_STACK_SIZE
help
Set the internal stack size for log processing thread.
endif
endif # LOG_PROCESS_THREAD
config LOG_BUFFER_SIZE
int "Number of bytes dedicated for the logger internal buffer."
@ -284,6 +286,8 @@ config LOG_STRDUP_BUF_COUNT
Each entry takes CONFIG_LOG_STRDUP_MAX_STRING bytes of memory plus
some additional fixed overhead.
endif # !LOG_IMMEDIATE
config LOG_DOMAIN_ID
int "Domain ID"
default 0

View file

@ -18,6 +18,26 @@
#define CONFIG_LOG_PRINTK_MAX_STRING_LENGTH 1
#endif
#ifndef CONFIG_LOG_PROCESS_THREAD_SLEEP_MS
#define CONFIG_LOG_PROCESS_THREAD_SLEEP_MS 0
#endif
#ifndef CONFIG_LOG_PROCESS_TRIGGER_THRESHOLD
#define CONFIG_LOG_PROCESS_TRIGGER_THRESHOLD 0
#endif
#ifndef CONFIG_LOG_PROCESS_THREAD_STACK_SIZE
#define CONFIG_LOG_PROCESS_THREAD_STACK_SIZE 1
#endif
#ifndef CONFIG_LOG_STRDUP_MAX_STRING
#define CONFIG_LOG_STRDUP_MAX_STRING 0
#endif
#ifndef CONFIG_LOG_STRDUP_BUF_COUNT
#define CONFIG_LOG_STRDUP_BUF_COUNT 0
#endif
struct log_strdup_buf {
atomic_t refcount;
char buf[CONFIG_LOG_STRDUP_MAX_STRING + 1]; /* for termination */
@ -63,12 +83,11 @@ static inline void msg_finalize(struct log_msg *msg,
irq_unlock(key);
if (IS_ENABLED(CONFIG_LOG_INPLACE_PROCESS) || panic_mode) {
if (panic_mode) {
(void)log_process(false);
} else if (!IS_ENABLED(CONFIG_LOG_INPLACE_PROCESS) &&
CONFIG_LOG_PROCESS_TRIGGER_THRESHOLD) {
if (buffered_cnt == CONFIG_LOG_PROCESS_TRIGGER_THRESHOLD &&
proc_tid) {
} else if (CONFIG_LOG_PROCESS_TRIGGER_THRESHOLD) {
if ((buffered_cnt == CONFIG_LOG_PROCESS_TRIGGER_THRESHOLD) &&
(proc_tid != NULL)) {
k_wakeup(proc_tid);
}
}
@ -155,30 +174,34 @@ void log_hexdump(const char *str,
int log_printk(const char *fmt, va_list ap)
{
int length = 0;
if (IS_ENABLED(CONFIG_LOG_PRINTK)) {
u8_t formatted_str[CONFIG_LOG_PRINTK_MAX_STRING_LENGTH];
struct log_msg_ids empty_id = { 0 };
struct log_msg *msg;
int length;
struct log_msg_ids src_level = {
.level = LOG_LEVEL_INTERNAL_RAW_STRING
};
length = vsnprintk(formatted_str,
sizeof(formatted_str), fmt, ap);
if (IS_ENABLED(CONFIG_LOG_IMMEDIATE)) {
log_generic(src_level, fmt, ap);
} else {
u8_t formatted_str[CONFIG_LOG_PRINTK_MAX_STRING_LENGTH];
struct log_msg *msg;
length = (length > sizeof(formatted_str)) ?
sizeof(formatted_str) : length;
length = vsnprintk(formatted_str,
sizeof(formatted_str), fmt, ap);
length = min(length, sizeof(formatted_str));
msg = log_msg_hexdump_create(NULL, formatted_str, length);
if (msg == NULL) {
return 0;
msg = log_msg_hexdump_create(NULL, formatted_str,
length);
if (msg == NULL) {
return 0;
}
msg_finalize(msg, src_level);
}
msg->hdr.params.hexdump.raw_string = 1;
msg_finalize(msg, empty_id);
return length;
} else {
return 0;
}
return length;
}
/** @brief Count number of arguments in formatted string.
@ -205,15 +228,56 @@ static u32_t count_args(const char *fmt)
void log_generic(struct log_msg_ids src_level, const char *fmt, va_list ap)
{
u32_t args[LOG_MAX_NARGS];
u32_t nargs = count_args(fmt);
if (IS_ENABLED(CONFIG_LOG_IMMEDIATE)) {
struct log_backend const *backend;
u32_t timestamp = timestamp_func();
for (int i = 0; i < nargs; i++) {
u32_t arg = va_arg(ap, u32_t);
args[i] = arg;
for (int i = 0; i < log_backend_count_get(); i++) {
backend = log_backend_get(i);
if (log_backend_is_active(backend)) {
log_backend_put_sync_string(backend, src_level,
timestamp, fmt, ap);
}
}
} else {
u32_t args[LOG_MAX_NARGS];
u32_t nargs = count_args(fmt);
for (int i = 0; i < nargs; i++) {
args[i] = va_arg(ap, u32_t);
}
log_n(fmt, args, nargs, src_level);
}
}
log_n(fmt, args, nargs, src_level);
void log_string_sync(struct log_msg_ids src_level, const char *fmt, ...)
{
va_list ap;
va_start(ap, fmt);
log_generic(src_level, fmt, ap);
va_end(ap);
}
void log_hexdump_sync(struct log_msg_ids src_level, const char *metadata,
const u8_t *data, u32_t len)
{
struct log_backend const *backend;
u32_t timestamp = timestamp_func();
for (int i = 0; i < log_backend_count_get(); i++) {
backend = log_backend_get(i);
if (log_backend_is_active(backend)) {
log_backend_put_sync_hexdump(backend, src_level,
timestamp, metadata,
data, len);
}
}
}
static u32_t timestamp_get(void)
@ -223,12 +287,14 @@ static u32_t timestamp_get(void)
void log_core_init(void)
{
log_msg_pool_init();
log_list_init(&list);
if (!IS_ENABLED(CONFIG_LOG_IMMEDIATE)) {
log_msg_pool_init();
log_list_init(&list);
k_mem_slab_init(&log_strdup_pool, log_strdup_pool_buf,
sizeof(struct log_strdup_buf),
CONFIG_LOG_STRDUP_BUF_COUNT);
k_mem_slab_init(&log_strdup_pool, log_strdup_pool_buf,
sizeof(struct log_strdup_buf),
CONFIG_LOG_STRDUP_BUF_COUNT);
}
/* Set default timestamp. */
timestamp_func = timestamp_get;
@ -282,7 +348,7 @@ static void thread_set(k_tid_t process_tid)
{
proc_tid = process_tid;
if (!IS_ENABLED(CONFIG_LOG_INPLACE_PROCESS) &&
if (!IS_ENABLED(CONFIG_LOG_IMMEDIATE) &&
CONFIG_LOG_PROCESS_TRIGGER_THRESHOLD &&
process_tid &&
buffered_cnt >= CONFIG_LOG_PROCESS_TRIGGER_THRESHOLD) {
@ -329,24 +395,30 @@ void log_panic(void)
panic_mode = true;
/* Flush */
while (log_process(false) == true) {
if (!IS_ENABLED(CONFIG_LOG_IMMEDIATE)) {
/* Flush */
while (log_process(false) == true) {
}
}
}
static bool msg_filter_check(struct log_backend const *backend,
struct log_msg *msg)
{
u32_t backend_level;
u32_t msg_level;
if (IS_ENABLED(CONFIG_LOG_RUNTIME_FILTERING)) {
u32_t backend_level;
u32_t msg_level;
backend_level = log_filter_get(backend,
log_msg_domain_id_get(msg),
log_msg_source_id_get(msg),
true /*enum RUNTIME, COMPILETIME*/);
msg_level = log_msg_level_get(msg);
backend_level = log_filter_get(backend,
log_msg_domain_id_get(msg),
log_msg_source_id_get(msg),
true /*enum RUNTIME, COMPILETIME*/);
msg_level = log_msg_level_get(msg);
return (msg_level <= backend_level);
return (msg_level <= backend_level);
} else {
return true;
}
}
static void msg_process(struct log_msg *msg, bool bypass)
@ -544,6 +616,10 @@ char *log_strdup(const char *str)
struct log_strdup_buf *dup;
int err;
if (IS_ENABLED(CONFIG_LOG_IMMEDIATE)) {
return (char *)str;
}
err = k_mem_slab_alloc(&log_strdup_pool, (void **)&dup, K_NO_WAIT);
if (err != 0) {
/* failed to allocate */
@ -582,7 +658,6 @@ void log_free(void *str)
}
}
#ifdef CONFIG_LOG_PROCESS_THREAD
static void log_process_thread_func(void *dummy1, void *dummy2, void *dummy3)
{
log_init();
@ -597,21 +672,22 @@ static void log_process_thread_func(void *dummy1, void *dummy2, void *dummy3)
K_THREAD_STACK_DEFINE(logging_stack, CONFIG_LOG_PROCESS_THREAD_STACK_SIZE);
struct k_thread logging_thread;
#endif /* CONFIG_LOG_PROCESS_THREAD */
static int enable_logger(struct device *arg)
{
ARG_UNUSED(arg);
#ifdef CONFIG_LOG_PROCESS_THREAD
/* start logging thread */
k_thread_create(&logging_thread, logging_stack,
K_THREAD_STACK_SIZEOF(logging_stack),
log_process_thread_func, NULL, NULL, NULL,
K_LOWEST_APPLICATION_THREAD_PRIO, 0, K_NO_WAIT);
k_thread_name_set(&logging_thread, "logging");
#else
log_init();
#endif
if (IS_ENABLED(CONFIG_LOG_PROCESS_THREAD)) {
/* start logging thread */
k_thread_create(&logging_thread, logging_stack,
K_THREAD_STACK_SIZEOF(logging_stack),
log_process_thread_func, NULL, NULL, NULL,
K_LOWEST_APPLICATION_THREAD_PRIO, 0, K_NO_WAIT);
k_thread_name_set(&logging_thread, "logging");
} else {
log_init();
}
return 0;
}

View file

@ -9,6 +9,10 @@
#include <logging/log_core.h>
#include <string.h>
#ifndef CONFIG_LOG_BUFFER_SIZE
#define CONFIG_LOG_BUFFER_SIZE 0
#endif
#define MSG_SIZE sizeof(union log_msg_chunk)
#define NUM_OF_MSGS (CONFIG_LOG_BUFFER_SIZE / MSG_SIZE)
@ -243,7 +247,6 @@ struct log_msg *log_msg_hexdump_create(const char *str,
/* all fields reset to 0, reference counter to 1 */
msg->hdr.ref_cnt = 1;
msg->hdr.params.hexdump.type = LOG_MSG_TYPE_HEXDUMP;
msg->hdr.params.hexdump.raw_string = 0;
msg->hdr.params.hexdump.length = length;
msg->str = str;

View file

@ -465,7 +465,7 @@ static int prefix_print(struct log_msg *msg,
{
int length = 0;
if (!log_msg_is_raw_string(msg)) {
if (log_msg_level_get(msg) != LOG_LEVEL_INTERNAL_RAW_STRING) {
bool stamp = flags & LOG_OUTPUT_FLAG_TIMESTAMP;
bool colors_on = flags & LOG_OUTPUT_FLAG_COLORS;
bool level_on = flags & LOG_OUTPUT_FLAG_LEVEL;
@ -512,7 +512,7 @@ static void postfix_print(struct log_msg *msg,
const struct log_output *log_output,
u32_t flags)
{
if (!log_msg_is_raw_string(msg)) {
if (log_msg_level_get(msg) != LOG_LEVEL_INTERNAL_RAW_STRING) {
color_postfix(msg, log_output,
(flags & LOG_OUTPUT_FLAG_COLORS));
newline_print(log_output, flags);
@ -528,7 +528,7 @@ void log_output_msg_process(const struct log_output *log_output,
if (log_msg_is_std(msg)) {
std_print(msg, log_output);
} else if (log_msg_is_raw_string(msg)) {
} else if (log_msg_level_get(msg) != LOG_LEVEL_INTERNAL_RAW_STRING) {
raw_string_print(msg, log_output);
} else {
hexdump_print(msg, log_output, prefix_offset, flags);

View file

@ -5,7 +5,6 @@ CONFIG_LOG_PRINTK=n
CONFIG_LOG_RUNTIME_FILTERING=y
CONFIG_LOG_BACKEND_UART=n
CONFIG_LOG_BUFFER_SIZE=512
CONFIG_LOG_INPLACE_PROCESS=n
CONFIG_LOG_STRDUP_BUF_COUNT=1
CONFIG_LOG_STRDUP_MAX_STRING=8
CONFIG_KERNEL_LOG_LEVEL_OFF=y

View file

@ -2,4 +2,5 @@ tests:
logging.log_core:
tags: log_core logging
platform_exclude: altera_max10 qemu_nios2 nucleo_l053r8
nucleo_f030r8 quark_d2000_crb stm32f0_disco
nucleo_f030r8 quark_d2000_crb stm32f0_disco native_posix
nrf52_bsim

View file

@ -2,3 +2,4 @@ CONFIG_MAIN_THREAD_PRIORITY=5
CONFIG_ZTEST=y
CONFIG_LOG=y
CONFIG_LOG_PRINTK=n
CONFIG_LOG_IMMEDIATE=n