From f6a40ae183ed0781ffcdeac4ba9263116247a750 Mon Sep 17 00:00:00 2001 From: Krzysztof Chruscinski Date: Thu, 19 Nov 2020 17:25:03 +0100 Subject: [PATCH] logging: Add logging v2 implementation for log_msg Added implementation of log_msg2 which is creating log messages using cbprintf packaging and storing them in circular ring buffer (mpsg_pbuf). Signed-off-by: Krzysztof Chruscinski --- include/linker/common-rom.ld | 7 + include/logging/log_core.h | 2 + include/logging/log_core2.h | 72 ++ include/logging/log_ctrl.h | 9 +- include/logging/log_msg.h | 1 + include/logging/log_msg2.h | 653 ++++++++++++++++++ subsys/logging/CMakeLists.txt | 6 + subsys/logging/Kconfig | 7 +- subsys/logging/Kconfig.misc | 39 +- subsys/logging/Kconfig.mode | 4 + subsys/logging/Kconfig.processing | 18 + subsys/logging/log_core.c | 105 ++- subsys/logging/log_msg2.c | 101 +++ .../subsys/logging/log_msg/src/log_msg_test.c | 4 +- 14 files changed, 1008 insertions(+), 20 deletions(-) create mode 100644 include/logging/log_core2.h create mode 100644 include/logging/log_msg2.h create mode 100644 subsys/logging/log_msg2.c diff --git a/include/linker/common-rom.ld b/include/linker/common-rom.ld index 5b73817cd4e..5642e7be662 100644 --- a/include/linker/common-rom.ld +++ b/include/linker/common-rom.ld @@ -153,6 +153,13 @@ } GROUP_LINK_IN(ROMABLE_REGION) #endif /* CONFIG_PCIE */ + SECTION_DATA_PROLOGUE(log_strings_sections,,) + { + __log_strings_start = .; + KEEP(*(SORT(.log_strings*))); + __log_strings_end = .; + } GROUP_ROM_LINK_IN(RAMABLE_REGION, ROMABLE_REGION) + SECTION_DATA_PROLOGUE(log_const_sections,,) { __log_const_start = .; diff --git a/include/logging/log_core.h b/include/logging/log_core.h index fa953d5aa86..533106791fb 100644 --- a/include/logging/log_core.h +++ b/include/logging/log_core.h @@ -7,6 +7,7 @@ #define ZEPHYR_INCLUDE_LOGGING_LOG_CORE_H_ #include +#include #include #include #include @@ -438,6 +439,7 @@ enum log_strdup_action { LOG_LEVEL_INTERNAL_RAW_STRING, NULL, 0, __VA_ARGS__);\ } while (0) + /** @brief Get name of the log source. * * @param source_id Source ID. diff --git a/include/logging/log_core2.h b/include/logging/log_core2.h new file mode 100644 index 00000000000..8438814c69c --- /dev/null +++ b/include/logging/log_core2.h @@ -0,0 +1,72 @@ +/* + * Copyright (c) 2021 Nordic Semiconductor ASA + * + * SPDX-License-Identifier: Apache-2.0 + */ +#ifndef ZEPHYR_INCLUDE_LOGGING_LOG_CORE2_H_ +#define ZEPHYR_INCLUDE_LOGGING_LOG_CORE2_H_ + +#include + +#ifdef __cplusplus +extern "C" { +#endif + +#define Z_TRACING_LOG_TRACE(id) do { \ + Z_TRACING_LOG_HDR_INIT(_msg, id); \ + z_log_msg2_put_trace(_msg); \ +} while (0) + +#define Z_TRACING_LOG_TRACE_PTR(id, ptr) do { \ + Z_TRACING_LOG_HDR_INIT(_msg, id); \ + z_log_msg2_put_trace_ptr(_msg, ptr); \ +} while (0) + +void z_log_msg2_put_trace(struct log_msg2_trace trace); + +void z_log_msg2_put_trace_ptr(struct log_msg2_trace hdr, void *data); + + +/** @brief Initialize module for handling logging message. */ +void z_log_msg2_init(void); + +/** @brief Allocate log message. + * + * @param wlen Length in 32 bit words. + * + * @return allocated space or null if cannot be allocated. + */ +struct log_msg2 *z_log_msg2_alloc(uint32_t wlen); + +/** @brief Commit log message. + * + * @param msg Message. + */ +void z_log_msg2_commit(struct log_msg2 *msg); + +/** @brief Get pending log message. + * + * @param[out] len Message length in bytes is written is @p len is not null. + * + * @param Message or null if no pending messages. + */ +union log_msg2_generic *z_log_msg2_claim(void); + +/** @brief Free message. + * + * @param msg Message. + */ +void z_log_msg2_free(union log_msg2_generic *msg); + +/** @brief Check if there are any message pending. + * + * @retval true if at least one message is pending. + * @retval false if no message is pending. + */ +bool z_log_msg2_pending(void); + +#ifdef __cplusplus +} +#endif + +#endif /* ZEPHYR_INCLUDE_LOGGING_LOG_CORE2_H_ */ diff --git a/include/logging/log_ctrl.h b/include/logging/log_ctrl.h index a861f32952a..af7e5794185 100644 --- a/include/logging/log_ctrl.h +++ b/include/logging/log_ctrl.h @@ -6,14 +6,14 @@ #ifndef ZEPHYR_INCLUDE_LOGGING_LOG_CTRL_H_ #define ZEPHYR_INCLUDE_LOGGING_LOG_CTRL_H_ -#include #include +#include +#include #ifdef __cplusplus extern "C" { #endif - /** * @brief Logger * @defgroup logger Logger system @@ -29,7 +29,7 @@ extern "C" { * @{ */ -typedef uint32_t (*timestamp_get_t)(void); +typedef log_timestamp_t (*log_timestamp_get_t)(void); /** @brief Function system initialization of the logger. * @@ -63,7 +63,8 @@ void log_thread_set(k_tid_t process_tid); * * @return 0 on success or error. */ -int log_set_timestamp_func(timestamp_get_t timestamp_getter, uint32_t freq); +int log_set_timestamp_func(log_timestamp_get_t timestamp_getter, + uint32_t freq); /** * @brief Switch the logger subsystem to the panic mode. diff --git a/include/logging/log_msg.h b/include/logging/log_msg.h index 892d3f98561..3daf56f0c79 100644 --- a/include/logging/log_msg.h +++ b/include/logging/log_msg.h @@ -9,6 +9,7 @@ #include #include #include +#include #ifdef __cplusplus extern "C" { diff --git a/include/logging/log_msg2.h b/include/logging/log_msg2.h new file mode 100644 index 00000000000..b5d3cd1cd8f --- /dev/null +++ b/include/logging/log_msg2.h @@ -0,0 +1,653 @@ +/* + * Copyright (c) 2021 Nordic Semiconductor ASA + * + * SPDX-License-Identifier: Apache-2.0 + */ +#ifndef ZEPHYR_INCLUDE_LOGGING_LOG_MSG2_H_ +#define ZEPHYR_INCLUDE_LOGGING_LOG_MSG2_H_ + +#include +#include +#include +#include +#include +#include + +#ifdef __GNUC__ +#ifndef alloca +#define alloca __builtin_alloca +#endif +#else +#include +#endif + +#ifdef __cplusplus +extern "C" { +#endif + +#define LOG_MSG2_DEBUG 0 +#define LOG_MSG2_DBG(...) IF_ENABLED(LOG_MSG2_DEBUG, (printk(__VA_ARGS__))) + +#if CONFIG_LOG_TIMESTAMP_64BIT +typedef uint64_t log_timestamp_t; +#else +typedef uint32_t log_timestamp_t; +#endif + +/** + * @brief Log message API + * @defgroup log_msg2 Log message v2 API + * @ingroup logger + * @{ + */ + +#define Z_LOG_MSG2_LOG 0 +#define Z_LOG_MSG2_TRACE 1 + +#define LOG_MSG2_GENERIC_HDR \ + MPSC_PBUF_HDR;\ + uint32_t type:1 + +struct log_msg2_desc { + LOG_MSG2_GENERIC_HDR; + uint32_t domain:3; + uint32_t level:3; + uint32_t package_len:10; + uint32_t data_len:12; + uint32_t reserved:1; +}; + +struct log_msg2_trace_hdr { + LOG_MSG2_GENERIC_HDR; + uint32_t evt_id:5; +#if CONFIG_LOG_TRACE_SHORT_TIMESTAMP + uint32_t timestamp:24; +#else + log_timestamp_t timestamp; +#endif +}; + +union log_msg2_source { + const struct log_source_const_data *fixed; + struct log_source_dynamic_data *dynamic; + void *raw; +}; + +struct log_msg2_hdr { + struct log_msg2_desc desc; +/* Attempting to keep best alignment. When address is 64 bit and timestamp 32 + * swap the order to have 16 byte header instead of 24 byte. + */ +#if (INTPTR_MAX > INT32_MAX) && !CONFIG_LOG_TIMESTAMP_64BIT + log_timestamp_t timestamp; + const void *source; +#else + const void *source; + log_timestamp_t timestamp; +#endif +#if defined(__xtensa__) && !defined(CONFIG_LOG_TIMESTAMP_64BIT) + /* xtensa requires that cbprintf package that follows the header is + * aligned to 16 bytes. Adding padding when necessary. + */ + uint32_t padding; +#endif +}; + +struct log_msg2_trace { + struct log_msg2_trace_hdr hdr; +}; + +struct log_msg2_trace_ptr { + struct log_msg2_trace_hdr hdr; + void *ptr; +}; + +struct log_msg2 { + struct log_msg2_hdr hdr; + uint8_t data[]; +}; + +struct log_msg2_generic_hdr { + LOG_MSG2_GENERIC_HDR; +}; + +union log_msg2_generic { + union mpsc_pbuf_generic buf; + struct log_msg2_generic_hdr generic; + struct log_msg2_trace trace; + struct log_msg2_trace_ptr trace_ptr; + struct log_msg2 log; +}; + +enum tracing_log_id { + TRACING_LOG_THREAD_SWITCHED_OUT, + TRACING_LOG_ISR_ENTER, + TRACING_LOG_ISR_EXIT, + TRACING_LOG_ISR_EXIT_TO_SCHEDULER, + TRACING_LOG_IDLE, + + TRACING_LOG_SINGLE_WORD = TRACING_LOG_IDLE, + + /* IDs using additional data */ + TRACING_LOG_THREAD_SWITCHED_IN, + TRACING_LOG_THREAD_PRIO_SET, + TRACING_LOG_THREAD_CREATE, + TRACING_LOG_THREAD_ABORT, + TRACING_LOG_THREAD_SUSPEND, + TRACING_LOG_THREAD_RESUME, + TRACING_LOG_THREAD_READY, + TRACING_LOG_THREAD_PEND, + TRACING_LOG_THREAD_INFO, + TRACING_LOG_THREAD_NAME_SET, + TRACING_LOG_VOID, + TRACING_LOG_END_CALL, + TRACING_LOG_SEMAPHORE_INIT, + TRACING_LOG_SEMAPHORE_TAKE, + TRACING_LOG_SEMAPHORE_GIVE, + TRACING_LOG_MUTEX_INIT, + TRACING_LOG_MUTEX_LOCK, + TRACING_LOG_MUTEX_UNLOCK +}; + +/** @brief Method used for creating a log message. + * + * It is used for testing purposes to validate that expected mode was used. + */ +enum z_log_msg2_mode { + /* Runtime mode is least efficient but supports all cases thus it is + * threated as a fallback method when others cannot be used. + */ + Z_LOG_MSG2_MODE_RUNTIME, + /* Mode creates statically a string package on stack and calls a + * function for creating a message. It takes code size than + * Z_LOG_MSG2_MODE_ZERO_COPY but is a bit slower. + */ + Z_LOG_MSG2_MODE_FROM_STACK, + + /* Mode calculates size of the message and allocates it and writes + * directly to the message space. It is the fastest method but requires + * more code size. + */ + Z_LOG_MSG2_MODE_ZERO_COPY, + + /* Mode used when synchronous logging is enabled. */ + Z_LOG_MSG2_MODE_SYNC +}; + +#define Z_LOG_MSG_DESC_INITIALIZER(_domain_id, _level, _plen, _dlen) \ +{ \ + .type = Z_LOG_MSG2_LOG, \ + .domain = _domain_id, \ + .level = _level, \ + .package_len = _plen, \ + .data_len = _dlen, \ +} + +/* Messages are aligned to alignment required by cbprintf package. */ +#define Z_LOG_MSG2_ALIGNMENT CBPRINTF_PACKAGE_ALIGNMENT + + +#if CONFIG_LOG2_USE_VLA +#define Z_LOG_MSG2_ON_STACK_ALLOC(ptr, len) \ + long long _ll_buf[ceiling_fraction(len, sizeof(long long))]; \ + long double _ld_buf[ceiling_fraction(len, sizeof(long double))]; \ + ptr = (sizeof(long double) == Z_LOG_MSG2_ALIGNMENT) ? \ + (void *)_ld_buf : (void *)_ll_buf; \ + if (IS_ENABLED(CONFIG_LOG_TEST_CLEAR_MESSAGE_SPACE)) { \ + /* During test fill with 0's to simplify message comparison */ \ + memset(ptr, 0, len); \ + } +#else /* Z_LOG_MSG2_USE_VLA */ +/* When VLA cannot be used we need to trick compiler a bit and create multiple + * fixed size arrays and take the smallest one that will fit the message. + * Compiler will remove unused arrays and stack usage will be kept similar + * to vla case, rounded to the size of the used buffer. + */ +#define Z_LOG_MSG2_ON_STACK_ALLOC(ptr, len) \ + long long _ll_buf32[32 / sizeof(long long)]; \ + long long _ll_buf48[48 / sizeof(long long)]; \ + long long _ll_buf64[64 / sizeof(long long)]; \ + long long _ll_buf128[128 / sizeof(long long)]; \ + long long _ll_buf256[256 / sizeof(long long)]; \ + long double _ld_buf32[32 / sizeof(long double)]; \ + long double _ld_buf48[48 / sizeof(long double)]; \ + long double _ld_buf64[64 / sizeof(long double)]; \ + long double _ld_buf128[128 / sizeof(long double)]; \ + long double _ld_buf256[256 / sizeof(long double)]; \ + if (sizeof(long double) == Z_LOG_MSG2_ALIGNMENT) { \ + ptr = (len > 128) ? (void *)_ld_buf256 : \ + ((len > 64) ? (void *)_ld_buf128 : \ + ((len > 48) ? (void *)_ld_buf64 : \ + ((len > 32) ? (void *)_ld_buf48 : (void *)_ld_buf32)));\ + } else { \ + ptr = (len > 128) ? (void *)_ll_buf256 : \ + ((len > 64) ? (void *)_ll_buf128 : \ + ((len > 48) ? (void *)_ll_buf64 : \ + ((len > 32) ? (void *)_ll_buf48 : (void *)_ll_buf32)));\ + } \ + if (IS_ENABLED(CONFIG_LOG_TEST_CLEAR_MESSAGE_SPACE)) { \ + /* During test fill with 0's to simplify message comparison */ \ + memset(ptr, 0, len); \ + } +#endif /* Z_LOG_MSG2_USE_VLA */ + +#define Z_LOG_MSG2_ALIGN_OFFSET \ + sizeof(struct log_msg2_hdr) + +#define Z_LOG_MSG2_LEN(pkg_len, data_len) \ + (sizeof(struct log_msg2_hdr) + pkg_len + (data_len)) + +#define Z_LOG_MSG2_ALIGNED_WLEN(pkg_len, data_len) \ + ceiling_fraction(ROUND_UP(Z_LOG_MSG2_LEN(pkg_len, data_len), \ + Z_LOG_MSG2_ALIGNMENT), \ + sizeof(uint32_t)) + +#define Z_LOG_MSG2_SYNC(_domain_id, _source, _level, _data, _dlen, ...) do { \ + int _plen; \ + CBPRINTF_STATIC_PACKAGE(NULL, 0, _plen, Z_LOG_MSG2_ALIGN_OFFSET, \ + __VA_ARGS__); \ + struct log_msg2 *_msg; \ + Z_LOG_MSG2_ON_STACK_ALLOC(_msg, Z_LOG_MSG2_LEN(_plen, _dlen)); \ + if (_plen) {\ + CBPRINTF_STATIC_PACKAGE(_msg->data, _plen, _plen, \ + Z_LOG_MSG2_ALIGN_OFFSET, __VA_ARGS__); \ + } \ + struct log_msg2_desc _desc = \ + Z_LOG_MSG_DESC_INITIALIZER(_domain_id, _level, \ + _plen, _dlen); \ + z_log_msg2_finalize(_msg, _source, _desc, _data); \ +} while (0) + +#define Z_LOG_MSG2_STACK_CREATE(_domain_id, _source, _level, _data, _dlen, ...)\ +do { \ + int _plen; \ + if (GET_ARG_N(1, __VA_ARGS__) == NULL) { \ + _plen = 0; \ + } else { \ + CBPRINTF_STATIC_PACKAGE(NULL, 0, _plen, \ + Z_LOG_MSG2_ALIGN_OFFSET, __VA_ARGS__); \ + } \ + struct log_msg2 *_msg; \ + Z_LOG_MSG2_ON_STACK_ALLOC(_msg, Z_LOG_MSG2_LEN(_plen, 0)); \ + if (_plen) { \ + CBPRINTF_STATIC_PACKAGE(_msg->data, _plen, \ + _plen, Z_LOG_MSG2_ALIGN_OFFSET, \ + __VA_ARGS__);\ + } \ + struct log_msg2_desc _desc = \ + Z_LOG_MSG_DESC_INITIALIZER(_domain_id, _level, \ + _plen, _dlen); \ + LOG_MSG2_DBG("creating message on stack: package len: %d, data len: %d\n", \ + _plen, (int)(_dlen)); \ + z_log_msg2_static_create((void *)_source, _desc, _msg->data, _data); \ +} while (0) + +#define Z_LOG_MSG2_SIMPLE_CREATE(_domain_id, _source, _level, ...) do { \ + int _plen; \ + CBPRINTF_STATIC_PACKAGE(NULL, 0, _plen, Z_LOG_MSG2_ALIGN_OFFSET, \ + __VA_ARGS__); \ + size_t _msg_wlen = Z_LOG_MSG2_ALIGNED_WLEN(_plen, 0); \ + struct log_msg2 *_msg = z_log_msg2_alloc(_msg_wlen); \ + struct log_msg2_desc _desc = \ + Z_LOG_MSG_DESC_INITIALIZER(_domain_id, _level, _plen, 0); \ + LOG_MSG2_DBG("creating message zero copy: package len: %d, msg: %p\n", \ + _plen, _msg); \ + if (_msg) { \ + CBPRINTF_STATIC_PACKAGE(_msg->data, _plen, _plen, \ + Z_LOG_MSG2_ALIGN_OFFSET, __VA_ARGS__); \ + } \ + z_log_msg2_finalize(_msg, (void *)_source, _desc, NULL); \ +} while (0) + +/* Macro handles case when local variable with log message string is created.It + * replaces origing string literal with that variable. + */ +#define Z_LOG_FMT_ARGS_2(_name, ...) \ + COND_CODE_1(CONFIG_LOG2_FMT_SECTION, \ + (COND_CODE_0(NUM_VA_ARGS_LESS_1(__VA_ARGS__), \ + (_name), (_name, GET_ARGS_LESS_N(1, __VA_ARGS__)))), \ + (__VA_ARGS__)) + +/** @brief Wrapper for log message string with arguments. + * + * Wrapper is replacing first argument with a variable from a dedicated memory + * section if option is enabled. Macro handles the case when there is no + * log message provided. + * + * @param _name Name of the variable with log message string. It is optionally used. + * @param ... Optional log message with arguments (may be empty). + */ +#define Z_LOG_FMT_ARGS(_name, ...) \ + COND_CODE_0(NUM_VA_ARGS_LESS_1(_, ##__VA_ARGS__), \ + (NULL), \ + (Z_LOG_FMT_ARGS_2(_name, ##__VA_ARGS__))) + +/* Macro handles case when there is no string provided, in that case variable + * is not created. + */ +#define Z_LOG_MSG2_STR_VAR_IN_SECTION(_name, ...) \ + COND_CODE_0(NUM_VA_ARGS_LESS_1(_, ##__VA_ARGS__), \ + (/* No args provided, no variable */), \ + (static const char _name[] \ + __attribute__((__section__(".log_strings"))) = \ + GET_ARG_N(1, __VA_ARGS__);)) + +/** @brief Create variable in the dedicated memory section (if enabled). + * + * Variable is initialized with a format string from the log message. + * + * @param _name Variable name. + * @param ... Optional log message with arguments (may be empty). + */ +#define Z_LOG_MSG2_STR_VAR(_name, ...) \ + IF_ENABLED(CONFIG_LOG2_FMT_SECTION, \ + (Z_LOG_MSG2_STR_VAR_IN_SECTION(_name, ##__VA_ARGS__))) + +/** @brief Create log message and write it into the logger buffer. + * + * Macro handles creation of log message which includes storing log message + * description, timestamp, arguments, copying string arguments into message and + * copying user data into the message space. The are 3 modes of message + * creation: + * - at compile time message size is determined, message is allocated and + * content is written directly to the message. It is the fastest but cannot + * be used in user mode. Message size cannot be determined at compile time if + * it contains data or string arguments which are string pointers. + * - at compile time message size is determined, string package is created on + * stack, message is created in function call. String package can only be + * created on stack if it does not contain unexpected pointers to strings. + * - string package is created at runtime. This mode has no limitations but + * it is significantly slower. + * + * @param _try_0cpy If positive then, if possible, message content is written + * directly to message. If 0 then, if possible, string package is created on + * the stack and message is created in the function call. + * + * @param _mode Used for testing. It is set according to message creation mode + * used. + * + * @param _cstr_cnt Number of constant strings present in the string. It is + * used to help detect messages which must be runtime processed, compared to + * message which can be prebuilt at compile time. + * + * @param _domain_id Domain ID. + * + * @param _source Pointer to the constant descriptor of the log message source. + * + * @param _level Log message level. + * + * @param _data Pointer to the data. Can be null. + * + * @param _dlen Number of data bytes. 0 if data is not provided. + * + * @param ... Optional string with arguments (fmt, ...). It may be empty. + */ +#if CONFIG_LOG2_ALWAYS_RUNTIME +#define Z_LOG_MSG2_CREATE2(_try_0cpy, _mode, _cstr_cnt, _domain_id, _source,\ + _level, _data, _dlen, ...) \ +do {\ + Z_LOG_MSG2_STR_VAR(_fmt, ##__VA_ARGS__) \ + z_log_msg2_runtime_create(_domain_id, (void *)_source, \ + _level, (uint8_t *)_data, _dlen,\ + Z_LOG_FMT_ARGS(_fmt, ##__VA_ARGS__));\ + _mode = Z_LOG_MSG2_MODE_RUNTIME; \ +} while (0) +#else /* CONFIG_LOG2_ALWAYS_RUNTIME */ +#define Z_LOG_MSG2_CREATE2(_try_0cpy, _mode, _cstr_cnt, _domain_id, _source,\ + _level, _data, _dlen, ...) \ +do { \ + Z_LOG_MSG2_STR_VAR(_fmt, ##__VA_ARGS__); \ + if (CBPRINTF_MUST_RUNTIME_PACKAGE(_cstr_cnt, __VA_ARGS__)) { \ + LOG_MSG2_DBG("create runtime message\n");\ + z_log_msg2_runtime_create(_domain_id, (void *)_source, \ + _level, (uint8_t *)_data, _dlen,\ + Z_LOG_FMT_ARGS(_fmt, ##__VA_ARGS__));\ + _mode = Z_LOG_MSG2_MODE_RUNTIME; \ + } else if (IS_ENABLED(CONFIG_LOG2_MODE_IMMEDIATE)) {\ + Z_LOG_MSG2_SYNC(_domain_id, _source, _level, \ + _data, _dlen, Z_LOG_FMT_ARGS(_fmt, ##__VA_ARGS__)); \ + _mode = Z_LOG_MSG2_MODE_SYNC; \ + } else if (IS_ENABLED(CONFIG_LOG_SPEED) && _try_0cpy && ((_dlen) == 0)) {\ + LOG_MSG2_DBG("create zero-copy message\n");\ + Z_LOG_MSG2_SIMPLE_CREATE(_domain_id, _source, \ + _level, Z_LOG_FMT_ARGS(_fmt, ##__VA_ARGS__)); \ + _mode = Z_LOG_MSG2_MODE_ZERO_COPY; \ + } else { \ + LOG_MSG2_DBG("create on stack message\n");\ + Z_LOG_MSG2_STACK_CREATE(_domain_id, _source, _level, _data, \ + _dlen, Z_LOG_FMT_ARGS(_fmt, ##__VA_ARGS__)); \ + _mode = Z_LOG_MSG2_MODE_FROM_STACK; \ + } \ + (void)_mode; \ +} while (0) +#endif /* CONFIG_LOG2_ALWAYS_RUNTIME */ + +#define Z_LOG_MSG2_CREATE(_try_0cpy, _mode, _domain_id, _source,\ + _level, _data, _dlen, ...) \ +do { \ + if (BIT(_level) & LOG_FUNCTION_PREFIX_MASK) {\ + Z_LOG_MSG2_CREATE2(_try_0cpy, _mode, 1, _domain_id, _source, \ + _level, _data, _dlen, Z_LOG_STR(__VA_ARGS__));\ + } else { \ + Z_LOG_MSG2_CREATE2(_try_0cpy, _mode, 0, _domain_id, _source, \ + _level, _data, _dlen, __VA_ARGS__); \ + } \ +} while (0) + +#define Z_TRACING_LOG_HDR_INIT(name, id) \ + struct log_msg2_trace name = { \ + .hdr = { \ + .type = Z_LOG_MSG2_TRACE, \ + .valid = 1, \ + .busy = 0, \ + .evt_id = id, \ + } \ + } + +/** @brief Finalize message. + * + * Finalization includes setting source, copying data and timestamp in the + * message followed by committing the message. + * + * @param msg Message. + * + * @param source Address of the source descriptor. + * + * @param desc Message descriptor. + * + * @param data Data. + */ +void z_log_msg2_finalize(struct log_msg2 *msg, const void *source, + const struct log_msg2_desc desc, const void *data); + +/** @brief Create simple message from message details and string package. + * + * @param source Source. + * + * @param desc Message descriptor. + * + * @param package Package. + * + * @oaram data Data. + */ +__syscall void z_log_msg2_static_create(const void *source, + const struct log_msg2_desc desc, + uint8_t *package, const void *data); + +/** @brief Create message at runtime. + * + * Function allows to build any log message based on input data. Processing + * time is significantly higher than statically message creating. + * + * @param domain_id Domain ID. + * + * @param source Source. + * + * @param level Log level. + * + * @param data Data. + * + * @param dlen Data length. + * + * @param fmt String. + * + * @param ap Variable list of string arguments. + */ +__syscall void z_log_msg2_runtime_vcreate(uint8_t domain_id, const void *source, + uint8_t level, const void *data, + size_t dlen, const char *fmt, + va_list ap); + +/** @brief Create message at runtime. + * + * Function allows to build any log message based on input data. Processing + * time is significantly higher than statically message creating. + * + * @param domain_id Domain ID. + * + * @param source Source. + * + * @param level Log level. + * + * @param data Data. + * + * @param dlen Data length. + * + * @param fmt String. + * + * @param ... String arguments. + */ +static inline void z_log_msg2_runtime_create(uint8_t domain_id, + const void *source, + uint8_t level, const void *data, + size_t dlen, const char *fmt, ...) +{ + va_list ap; + + va_start(ap, fmt); + z_log_msg2_runtime_vcreate(domain_id, source, level, + data, dlen, fmt, ap); + va_end(ap); +} + +static inline bool z_log_item_is_msg(union log_msg2_generic *msg) +{ + return msg->generic.type == Z_LOG_MSG2_LOG; +} + +/** @brief Get total length (in 32 bit words) of a log message. + * + * @param desc Log message descriptor. + * + * @return Length. + */ +static inline uint32_t log_msg2_get_total_wlen(const struct log_msg2_desc desc) +{ + return Z_LOG_MSG2_ALIGNED_WLEN(desc.package_len, desc.data_len); +} + +/** @brief Get length of the log item. + * + * @param item Item. + * + * @return Length in 32 bit words. + */ +static inline uint32_t log_msg2_generic_get_wlen(union mpsc_pbuf_generic *item) +{ + union log_msg2_generic *generic_msg = (union log_msg2_generic *)item; + + if (z_log_item_is_msg(generic_msg)) { + struct log_msg2 *msg = (struct log_msg2 *)generic_msg; + + return log_msg2_get_total_wlen(msg->hdr.desc); + } + + /* trace TODO */ + return 0; +} + +/** @brief Get log message domain ID. + * + * @param msg Log message. + * + * @return Domain ID + */ +static inline uint8_t log_msg2_get_domain(struct log_msg2 *msg) +{ + return msg->hdr.desc.domain; +} + +/** @brief Get log message level. + * + * @param msg Log message. + * + * @return Log level. + */ +static inline uint8_t log_msg2_get_level(struct log_msg2 *msg) +{ + return msg->hdr.desc.level; +} + +/** @brief Get message source data. + * + * @param msg Log message. + * + * @return Pointer to the source data. + */ +static inline const void *log_msg2_get_source(struct log_msg2 *msg) +{ + return msg->hdr.source; +} + +/** @brief Get timestamp. + * + * @param msg Log message. + * + * @return Timestamp. + */ +static inline log_timestamp_t log_msg2_get_timestamp(struct log_msg2 *msg) +{ + return msg->hdr.timestamp; +} + +/** @brief Get data buffer. + * + * @param msg log message. + * + * @param len location where data length is written. + * + * @return pointer to the data buffer. + */ +static inline uint8_t *log_msg2_get_data(struct log_msg2 *msg, size_t *len) +{ + *len = msg->hdr.desc.data_len; + + return msg->data + msg->hdr.desc.package_len; +} + +/** @brief Get string package. + * + * @param msg log message. + * + * @param len location where string package length is written. + * + * @return pointer to the package. + */ +static inline uint8_t *log_msg2_get_package(struct log_msg2 *msg, size_t *len) +{ + *len = msg->hdr.desc.package_len; + + return msg->data; +} + +/** + * @} + */ + +#include + +#ifdef __cplusplus +} +#endif + +#endif /* ZEPHYR_INCLUDE_LOGGING_LOG_MSG2_H_ */ diff --git a/subsys/logging/CMakeLists.txt b/subsys/logging/CMakeLists.txt index 5b40230f9dd..6a1103f4b46 100644 --- a/subsys/logging/CMakeLists.txt +++ b/subsys/logging/CMakeLists.txt @@ -9,6 +9,12 @@ if(NOT CONFIG_LOG_MINIMAL) log_output.c ) + zephyr_sources_ifdef( + CONFIG_LOG2 + log_msg2.c + ) + + zephyr_sources_ifdef( CONFIG_LOG_BACKEND_UART log_backend_uart.c diff --git a/subsys/logging/Kconfig b/subsys/logging/Kconfig index e1ec8896844..7f63205d7fe 100644 --- a/subsys/logging/Kconfig +++ b/subsys/logging/Kconfig @@ -14,9 +14,7 @@ rsource "Kconfig.mode" rsource "Kconfig.filtering" -if !LOG_MINIMAL - -if !LOG_FRONTEND +if !LOG_FRONTEND && !LOG_MINIMAL rsource "Kconfig.formatting" @@ -24,9 +22,8 @@ rsource "Kconfig.processing" rsource "Kconfig.backends" -endif # !LOG_FRONTEND +endif # !LOG_FRONTEND && !LOG_MINIMAL rsource "Kconfig.misc" -endif # LOG_MINIMAL endif # LOG diff --git a/subsys/logging/Kconfig.misc b/subsys/logging/Kconfig.misc index 49814942f6a..4c97e6d6f16 100644 --- a/subsys/logging/Kconfig.misc +++ b/subsys/logging/Kconfig.misc @@ -5,6 +5,7 @@ menu "Misc" config LOG_DOMAIN_ID int "Domain ID" + depends on !LOG_MINIMAL default 0 range 0 7 help @@ -13,7 +14,43 @@ config LOG_DOMAIN_ID config LOG_CMDS bool "Enable shell commands" depends on SHELL - depends on !LOG_FRONTEND + depends on !LOG_FRONTEND && !LOG_MINIMAL default y if SHELL +config LOG_TEST_CLEAR_MESSAGE_SPACE + bool "Clear message after allocation" + default y + depends on ZTEST + depends on LOG2 + help + Used in testing to simplify message comparision if message contains + paddings. + +config LOG2_USE_VLA + bool "Using variable length arrays" + default y if !MISRA_SANE + help + Using VLA slightly decreases stack usage in some cases it may not be + supported. Note that VLA are used for arrays which size is resolved at + compile time so at runtime arrays have fixed size. + +config LOG2_ALWAYS_RUNTIME + bool "Always use runtime message creation (v2)" + default y if NO_OPTIMIZATIONS + help + If enabled, runtime method is always used for message creation. Static + creation relies on compiler being able to optimize and remove code + based on information known at compile time. It is recommended to + enable this option when optimization is disabled because some compilers + (seen on arm_cortex_m and x86) were using unrealistic amount of stack + for dead code. Option applies to v1 as well because distinction + between versions is done by the compiler. + +config LOG2_FMT_SECTION + bool "Keep log strings in dedicated section" + help + When enabled, logs are kept in dedicated memory section. It allows + removing strings from final binary and should be used for dictionary + logging. + endmenu diff --git a/subsys/logging/Kconfig.mode b/subsys/logging/Kconfig.mode index afbdcfabdc8..454fe2dc1bd 100644 --- a/subsys/logging/Kconfig.mode +++ b/subsys/logging/Kconfig.mode @@ -12,6 +12,10 @@ config LOG_MODE_DEFERRED least impact on the application. Time consuming processing is deferred to the known context. +config LOG2 + bool "Deferred logging v2" + select MPSC_PBUF + config LOG_MODE_IMMEDIATE bool "Synchronous" help diff --git a/subsys/logging/Kconfig.processing b/subsys/logging/Kconfig.processing index 162e096aa25..117fb29e7be 100644 --- a/subsys/logging/Kconfig.processing +++ b/subsys/logging/Kconfig.processing @@ -138,6 +138,24 @@ config LOG_STRDUP_POOL_PROFILING endif # LOG_MODE_DEFERRED +if LOG2 + +config LOG_TRACE_SHORT_TIMESTAMP + bool "Use 24 bit timestamp for tracing" + default y + help + When enabled, shorter timestamp is used and trace message is + compressed. + +config LOG_TIMESTAMP_64BIT + bool "Use 64 bit timestamp" + +config LOG_SPEED + bool "Prefer performance over size" + help + If enabled, logging may take more code size to get faster logging. +endif # LOG2 + endif # !LOG_MINIMAL endmenu diff --git a/subsys/logging/log_core.c b/subsys/logging/log_core.c index 88dbf24e1b6..90839dbb805 100644 --- a/subsys/logging/log_core.c +++ b/subsys/logging/log_core.c @@ -9,6 +9,8 @@ #include #include #include +#include +#include #include #include #include @@ -47,6 +49,10 @@ LOG_MODULE_REGISTER(log); #define CONFIG_LOG_STRDUP_BUF_COUNT 0 #endif +#ifndef CONFIG_LOG_BLOCK_IN_THREAD_TIMEOUT_MS +#define CONFIG_LOG_BLOCK_IN_THREAD_TIMEOUT_MS 0 +#endif + struct log_strdup_buf { atomic_t refcount; char buf[CONFIG_LOG_STRDUP_MAX_STRING + 1]; /* for termination */ @@ -75,8 +81,25 @@ static uint32_t log_strdup_longest; static struct k_timer log_process_thread_timer; static uint32_t dummy_timestamp(void); -static timestamp_get_t timestamp_func = dummy_timestamp; +log_timestamp_get_t log_timestamp_func = dummy_timestamp; +struct mpsc_pbuf_buffer log_buffer; +static uint32_t __aligned(Z_LOG_MSG2_ALIGNMENT) + buf32[CONFIG_LOG_BUFFER_SIZE / sizeof(int)]; + +static void notify_drop(struct mpsc_pbuf_buffer *buffer, + union mpsc_pbuf_generic *item) +{ + /* empty for now */ +} + +static const struct mpsc_pbuf_buffer_config mpsc_config = { + .buf = (uint32_t *)buf32, + .size = ARRAY_SIZE(buf32), + .notify_drop = notify_drop, + .get_wlen = log_msg2_generic_get_wlen, + .flags = 0 +}; bool log_is_strdup(const void *buf); @@ -396,7 +419,7 @@ void log_generic(struct log_msg_ids src_level, const char *fmt, va_list ap, } else if (IS_ENABLED(CONFIG_LOG_IMMEDIATE) && (!IS_ENABLED(CONFIG_LOG_FRONTEND))) { struct log_backend const *backend; - uint32_t timestamp = timestamp_func(); + uint32_t timestamp = log_timestamp_func(); for (int i = 0; i < log_backend_count_get(); i++) { backend = log_backend_get(i); @@ -461,7 +484,7 @@ void log_hexdump_sync(struct log_msg_ids src_level, const char *metadata, src_level); } else { struct log_backend const *backend; - uint32_t timestamp = timestamp_func(); + uint32_t timestamp = log_timestamp_func(); for (int i = 0; i < log_backend_count_get(); i++) { backend = log_backend_get(i); @@ -479,7 +502,7 @@ static uint32_t k_cycle_get_32_wrapper(void) { /* * The k_cycle_get_32() is a define which cannot be referenced - * by timestamp_func. Instead, this wrapper is used. + * by log_timestamp_func. Instead, this wrapper is used. */ return k_cycle_get_32(); } @@ -499,10 +522,10 @@ void log_core_init(void) /* Set default timestamp. */ if (sys_clock_hw_cycles_per_sec() > 1000000) { - timestamp_func = k_uptime_get_32; + log_timestamp_func = k_uptime_get_32; freq = 1000U; } else { - timestamp_func = k_cycle_get_32_wrapper; + log_timestamp_func = k_cycle_get_32_wrapper; freq = sys_clock_hw_cycles_per_sec(); } @@ -580,13 +603,13 @@ void log_thread_set(k_tid_t process_tid) } } -int log_set_timestamp_func(timestamp_get_t timestamp_getter, uint32_t freq) +int log_set_timestamp_func(log_timestamp_get_t timestamp_getter, uint32_t freq) { if (timestamp_getter == NULL) { return -EINVAL; } - timestamp_func = timestamp_getter; + log_timestamp_func = timestamp_getter; log_output_timestamp_freq_set(freq); return 0; @@ -1189,6 +1212,72 @@ void log_hexdump_from_user(struct log_msg_ids src_level, const char *metadata, } #endif /* !defined(CONFIG_USERSPACE) */ +void z_log_msg2_init(void) +{ + mpsc_pbuf_init(&log_buffer, &mpsc_config); +} + +static uint32_t log_diff_timestamp(void) +{ + extern log_timestamp_get_t log_timestamp_func; + + return log_timestamp_func(); +} + +void z_log_msg2_put_trace(struct log_msg2_trace trace) +{ + union log_msg2_generic generic = { + .trace = trace + }; + + trace.hdr.timestamp = IS_ENABLED(CONFIG_LOG_TRACE_SHORT_TIMESTAMP) ? + log_diff_timestamp() : log_timestamp_func(); + mpsc_pbuf_put_word(&log_buffer, generic.buf); +} + +void z_log_msg2_put_trace_ptr(struct log_msg2_trace trace, void *data) +{ + union log_msg2_generic generic = { + .trace = trace + }; + + trace.hdr.timestamp = IS_ENABLED(CONFIG_LOG_TRACE_SHORT_TIMESTAMP) ? + log_diff_timestamp() : log_timestamp_func(); + mpsc_pbuf_put_word_ext(&log_buffer, generic.buf, data); +} + +struct log_msg2 *z_log_msg2_alloc(uint32_t wlen) +{ + return (struct log_msg2 *)mpsc_pbuf_alloc(&log_buffer, wlen, + K_MSEC(CONFIG_LOG_BLOCK_IN_THREAD_TIMEOUT_MS)); +} + +void z_log_msg2_commit(struct log_msg2 *msg) +{ + msg->hdr.timestamp = log_timestamp_func(); + mpsc_pbuf_commit(&log_buffer, (union mpsc_pbuf_generic *)msg); + + if (IS_ENABLED(CONFIG_LOG2_MODE_DEFERRED)) { + z_log_msg_post_finalize(); + } +} + +union log_msg2_generic *z_log_msg2_claim(void) +{ + return (union log_msg2_generic *)mpsc_pbuf_claim(&log_buffer); +} + +void z_log_msg2_free(union log_msg2_generic *msg) +{ + mpsc_pbuf_free(&log_buffer, (union mpsc_pbuf_generic *)msg); +} + + +bool z_log_msg2_pending(void) +{ + return mpsc_pbuf_is_pending(&log_buffer); +} + static void log_process_thread_timer_expiry_fn(struct k_timer *timer) { k_sem_give(&log_process_thread_sem); diff --git a/subsys/logging/log_msg2.c b/subsys/logging/log_msg2.c new file mode 100644 index 00000000000..ad80d983933 --- /dev/null +++ b/subsys/logging/log_msg2.c @@ -0,0 +1,101 @@ +/* + * Copyright (c) 2020 Nordic Semiconductor + * + * SPDX-License-Identifier: Apache-2.0 + */ +#include +#include +#include +#include +#include + +void z_log_msg2_finalize(struct log_msg2 *msg, const void *source, + const struct log_msg2_desc desc, const void *data) +{ + if (!msg) { + z_log_dropped(); + + return; + } + + if (data) { + uint8_t *d = msg->data + desc.package_len; + + memcpy(d, data, desc.data_len); + } + + msg->hdr.desc = desc; + msg->hdr.source = source; + z_log_msg2_commit(msg); +} + +void z_impl_z_log_msg2_static_create(const void *source, + const struct log_msg2_desc desc, + uint8_t *package, const void *data) +{ + uint32_t msg_wlen = log_msg2_get_total_wlen(desc); + struct log_msg2 *msg = z_log_msg2_alloc(msg_wlen); + + if (msg) { + memcpy(msg->data, package, desc.package_len); + } + + z_log_msg2_finalize(msg, source, desc, data); +} + +#ifdef CONFIG_USERSPACE +static inline void z_vrfy_z_log_msg2_static_create(const void *source, + const struct log_msg2_desc desc, + uint8_t *package, const void *data) +{ + return z_impl_z_log_msg2_static_create(source, desc, package, data); +} +#include +#endif + +void z_impl_z_log_msg2_runtime_vcreate(uint8_t domain_id, const void *source, + uint8_t level, const void *data, size_t dlen, + const char *fmt, va_list ap) +{ + int plen; + va_list ap2; + + if (fmt) { + va_copy(ap2, ap); + plen = cbvprintf_package(NULL, Z_LOG_MSG2_ALIGN_OFFSET, + fmt, ap2); + __ASSERT_NO_MSG(plen >= 0); + } else { + plen = 0; + } + + size_t msg_wlen = Z_LOG_MSG2_ALIGNED_WLEN(plen, dlen); + struct log_msg2 *msg; + struct log_msg2_desc desc = + Z_LOG_MSG_DESC_INITIALIZER(domain_id, level, plen, dlen); + + if (IS_ENABLED(CONFIG_LOG2_MODE_IMMEDIATE)) { + msg = alloca(msg_wlen * sizeof(int)); + } else { + msg = z_log_msg2_alloc(msg_wlen); + } + + if (msg && fmt) { + plen = cbvprintf_package(msg->data, plen, fmt, ap); + __ASSERT_NO_MSG(plen >= 0); + } + + z_log_msg2_finalize(msg, source, desc, data); +} + +#ifdef CONFIG_USERSPACE +static inline void z_vrfy_z_log_msg2_runtime_vcreate(uint8_t domain_id, + const void *source, + uint8_t level, const void *data, size_t dlen, + const char *fmt, va_list ap) +{ + return z_impl_z_log_msg2_runtime_vcreate(domain_id, source, level, data, + dlen, fmt, ap); +} +#include +#endif diff --git a/tests/subsys/logging/log_msg/src/log_msg_test.c b/tests/subsys/logging/log_msg/src/log_msg_test.c index fe98a84fbda..8971dbc1b30 100644 --- a/tests/subsys/logging/log_msg/src/log_msg_test.c +++ b/tests/subsys/logging/log_msg/src/log_msg_test.c @@ -458,7 +458,6 @@ void test_log_hexdump_data_put_chunks(void) log_msg_put(msg); } - /*test case main entry*/ void test_main(void) { @@ -468,6 +467,7 @@ void test_main(void) ztest_unit_test(test_log_hexdump_data_get_single_chunk), ztest_unit_test(test_log_hexdump_data_get_two_chunks), ztest_unit_test(test_log_hexdump_data_get_multiple_chunks), - ztest_unit_test(test_log_hexdump_data_put_chunks)); + ztest_unit_test(test_log_hexdump_data_put_chunks) + ); ztest_run_test_suite(test_log_message); }