From 117fab3004196d6fbdc65669c7d0cd4fbbc691c7 Mon Sep 17 00:00:00 2001 From: Krzysztof Chruscinski Date: Wed, 20 Nov 2019 14:28:06 +0100 Subject: [PATCH] logging: log_output: Improve immediate mode handling When in immediate mode ensure that buffering is not used in log output. Every byte is pushed to the transport. Signed-off-by: Krzysztof Chruscinski --- include/logging/log_output.h | 3 +- subsys/logging/Kconfig | 11 +++++++ subsys/logging/log_backend_std.h | 50 ++++++++++++++++++-------------- subsys/logging/log_output.c | 16 +++++++--- 4 files changed, 54 insertions(+), 26 deletions(-) diff --git a/include/logging/log_output.h b/include/logging/log_output.h index b4c0a62ee16..ddccab4a7b7 100644 --- a/include/logging/log_output.h +++ b/include/logging/log_output.h @@ -9,6 +9,7 @@ #include #include #include +#include #ifdef __cplusplus extern "C" { @@ -66,7 +67,7 @@ typedef int (*log_output_func_t)(u8_t *buf, size_t size, void *ctx); /* @brief Control block structure for log_output instance. */ struct log_output_control_block { - size_t offset; + atomic_t offset; void *ctx; const char *hostname; }; diff --git a/subsys/logging/Kconfig b/subsys/logging/Kconfig index 92c7522f60f..3dce7707537 100644 --- a/subsys/logging/Kconfig +++ b/subsys/logging/Kconfig @@ -127,6 +127,17 @@ config LOG_IMMEDIATE flawlessly in that mode because one log operation can be interrupted by another one in the higher priority context. +if LOG_IMMEDIATE +config LOG_IMMEDIATE_CLEAN_OUTPUT + bool "Enable clean log output" + help + If enabled, interrupts are locked during whole log message processing. + As a result, processing on one log message cannot be interrupted by + another one and output is clean, not interleaved. However, enabling + this option is causing interrupts locking for significant amount of + time (up to multiple milliseconds). +endif + config LOG_ENABLE_FANCY_OUTPUT_FORMATTING depends on MINIMAL_LIBC bool "Format strings with minimal libc _prf() instead of _vprintk()" diff --git a/subsys/logging/log_backend_std.h b/subsys/logging/log_backend_std.h index 7b9d1f26ca4..a184a7ab879 100644 --- a/subsys/logging/log_backend_std.h +++ b/subsys/logging/log_backend_std.h @@ -8,7 +8,7 @@ #include #include -#include +#include #ifdef __cplusplus extern "C" { @@ -76,7 +76,7 @@ log_backend_std_sync_string(const struct log_output *const log_output, u32_t flags, struct log_msg_ids src_level, u32_t timestamp, const char *fmt, va_list ap) { - u32_t key; + int key; flags |= LOG_OUTPUT_FLAG_LEVEL | LOG_OUTPUT_FLAG_TIMESTAMP; if (IS_ENABLED(CONFIG_LOG_BACKEND_SHOW_COLOR)) { @@ -87,16 +87,20 @@ log_backend_std_sync_string(const struct log_output *const log_output, flags |= LOG_OUTPUT_FLAG_FORMAT_TIMESTAMP; } - key = irq_lock(); - /* Even though interrupts are locked here there are still cases when - * it may lead to failure. Log output is not re-entrant and irq_lock - * does not prevent NMI or ZLI (Zero latency interrupts). If context - * is interrupted by NMI it usually means fault scenario and best that - * can be done is to flush the output and process new data. - */ - log_output_flush(log_output); + if (IS_ENABLED(CONFIG_LOG_IMMEDIATE) && + IS_ENABLED(CONFIG_LOG_IMMEDIATE_CLEAN_OUTPUT)) { + /* In order to ensure that one log processing is not interrupted + * by another one, lock context for whole log processing. + */ + key = irq_lock(); + } + log_output_string(log_output, src_level, timestamp, fmt, ap, flags); - irq_unlock(key); + + if (IS_ENABLED(CONFIG_LOG_IMMEDIATE) && + IS_ENABLED(CONFIG_LOG_IMMEDIATE_CLEAN_OUTPUT)) { + irq_unlock(key); + } } /** @brief Synchronously process hexdump message by a standard logger backend. @@ -115,7 +119,7 @@ log_backend_std_sync_hexdump(const struct log_output *const log_output, u32_t timestamp, const char *metadata, const u8_t *data, u32_t length) { - u32_t key; + int key; flags |= LOG_OUTPUT_FLAG_LEVEL | LOG_OUTPUT_FLAG_TIMESTAMP; if (IS_ENABLED(CONFIG_LOG_BACKEND_SHOW_COLOR)) { @@ -126,17 +130,21 @@ log_backend_std_sync_hexdump(const struct log_output *const log_output, flags |= LOG_OUTPUT_FLAG_FORMAT_TIMESTAMP; } - key = irq_lock(); - /* Even though interrupts are locked here there are still cases when - * it may lead to failure. Log output is not re-entrant and irq_lock - * does not prevent NMI or ZLI (Zero latency interrupts). If context - * is interrupted by NMI it usually means fault scenario and best that - * can be done is to flush the output and process new data. - */ - log_output_flush(log_output); + if (IS_ENABLED(CONFIG_LOG_IMMEDIATE) && + IS_ENABLED(CONFIG_LOG_IMMEDIATE_CLEAN_OUTPUT)) { + /* In order to ensure that one log processing is not interrupted + * by another one, lock context for whole log processing. + */ + key = irq_lock(); + } + log_output_hexdump(log_output, src_level, timestamp, metadata, data, length, flags); - irq_unlock(key); + + if (IS_ENABLED(CONFIG_LOG_IMMEDIATE) && + IS_ENABLED(CONFIG_LOG_IMMEDIATE_CLEAN_OUTPUT)) { + irq_unlock(key); + } } #ifdef __cplusplus diff --git a/subsys/logging/log_output.c b/subsys/logging/log_output.c index 801ea06ba6c..802f880eace 100644 --- a/subsys/logging/log_output.c +++ b/subsys/logging/log_output.c @@ -102,16 +102,23 @@ static int out_func(int c, void *ctx) { const struct log_output *out_ctx = (const struct log_output *)ctx; + int idx; - out_ctx->buf[out_ctx->control_block->offset] = (u8_t)c; - out_ctx->control_block->offset++; - - __ASSERT_NO_MSG(out_ctx->control_block->offset <= out_ctx->size); + if (IS_ENABLED(CONFIG_LOG_IMMEDIATE)) { + /* Backend must be thread safe in synchronous operation. */ + out_ctx->func((u8_t *)&c, 1, out_ctx->control_block->ctx); + return 0; + } if (out_ctx->control_block->offset == out_ctx->size) { log_output_flush(out_ctx); } + idx = atomic_inc(&out_ctx->control_block->offset); + out_ctx->buf[idx] = (u8_t)c; + + __ASSERT_NO_MSG(out_ctx->control_block->offset <= out_ctx->size); + return 0; } @@ -145,6 +152,7 @@ static void buffer_write(log_output_func_t outf, u8_t *buf, size_t len, } while (len != 0); } + void log_output_flush(const struct log_output *log_output) { buffer_write(log_output->func, log_output->buf,