michaelh/zephyr
1
0
Fork 0
Code Releases Activity

logging: Add logging v2 implementation for log_msg

Browse source 
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 <krzysztof.chruscinski@nordicsemi.no>
This commit is contained in:
Krzysztof Chruscinski 2020-11-19 17:25:03 +01:00 • committed by Anas Nashif
commit f6a40ae183
14 changed files with 1008 additions and 20 deletions
Download patch file Download diff file Expand all files Collapse all files

7
include/linker/common-rom.ld
View file

@ -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 = .;

2
include/logging/log_core.h
View file

@ -7,6 +7,7 @@
#define ZEPHYR_INCLUDE_LOGGING_LOG_CORE_H_
#include <logging/log_msg.h>
#include <logging/log_core2.h>
#include <logging/log_instance.h>
#include <stdbool.h>
#include <stdint.h>
@ -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.

72
include/logging/log_core2.h Normal file
View file

@ -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 <logging/log_msg2.h>
#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_ */

9
include/logging/log_ctrl.h
View file

@ -6,14 +6,14 @@
#ifndef ZEPHYR_INCLUDE_LOGGING_LOG_CTRL_H_
#define ZEPHYR_INCLUDE_LOGGING_LOG_CTRL_H_
#include <logging/log_backend.h>
#include <kernel.h>
#include <logging/log_backend.h>
#include <logging/log_msg.h>
#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.

1
include/logging/log_msg.h
View file

@ -9,6 +9,7 @@
#include <sys/atomic.h>
#include <sys/util.h>
#include <string.h>
#include <logging/log_msg2.h>
#ifdef __cplusplus
extern "C" {

653
include/logging/log_msg2.h Normal file
View file

@ -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 <logging/log_instance.h>
#include <sys/mpsc_packet.h>
#include <sys/cbprintf.h>
#include <sys/atomic.h>
#include <sys/util.h>
#include <string.h>
#ifdef __GNUC__
#ifndef alloca
#define alloca __builtin_alloca
#endif
#else
#include <alloca.h>
#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 <syscalls/log_msg2.h>
#ifdef __cplusplus
}
#endif
#endif /* ZEPHYR_INCLUDE_LOGGING_LOG_MSG2_H_ */

6
subsys/logging/CMakeLists.txt
View file

@ -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

7
subsys/logging/Kconfig
View file

@ -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

39
subsys/logging/Kconfig.misc
View file

@ -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

4
subsys/logging/Kconfig.mode
View file

@ -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

18
subsys/logging/Kconfig.processing
View file

@ -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

105
subsys/logging/log_core.c
View file

@ -9,6 +9,8 @@
#include <logging/log_backend.h>
#include <logging/log_ctrl.h>
#include <logging/log_output.h>
#include <logging/log_core2.h>
#include <sys/mpsc_pbuf.h>
#include <sys/printk.h>
#include <init.h>
#include <sys/__assert.h>
@ -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);

101
subsys/logging/log_msg2.c Normal file
View file

@ -0,0 +1,101 @@
/*
* Copyright (c) 2020 Nordic Semiconductor
*
* SPDX-License-Identifier: Apache-2.0
*/
#include <zephyr.h>
#include <syscall_handler.h>
#include <logging/log_msg2.h>
#include <logging/log_core.h>
#include <logging/log_ctrl.h>
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 <syscalls/z_log_msg2_static_create_mrsh.c>
#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 <syscalls/z_log_msg2_runtime_vcreate_mrsh.c>
#endif

4
tests/subsys/logging/log_msg/src/log_msg_test.c
View file

@ -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);
}