From c73578f37ac7174f362be6865dc8307e4b324932 Mon Sep 17 00:00:00 2001 From: Tomasz Konieczny Date: Fri, 27 Mar 2020 08:24:53 +0100 Subject: [PATCH] logging: enhanced external logsystems Introduced interface for efficient logging from external logsystems: Added handling of vaargs and automatic strdup to macros intended to be used in logging interface function. Fast path to less then 4 arguments to speed up the execution. Made log_count_args external, if external logsystem cannot count arguments. Signed-off-by: Tomasz Konieczny --- include/logging/log_core.h | 136 +++++++++++++++++- .../logger/src/ext_log_system_adapter.c | 2 +- .../intel_s1000/xcc/log_minimal_fixes.c | 3 +- subsys/logging/log_core.c | 33 ++++- 4 files changed, 165 insertions(+), 9 deletions(-) diff --git a/include/logging/log_core.h b/include/logging/log_core.h index 7959b25ed7d..55fecaed3d0 100644 --- a/include/logging/log_core.h +++ b/include/logging/log_core.h @@ -416,6 +416,13 @@ static inline char z_log_minimal_level_to_char(int level) extern struct log_source_const_data __log_const_start[]; extern struct log_source_const_data __log_const_end[]; +/** @brief Enum with possible actions for strdup operation. */ +enum log_strdup_action { + LOG_STRDUP_SKIP, /**< None RAM string duplication. */ + LOG_STRDUP_EXEC, /**< Always duplicate RAM strings. */ + LOG_STRDUP_CHECK_EXEC/**< Duplicate RAM strings, if not dupl. before.*/ +}; + /** @brief Get name of the log source. * * @param source_id Source ID. @@ -586,8 +593,25 @@ void log_hexdump_sync(struct log_msg_ids src_level, const char *metadata, * @brief Writes a generic log message to the log. * * @note This function is intended to be used when porting other log systems. + * + * @param src_level Log identification. + * @param fmt String to format. + * @param ap Poiner to arguments list. + * @param strdup_action Manages strdup activity. */ -void log_generic(struct log_msg_ids src_level, const char *fmt, va_list ap); +void log_generic(struct log_msg_ids src_level, const char *fmt, va_list ap, + enum log_strdup_action strdup_action); + +/** + * @brief Returns number of arguments visible from format string. + * + * @note This function is intended to be used when porting other log systems. + * + * @param fmt Format string. + * + * @return Number of arguments. + */ +uint32_t log_count_args(const char *fmt); /** * @brief Writes a generic log message to the log from user mode. @@ -677,6 +701,116 @@ __syscall void z_log_hexdump_from_user(uint32_t src_level_val, const char *metadata, const uint8_t *data, uint32_t len); +/******************************************************************************/ +/********** Mocros _VA operate on var-args parameters. ***************/ +/********* Intended to be used when porting other log systems. ***************/ +/********* Shall be used in the log entry interface function. ***************/ +/********* Speed optimized for up to three arguments number. ***************/ +/******************************************************************************/ +#define Z_LOG_VA(_level, _str, _valist, _argnum, _strdup_action)\ + __LOG_VA(_level, \ + (uint16_t)LOG_CURRENT_MODULE_ID(), \ + LOG_CURRENT_DYNAMIC_DATA_ADDR(), \ + _str, _valist, _argnum, _strdup_action) + +#define __LOG_VA(_level, _id, _filter, _str, _valist, _argnum, _strdup_action) \ + do { \ + bool is_user_context = _is_user_context(); \ + \ + if (Z_LOG_CONST_LEVEL_CHECK(_level)) { \ + if (IS_ENABLED(CONFIG_LOG_MINIMAL)) { \ + if (IS_ENABLED(CONFIG_LOG_PRINTK)) { \ + log_printk(_str, _valist); \ + } else { \ + vprintk(_str, _valist); \ + } \ + } 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 \ + }; \ + __LOG_INTERNAL_VA(is_user_context, \ + src_level, \ + _str, _valist, _argnum, \ + _strdup_action); \ + } \ + } \ + } while (false) + +/** + * @brief Inline function to perform strdup, used in __LOG_INTERNAL_VA macro + * + * @note This function is intended to be used when porting other log systems. + * + * @param msk Bitmask marking all %s arguments. + * @param idx Index of actually processed argument. + * @param param Value of actually processed argument. + * @param action Action for strdup operation. + * + * @return Duplicated string or not changed param. + */ +static inline log_arg_t z_log_do_strdup(uint32_t msk, uint32_t idx, + log_arg_t param, + enum log_strdup_action action) +{ +#ifndef CONFIG_LOG_MINIMAL + char *log_strdup(const char *str); + + if (msk & (1 << idx)) { + const char *str = (const char *)param; + /* is_rodata(str) is not checked, + * because log_strdup does it. + * Hence, we will do only optional check + * if already not duplicated. + */ + if (action == LOG_STRDUP_EXEC || !log_is_strdup(str)) { + param = (log_arg_t)log_strdup(str); + } + } +#endif + return param; +} + +#define __LOG_INTERNAL_VA(is_user_context, _src_level, _str, _valist, \ + _argnum, _strdup_action) \ +do { \ + if (is_user_context) { \ + log_generic_from_user(_src_level, _str, _valist); \ + } else if (IS_ENABLED(CONFIG_LOG_IMMEDIATE)) { \ + log_generic(_src_level, _str, _valist, _strdup_action); \ + } else if (_argnum == 0) { \ + _LOG_INTERNAL_0(_src_level, _str); \ + } else { \ + uint32_t mask = (_strdup_action != LOG_STRDUP_SKIP) ? \ + z_log_get_s_mask(_str, _argnum) \ + : 0; \ + \ + if (_argnum == 1) { \ + _LOG_INTERNAL_1(_src_level, _str, \ + z_log_do_strdup(mask, 0, \ + va_arg(_valist, log_arg_t), _strdup_action));\ + } else if (_argnum == 2) { \ + _LOG_INTERNAL_2(_src_level, _str, \ + z_log_do_strdup(mask, 0, \ + va_arg(_valist, log_arg_t), _strdup_action), \ + z_log_do_strdup(mask, 1, \ + va_arg(_valist, log_arg_t), _strdup_action));\ + } else if (_argnum == 3) { \ + _LOG_INTERNAL_3(_src_level, _str, \ + z_log_do_strdup(mask, 0, \ + va_arg(_valist, log_arg_t), _strdup_action), \ + z_log_do_strdup(mask, 1, \ + va_arg(_valist, log_arg_t), _strdup_action), \ + z_log_do_strdup(mask, 2, \ + va_arg(_valist, log_arg_t), _strdup_action));\ + } else { \ + log_generic(_src_level, _str, _valist, _strdup_action);\ + } \ + } \ +} while (false) + #include #ifdef __cplusplus diff --git a/samples/subsys/logging/logger/src/ext_log_system_adapter.c b/samples/subsys/logging/logger/src/ext_log_system_adapter.c index 8c0714ad809..6f863b6c881 100644 --- a/samples/subsys/logging/logger/src/ext_log_system_adapter.c +++ b/samples/subsys/logging/logger/src/ext_log_system_adapter.c @@ -33,7 +33,7 @@ static void log_handler(enum ext_log_level level, const char *fmt, ...) va_list ap; va_start(ap, fmt); - log_generic(src_level, fmt, ap); + log_generic(src_level, fmt, ap, LOG_STRDUP_CHECK_EXEC); va_end(ap); } diff --git a/soc/xtensa/intel_s1000/xcc/log_minimal_fixes.c b/soc/xtensa/intel_s1000/xcc/log_minimal_fixes.c index 4e54fee3e61..4073849b675 100644 --- a/soc/xtensa/intel_s1000/xcc/log_minimal_fixes.c +++ b/soc/xtensa/intel_s1000/xcc/log_minimal_fixes.c @@ -61,7 +61,8 @@ void log_hexdump_sync(struct log_msg_ids src_level, const char *metadata, { } -void log_generic(struct log_msg_ids src_level, const char *fmt, va_list ap) +void log_generic(struct log_msg_ids src_level, const char *fmt, va_list ap, + enum log_strdup_action strdup_action) { } diff --git a/subsys/logging/log_core.c b/subsys/logging/log_core.c index 42ee425f036..1dd996a1f1d 100644 --- a/subsys/logging/log_core.c +++ b/subsys/logging/log_core.c @@ -335,7 +335,8 @@ void log_printk(const char *fmt, va_list ap) z_log_string_from_user(src_level_union.value, str); } else if (IS_ENABLED(CONFIG_LOG_IMMEDIATE)) { - log_generic(src_level_union.structure, fmt, ap); + log_generic(src_level_union.structure, fmt, ap, + LOG_STRDUP_SKIP); } else { uint8_t str[CONFIG_LOG_PRINTK_MAX_STRING_LENGTH + 1]; struct log_msg *msg; @@ -358,7 +359,7 @@ void log_printk(const char *fmt, va_list ap) * * Function counts number of '%' not followed by '%'. */ -static uint32_t count_args(const char *fmt) +uint32_t log_count_args(const char *fmt) { uint32_t args = 0U; bool prev = false; /* if previous char was a modificator. */ @@ -376,11 +377,12 @@ static uint32_t count_args(const char *fmt) return args; } -void log_generic(struct log_msg_ids src_level, const char *fmt, va_list ap) +void log_generic(struct log_msg_ids src_level, const char *fmt, va_list ap, + enum log_strdup_action strdup_action) { if (_is_user_context()) { log_generic_from_user(src_level, fmt, ap); - } else if (IS_ENABLED(CONFIG_LOG_IMMEDIATE) && + } else if (IS_ENABLED(CONFIG_LOG_IMMEDIATE) && (!IS_ENABLED(CONFIG_LOG_FRONTEND))) { struct log_backend const *backend; uint32_t timestamp = timestamp_func(); @@ -395,13 +397,32 @@ void log_generic(struct log_msg_ids src_level, const char *fmt, va_list ap) } } else { log_arg_t args[LOG_MAX_NARGS]; - uint32_t nargs = count_args(fmt); + uint32_t nargs = log_count_args(fmt); __ASSERT_NO_MSG(nargs < LOG_MAX_NARGS); for (int i = 0; i < nargs; i++) { args[i] = va_arg(ap, log_arg_t); } + if (strdup_action != LOG_STRDUP_SKIP) { + uint32_t mask = z_log_get_s_mask(fmt, nargs); + + while (mask) { + uint32_t idx = 31 - __builtin_clz(mask); + const char *str = (const char *)args[idx]; + + /* is_rodata(str) is not checked, + * because log_strdup does it. + * Hence, we will do only optional check + * if already not duplicated. + */ + if (strdup_action == LOG_STRDUP_EXEC + || !log_is_strdup(str)) { + args[idx] = (log_arg_t)log_strdup(str); + } + mask &= ~BIT(idx); + } + } log_n(fmt, args, nargs, src_level); } } @@ -412,7 +433,7 @@ void log_string_sync(struct log_msg_ids src_level, const char *fmt, ...) va_start(ap, fmt); - log_generic(src_level, fmt, ap); + log_generic(src_level, fmt, ap, LOG_STRDUP_SKIP); va_end(ap); }