From 7e29c9da0bfcb40c32aa0b39d94381ef69a547c3 Mon Sep 17 00:00:00 2001 From: Andrew Boie Date: Sun, 22 Sep 2019 16:44:43 -0700 Subject: [PATCH] logging: add minimal implementation The log mechanism, even in immediate mode, adds somewhere between 1K-2K of footprint to applications that use it. We want to standardize the logging APIs for all logging within the kernel, but need to not let platforms with very constrained RAM/ROM in the dust. This patch introduces CONFIG_LOG_MINIMAL, which is a very thin wrapper to printk(). It supports the APIs expressed in logging/log.h. This will be the new default for test cases. Signed-off-by: Andrew Boie --- include/logging/log.h | 25 ++++-- include/logging/log_core.h | 148 ++++++++++++++++++++++------------ include/logging/log_ctrl.h | 2 +- subsys/logging/CMakeLists.txt | 70 ++++++++-------- subsys/logging/Kconfig | 17 +++- subsys/logging/log_minimal.c | 50 ++++++++++++ subsys/testsuite/Kconfig | 4 +- 7 files changed, 222 insertions(+), 94 deletions(-) create mode 100644 subsys/logging/log_minimal.c diff --git a/include/logging/log.h b/include/logging/log.h index 6f0705e893..cdd69a19b2 100644 --- a/include/logging/log.h +++ b/include/logging/log.h @@ -28,12 +28,6 @@ extern "C" { * @{ */ -#define LOG_LEVEL_NONE 0 -#define LOG_LEVEL_ERR 1 -#define LOG_LEVEL_WRN 2 -#define LOG_LEVEL_INF 3 -#define LOG_LEVEL_DBG 4 - /** * @brief Writes an ERROR level message to the log. * @@ -247,6 +241,7 @@ extern "C" { #define LOG_INST_HEXDUMP_DBG(_log_inst, _data, _length, _str) \ Z_LOG_HEXDUMP_INSTANCE(LOG_LEVEL_DBG, _log_inst, _data, _length, _str) +#ifndef CONFIG_LOG_MINIMAL /** * @brief Writes an formatted string to the log. * @@ -266,13 +261,29 @@ void log_printk(const char *fmt, va_list ap); * Logger allocates a buffer and copies input string returning a pointer to the * copy. Logger ensures that buffer is freed when logger message is freed. * + * Depending on configuration, this function may do nothing and just pass + * along the supplied string pointer. Do not rely on this function to always + * make a copy! + * * @param str Transient string. * * @return Copy of the string or default string if buffer could not be * allocated. String may be truncated if input string does not fit in - * a buffer from the pool (see CONFIG_LOG_STRDUP_MAX_STRING). + * a buffer from the pool (see CONFIG_LOG_STRDUP_MAX_STRING). In + * some configurations, the original string pointer is returned. */ char *log_strdup(const char *str); +#else +static inline void log_printk(const char *fmt, va_list ap) +{ + vprintk(fmt, ap); +} + +static inline char *log_strdup(const char *str) +{ + return (char *)str; +} +#endif /* CONFIG_LOG_MINIMAL */ #ifdef __cplusplus } diff --git a/include/logging/log_core.h b/include/logging/log_core.h index 579e826cec..24105b020b 100644 --- a/include/logging/log_core.h +++ b/include/logging/log_core.h @@ -13,6 +13,13 @@ #include #include #include +#include + +#define LOG_LEVEL_NONE 0 +#define LOG_LEVEL_ERR 1 +#define LOG_LEVEL_WRN 2 +#define LOG_LEVEL_INF 3 +#define LOG_LEVEL_DBG 4 #ifdef __cplusplus extern "C" { @@ -20,10 +27,13 @@ extern "C" { #ifndef CONFIG_LOG #define CONFIG_LOG_DEFAULT_LEVEL 0 -#define CONFIG_LOG_DOMAIN_ID 0 #define CONFIG_LOG_MAX_LEVEL 0 #endif +#if !defined(CONFIG_LOG) || defined(CONFIG_LOG_MINIMAL) +#define CONFIG_LOG_DOMAIN_ID 0 +#endif + #define LOG_FUNCTION_PREFIX_MASK \ (((u32_t)IS_ENABLED(CONFIG_LOG_FUNC_NAME_PREFIX_ERR) << \ LOG_LEVEL_ERR) | \ @@ -210,35 +220,67 @@ extern "C" { ) \ )) +/******************************************************************************/ +/****************** Defiinitions used by minimal logging **********************/ +/******************************************************************************/ +void log_minimal_hexdump_print(int level, const char *data, size_t size); + +#define Z_LOG_TO_PRINTK(_level, fmt, ...) do { \ + printk("%c: " fmt "\n", z_log_minimal_level_to_char(_level), \ + ##__VA_ARGS__); \ + } while (false) + +static inline char z_log_minimal_level_to_char(int level) +{ + switch (level) { + case LOG_LEVEL_ERR: + return 'E'; + case LOG_LEVEL_WRN: + return 'W'; + case LOG_LEVEL_INF: + return 'I'; + case LOG_LEVEL_DBG: + return 'D'; + default: + return '?'; + } +} /******************************************************************************/ /****************** Macros for standard logging *******************************/ /******************************************************************************/ -#define __LOG(_level, _id, _filter, ...) \ - do { \ - bool is_user_context = _is_user_context(); \ - \ - if (Z_LOG_CONST_LEVEL_CHECK(_level) && \ - (is_user_context || \ - (_level <= LOG_RUNTIME_FILTER(_filter)))) { \ - struct log_msg_ids src_level = { \ - .level = _level, \ - .domain_id = CONFIG_LOG_DOMAIN_ID, \ - .source_id = _id \ - }; \ - \ - if ((BIT(_level) & LOG_FUNCTION_PREFIX_MASK) != 0U) {\ - __LOG_INTERNAL(is_user_context, src_level, \ - Z_LOG_STR(__VA_ARGS__)); \ - } else { \ - __LOG_INTERNAL(is_user_context, src_level, \ - __VA_ARGS__); \ - } \ - } else if (false) { \ - /* Arguments checker present but never evaluated.*/ \ - /* Placed here to ensure that __VA_ARGS__ are*/ \ - /* evaluated once when log is enabled.*/ \ - log_printf_arg_checker(__VA_ARGS__); \ - } \ +#define __LOG(_level, _id, _filter, ...) \ + do { \ + bool is_user_context = _is_user_context(); \ + \ + if (Z_LOG_CONST_LEVEL_CHECK(_level)) { \ + if (IS_ENABLED(CONFIG_LOG_MINIMAL)) { \ + Z_LOG_TO_PRINTK(_level, __VA_ARGS__); \ + } else if (is_user_context || \ + (_level <= LOG_RUNTIME_FILTER(_filter))) { \ + struct log_msg_ids src_level = { \ + .level = _level, \ + .domain_id = CONFIG_LOG_DOMAIN_ID, \ + .source_id = _id \ + }; \ + \ + if ((BIT(_level) & \ + LOG_FUNCTION_PREFIX_MASK) != 0U) { \ + __LOG_INTERNAL(is_user_context, \ + src_level, \ + Z_LOG_STR(__VA_ARGS__));\ + } else { \ + __LOG_INTERNAL(is_user_context, \ + src_level, \ + __VA_ARGS__); \ + } \ + } \ + } \ + if (false) { \ + /* Arguments checker present but never evaluated.*/ \ + /* Placed here to ensure that __VA_ARGS__ are*/ \ + /* evaluated once when log is enabled.*/ \ + log_printf_arg_checker(__VA_ARGS__); \ + } \ } while (false) #define Z_LOG(_level, ...) \ @@ -259,29 +301,35 @@ extern "C" { /******************************************************************************/ /****************** Macros for hexdump logging ********************************/ /******************************************************************************/ -#define __LOG_HEXDUMP(_level, _id, _filter, _data, _length, _str) \ - do { \ - bool is_user_context = _is_user_context(); \ - \ - if (Z_LOG_CONST_LEVEL_CHECK(_level) && \ - (is_user_context || \ - (_level <= LOG_RUNTIME_FILTER(_filter)))) { \ - struct log_msg_ids src_level = { \ - .level = _level, \ - .source_id = _id, \ - .domain_id = CONFIG_LOG_DOMAIN_ID \ - }; \ - \ - if (is_user_context) { \ - log_hexdump_from_user(src_level, _str, \ - _data, _length); \ - } else if (IS_ENABLED(CONFIG_LOG_IMMEDIATE)) { \ - log_hexdump_sync(src_level, _str, \ - _data, _length); \ - } else { \ - log_hexdump(_str, _data, _length, src_level); \ - } \ - } \ +#define __LOG_HEXDUMP(_level, _id, _filter, _data, _length, _str) \ + do { \ + bool is_user_context = _is_user_context(); \ + \ + if (Z_LOG_CONST_LEVEL_CHECK(_level)) { \ + if (IS_ENABLED(CONFIG_LOG_MINIMAL)) { \ + Z_LOG_TO_PRINTK(_level, "%s", _str); \ + log_minimal_hexdump_print(_level, _data, \ + _length); \ + } else if (is_user_context || \ + (_level <= LOG_RUNTIME_FILTER(_filter))) { \ + struct log_msg_ids src_level = { \ + .level = _level, \ + .source_id = _id, \ + .domain_id = CONFIG_LOG_DOMAIN_ID \ + }; \ + \ + if (is_user_context) { \ + log_hexdump_from_user(src_level, _str, \ + _data, _length); \ + } else 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 Z_LOG_HEXDUMP(_level, _data, _length, _str) \ diff --git a/include/logging/log_ctrl.h b/include/logging/log_ctrl.h index 0a50b42127..13b8f41ebf 100644 --- a/include/logging/log_ctrl.h +++ b/include/logging/log_ctrl.h @@ -169,7 +169,7 @@ void log_backend_enable(struct log_backend const *const backend, */ void log_backend_disable(struct log_backend const *const backend); -#if defined(CONFIG_LOG) +#if defined(CONFIG_LOG) && !defined(CONFIG_LOG_MINIMAL) #define LOG_CORE_INIT() log_core_init() #define LOG_INIT() log_init() #define LOG_PANIC() log_panic() diff --git a/subsys/logging/CMakeLists.txt b/subsys/logging/CMakeLists.txt index 78520fc263..3c8e0f289e 100644 --- a/subsys/logging/CMakeLists.txt +++ b/subsys/logging/CMakeLists.txt @@ -1,49 +1,53 @@ # SPDX-License-Identifier: Apache-2.0 -zephyr_sources_ifdef( - CONFIG_LOG - log_list.c - log_core.c - log_msg.c - log_output.c +if(NOT CONFIG_LOG_MINIMAL) + zephyr_sources_ifdef( + CONFIG_LOG + log_list.c + log_core.c + log_msg.c + log_output.c ) -zephyr_sources_ifdef( - CONFIG_LOG_BACKEND_UART - log_backend_uart.c + zephyr_sources_ifdef( + CONFIG_LOG_BACKEND_UART + log_backend_uart.c ) -zephyr_sources_ifdef( - CONFIG_LOG_CMDS - log_cmds.c + zephyr_sources_ifdef( + CONFIG_LOG_CMDS + log_cmds.c ) -zephyr_sources_ifdef( - CONFIG_LOG_BACKEND_NATIVE_POSIX - log_backend_native_posix.c + zephyr_sources_ifdef( + CONFIG_LOG_BACKEND_NATIVE_POSIX + log_backend_native_posix.c ) -zephyr_sources_ifdef( - CONFIG_LOG_BACKEND_XTENSA_SIM - log_backend_xtensa_sim.c + zephyr_sources_ifdef( + CONFIG_LOG_BACKEND_XTENSA_SIM + log_backend_xtensa_sim.c ) -zephyr_sources_ifdef( - CONFIG_LOG_BACKEND_NET - log_backend_net.c + zephyr_sources_ifdef( + CONFIG_LOG_BACKEND_NET + log_backend_net.c ) -zephyr_sources_ifdef( - CONFIG_LOG_BACKEND_RTT - log_backend_rtt.c -) + zephyr_sources_ifdef( + CONFIG_LOG_BACKEND_RTT + log_backend_rtt.c + ) -zephyr_sources_ifdef( - CONFIG_LOG_BACKEND_SWO - log_backend_swo.c -) + zephyr_sources_ifdef( + CONFIG_LOG_BACKEND_SWO + log_backend_swo.c + ) -zephyr_sources_ifdef( - CONFIG_LOG_BACKEND_QEMU_X86_64 - log_backend_qemu_x86_64.c -) + zephyr_sources_ifdef( + CONFIG_LOG_BACKEND_QEMU_X86_64 + log_backend_qemu_x86_64.c + ) +else() + zephyr_sources(log_minimal.c) +endif() diff --git a/subsys/logging/Kconfig b/subsys/logging/Kconfig index ccd6b29c87..ddfd5e84e5 100644 --- a/subsys/logging/Kconfig +++ b/subsys/logging/Kconfig @@ -13,9 +13,21 @@ menuconfig LOG if LOG +config LOG_MINIMAL + bool "Enable minimal-footprint logging" + imply PRINTK + help + Enable minimal logging implementation. This has very little footprint + overhead on top of the printk() implementation for standard + logging macros. Hexdump macros are also supported, with a small + amount of code pulled in if used. Build time filtering is supported, + but not runtime filtering. There are no timestamps, prefixes, + colors, or asynchronous logging, and all messages are simply + sent to printk(). + config LOG_RUNTIME_FILTERING bool "Enable runtime reconfiguration of the logger" - depends on !LOG_FRONTEND + depends on !LOG_FRONTEND && !LOG_MINIMAL help Allow runtime configuration of maximal, independent severity level for instance. @@ -69,6 +81,8 @@ config LOG_MAX_LEVEL - 3 INFO, maximal level set to LOG_LEVEL_INFO - 4 DEBUG, maximal level set to LOG_LEVEL_DBG +if !LOG_MINIMAL + menu "Prepend log message with function name" depends on !LOG_FRONTEND @@ -477,4 +491,5 @@ config LOG_BACKEND_FORMAT_TIMESTAMP help When enabled timestamp is formatted to hh:mm:ss:ms,us. +endif # LOG_MINIMAL endif # LOG diff --git a/subsys/logging/log_minimal.c b/subsys/logging/log_minimal.c new file mode 100644 index 0000000000..0457fe33e5 --- /dev/null +++ b/subsys/logging/log_minimal.c @@ -0,0 +1,50 @@ +/* + * Copyright (c) 2019 Intel Corporation. + * + * SPDX-License-Identifier: Apache-2.0 + */ + +#include +#include +#include + +#define HEXDUMP_BYTES_IN_LINE 8 + +static void minimal_hexdump_line_print(const char *data, size_t length) +{ + for (int i = 0; i < HEXDUMP_BYTES_IN_LINE; i++) { + if (i < length) { + printk("%02x ", data[i] & 0xFF); + } else { + printk(" "); + } + } + + printk("|"); + + for (int i = 0; i < HEXDUMP_BYTES_IN_LINE; i++) { + if (i < length) { + char c = data[i]; + + printk("%c", isprint((int)c) ? c : '.'); + } else { + printk(" "); + } + } + printk("\n"); +} + +void log_minimal_hexdump_print(int level, const char *data, size_t size) +{ + while (size > 0) { + printk("%c: ", z_log_minimal_level_to_char(level)); + minimal_hexdump_line_print(data, size); + + if (size < HEXDUMP_BYTES_IN_LINE) { + break; + } + + size -= HEXDUMP_BYTES_IN_LINE; + data += HEXDUMP_BYTES_IN_LINE; + } +} diff --git a/subsys/testsuite/Kconfig b/subsys/testsuite/Kconfig index 8e2413271a..f80eb6791f 100644 --- a/subsys/testsuite/Kconfig +++ b/subsys/testsuite/Kconfig @@ -83,11 +83,11 @@ config TEST_LOGGING_DEFAULTS bool "Enable test case logging defaults" depends on TEST select LOG - select LOG_IMMEDIATE + select LOG_MINIMAL default y help Option which implements default policy of enabling logging in - immediate mode for all test cases. For tests that need alternate + minimal mode for all test cases. For tests that need alternate logging configuration, or no logging at all, disable this in the project-level defconfig.