michaelh/zephyr
1
0
Fork 0
Code Releases Activity

logging: frontends: stmesp: Add optimized short logs

Browse source 
Add 'turbo' logging feature. When enabled, short logs (no argument
or one numeric, 32 bit argument) are handled in a special way that
is much faster than the default one (5-10x faster). Additionally,
there is an option to remove all other logs from the system which
allows to not include almost any logging framework code in the
binary (~170 bytes of code is needed). It may be especially
valueable for memory constraint targets (ppr, flpr) where with
only 170 byte of code (+code for each log message) we can provide
limited formatted string logging support.

'Turbo' logging is using following to achieve that:
- logging strings are put into a memory section and additional
memory section is created which holds addresses of those strings.
Index in that array is used to identify a string (32 bit address
is encoded into a smaller number, 15 bits is more than enough).
This index is used for a STMESP register set (there are 2^16
available). So STMESP channel encodes string.
- Logging level is stringified and prepended to a string
- Source ID is encoded by using DM16 (so far not used).
- Log without arguments is written as DMTS16
- Log with one argumetn is written as DM16+DMTS32

Signed-off-by: Krzysztof Chruściński <krzysztof.chruscinski@nordicsemi.no>
This commit is contained in:
Krzysztof Chruściński 2024-10-07 09:24:30 +02:00 • committed by Benjamin Cabé
commit 752f8b0176
5 changed files with 280 additions and 3 deletions
Download patch file Download diff file Expand all files Collapse all files

14
include/zephyr/linker/common-rom/common-rom-logging.ld
View file

@ -7,8 +7,22 @@
{ {
Z_LINK_ITERABLE(log_strings); Z_LINK_ITERABLE(log_strings);
} GROUP_ROM_LINK_IN(DEVNULL_REGION, DEVNULL_REGION) } GROUP_ROM_LINK_IN(DEVNULL_REGION, DEVNULL_REGION)
SECTION_PROLOGUE(log_stmesp_ptr,(COPY),SUBALIGN(Z_LINK_ITERABLE_SUBALIGN))
{
Z_LINK_ITERABLE(log_stmesp_ptr);
} GROUP_ROM_LINK_IN(DEVNULL_REGION, DEVNULL_REGION)
SECTION_PROLOGUE(log_stmesp_str,(COPY),SUBALIGN(Z_LINK_ITERABLE_SUBALIGN))
{
Z_LINK_ITERABLE(log_stmesp_str);
} GROUP_ROM_LINK_IN(DEVNULL_REGION, DEVNULL_REGION)
#else #else
ITERABLE_SECTION_ROM(log_strings, Z_LINK_ITERABLE_SUBALIGN) ITERABLE_SECTION_ROM(log_strings, Z_LINK_ITERABLE_SUBALIGN)
ITERABLE_SECTION_ROM(log_stmesp_ptr, Z_LINK_ITERABLE_SUBALIGN)
ITERABLE_SECTION_ROM(log_stmesp_str, Z_LINK_ITERABLE_SUBALIGN)
#endif #endif
ITERABLE_SECTION_ROM(log_const, Z_LINK_ITERABLE_SUBALIGN) ITERABLE_SECTION_ROM(log_const, Z_LINK_ITERABLE_SUBALIGN)

55
include/zephyr/logging/log_frontend_stmesp.h
View file

@ -44,7 +44,7 @@ void log_frontend_stmesp_dummy_write(void);
/** @brief Trace point /** @brief Trace point
* *
* Write a trace point information using STM. Number of unique trace points is limited * Write a trace point information using STM. Number of unique trace points is limited
* to 65536 - CONFIG_LOG_FRONTEND_STMESP_TP_CHAN_BASE per core. * to 32768 - CONFIG_LOG_FRONTEND_STMESP_TP_CHAN_BASE per core.
* *
* @param x Trace point ID. * @param x Trace point ID.
*/ */
@ -65,7 +65,7 @@ static inline void log_frontend_stmesp_tp(uint16_t x)
/** @brief Trace point with 32 bit data. /** @brief Trace point with 32 bit data.
* *
* Write a trace point information using STM. Number of unique trace points is limited * Write a trace point information using STM. Number of unique trace points is limited
* to 65536 - CONFIG_LOG_FRONTEND_STMESP_TP_CHAN_BASE per core. * to 32768 - CONFIG_LOG_FRONTEND_STMESP_TP_CHAN_BASE per core.
* *
* @param x Trace point ID. * @param x Trace point ID.
* @param d Data. 32 bit word. * @param d Data. 32 bit word.
@ -84,6 +84,57 @@ static inline void log_frontend_stmesp_tp_d32(uint16_t x, uint32_t d)
#endif #endif
} }
/** @brief Function called for log message with no arguments when turbo logging is enabled.
*
* @param source Pointer to the source structure.
* @param x Index of the string used for the log message.
*/
void log_frontend_stmesp_log0(const void *source, uint32_t x);
/** @brief Function called for log message with one argument when turbo logging is enabled.
*
* @param source Pointer to the source structure.
* @param x Index of the string used for the log message.
* @param arg Argument.
*/
void log_frontend_stmesp_log1(const void *source, uint32_t x, uint32_t arg);
TYPE_SECTION_START_EXTERN(const char *, log_stmesp_ptr);
/** @brief Macro for handling a turbo log message with no arguments.
*
* @param _source Pointer to the source structure.
* @param ... String.
*/
#define LOG_FRONTEND_STMESP_LOG0(_source, ...) \
do { \
static const char _str[] __in_section(_log_stmesp_str, static, _) \
__used __noasan __aligned(sizeof(uint32_t)) = GET_ARG_N(1, __VA_ARGS__); \
static const char *_str_ptr __in_section(_log_stmesp_ptr, static, _) \
__used __noasan = _str; \
uint32_t idx = \
((uintptr_t)&_str_ptr - (uintptr_t)TYPE_SECTION_START(log_stmesp_ptr)) / \
sizeof(void *); \
log_frontend_stmesp_log0(_source, idx); \
} while (0)
/** @brief Macro for handling a turbo log message with one argument.
*
* @param _source Pointer to the source structure.
* @param ... String with one numeric argument.
*/
#define LOG_FRONTEND_STMESP_LOG1(_source, ...) \
do { \
static const char _str[] __in_section(_log_stmesp_str, static, _) \
__used __noasan __aligned(sizeof(uint32_t)) = GET_ARG_N(1, __VA_ARGS__); \
static const char *_str_ptr __in_section(_log_stmesp_ptr, static, _) \
__used __noasan = _str; \
uint32_t idx = \
((uintptr_t)&_str_ptr - (uintptr_t)TYPE_SECTION_START(log_stmesp_ptr)) / \
sizeof(void *); \
log_frontend_stmesp_log1(_source, idx, (uintptr_t)GET_ARG_N(2, __VA_ARGS__)); \
} while (0)
#ifdef __cplusplus #ifdef __cplusplus
} }
#endif #endif

150
soc/nordic/common/zephyr_custom_log.h Normal file
View file

@ -0,0 +1,150 @@
/*
* Copyright (c) 2024 Nordic Semiconductor ASA
* SPDX-License-Identifier: Apache-2.0
*/
/**
* @file
* Custom logging
*/
#ifndef SOC_NORDIC_COMMON_ZEPHYR_CUSTOM_LOG_H_
#define SOC_NORDIC_COMMON_ZEPHYR_CUSTOM_LOG_H_
#include <zephyr/logging/log_frontend_stmesp.h>
#include <zephyr/sys/cbprintf_internal.h>
#ifdef __cplusplus
extern "C" {
#endif
/* Undef to override those macros. */
#undef LOG_ERR
#undef LOG_WRN
#undef LOG_INF
#undef LOG_DBG
#undef LOG_INST_ERR
#undef LOG_INST_WRN
#undef LOG_INST_INF
#undef LOG_INST_DBG
/** @brief Optimized macro for log message with no arguments.
*
* In order to compress information, logging level is stringified and prepended
* to the string.
*
* @param _level Level.
* @param _module_const_source Constant module structure.
* @param _source Source structure (dynamic or constant).
* @param ... String (with no arguments).
*/
#define Z_LOG_STMESP_0(_level, _source, ...) \
do { \
if (!Z_LOG_LEVEL_ALL_CHECK(_level, __log_current_const_data, _source)) { \
break; \
} \
LOG_FRONTEND_STMESP_LOG0(_source, STRINGIFY(_level) __VA_ARGS__); \
} while (0)
/** @brief Determine if first argument is a numeric value that fits in 32 bit word.
*
* @return 1 if yes and 0 if not.
*/
#define Z_LOG_STMESP_1_ARG_CHECK(...) \
COND_CODE_1(NUM_VA_ARGS_LESS_1(__VA_ARGS__), \
(Z_CBPRINTF_IS_WORD_NUM(GET_ARG_N(2, __VA_ARGS__, dummy))), (0))
/** @brief Optimized macro for log message with 1 numeric argument.
*
* In order to compress information, logging level is stringified and prepended
* to the string.
*
* @param _level Level.
* @param _module_const_source Constant module structure.
* @param _source Source structure (dynamic or constant).
* @param ... String (with 1 argument).
*/
#define Z_LOG_STMESP_1(_level, _source, ...) \
do { \
/* Do turbo logging only if argument fits in 32 bit word. */ \
if (!Z_LOG_STMESP_1_ARG_CHECK(__VA_ARGS__)) { \
COND_CODE_1(CONFIG_LOG_FRONTEND_STMESP_TURBO_DROP_OTHERS, (), \
(Z_LOG(_level, __VA_ARGS__))); \
} \
if (!Z_LOG_LEVEL_ALL_CHECK(_level, __log_current_const_data, _source)) { \
break; \
} \
LOG_FRONTEND_STMESP_LOG1(_source, STRINGIFY(_level) __VA_ARGS__, dummy); \
} while (0)
/** @brief Top level logging macro.
*
* Macro is using special approach for short log message (0 or 1 numeric argument)
* and proceeds with standard approach (or optionally drops) for remaining messages.
*
* @param _level Severity level.
* @param _source Pointer to a structure associated with the source.
* @param ... String with arguments.
*/
#define Z_LOG_STMESP(_level, _source, ...) \
COND_CODE_0(NUM_VA_ARGS_LESS_1(__VA_ARGS__), \
(Z_LOG_STMESP_0(_level, _source, __VA_ARGS__)), ( \
COND_CODE_1(NUM_VA_ARGS_LESS_1(__VA_ARGS__), \
(Z_LOG_STMESP_1(_level, _source, __VA_ARGS__)), \
( \
if (!IS_ENABLED(CONFIG_LOG_FRONTEND_STMESP_TURBO_DROP_OTHERS)) { \
Z_LOG(_level, __VA_ARGS__); \
}))))
/* Overridden logging API macros. */
#define LOG_ERR(...) Z_LOG_STMESP(LOG_LEVEL_ERR, Z_LOG_CURRENT_DATA(), __VA_ARGS__)
#define LOG_WRN(...) Z_LOG_STMESP(LOG_LEVEL_WRN, Z_LOG_CURRENT_DATA(), __VA_ARGS__)
#define LOG_INF(...) Z_LOG_STMESP(LOG_LEVEL_INF, Z_LOG_CURRENT_DATA(), __VA_ARGS__)
#define LOG_DBG(...) Z_LOG_STMESP(LOG_LEVEL_DBG, Z_LOG_CURRENT_DATA(), __VA_ARGS__)
#define LOG_INST_ERR(_inst, ...) Z_LOG_STMESP(LOG_LEVEL_ERR, Z_LOG_INST(_inst), __VA_ARGS__)
#define LOG_INST_WRN(_inst, ...) Z_LOG_STMESP(LOG_LEVEL_WRN, Z_LOG_INST(_inst), __VA_ARGS__)
#define LOG_INST_INF(_inst, ...) Z_LOG_STMESP(LOG_LEVEL_INF, Z_LOG_INST(_inst), __VA_ARGS__)
#define LOG_INST_DBG(_inst, ...) Z_LOG_STMESP(LOG_LEVEL_DBG, Z_LOG_INST(_inst), __VA_ARGS__)
#if CONFIG_LOG_FRONTEND_STMESP_TURBO_DROP_OTHERS
#undef LOG_RAW
#undef LOG_PRINTK
#undef LOG_HEXDUMP_ERR
#undef LOG_HEXDUMP_WRN
#undef LOG_HEXDUMP_INF
#undef LOG_HEXDUMP_DBG
#undef LOG_INST_HEXDUMP_ERR
#undef LOG_INST_HEXDUMP_WRN
#undef LOG_INST_HEXDUMP_INF
#undef LOG_INST_HEXDUMP_DBG
#define LOG_RAW(...) \
do { \
if (0) { \
Z_LOG_PRINTK(1, __VA_ARGS__); \
} \
} while (0)
#define LOG_PRINTK(...) \
do { \
if (0) { \
Z_LOG_PRINTK(1, __VA_ARGS__); \
} \
} while (0)
#define LOG_HEXDUMP_ERR(_data, _length, _str) (void)_data
#define LOG_HEXDUMP_WRN(_data, _length, _str) (void)_data
#define LOG_HEXDUMP_INF(_data, _length, _str) (void)_data
#define LOG_HEXDUMP_DBG(_data, _length, _str) (void)_data
#define LOG_INST_HEXDUMP_ERR(_inst, _data, _length, _str) (void)_data
#define LOG_INST_HEXDUMP_WRN(_inst, _data, _length, _str) (void)_data
#define LOG_INST_HEXDUMP_INF(_inst, _data, _length, _str) (void)_data
#define LOG_INST_HEXDUMP_DBG(_inst, _data, _length, _str) (void)_data
#endif
#ifdef __cplusplus
}
#endif
#endif /* SOC_NORDIC_COMMON_ZEPHYR_CUSTOM_LOG_H_ */

22
subsys/logging/frontends/Kconfig
View file

@ -67,6 +67,28 @@ config LOG_FRONTEND_STMESP_EARLY_BUF_SIZE
config LOG_FRONTEND_STMESP_DICT_VER config LOG_FRONTEND_STMESP_DICT_VER
def_int 0 def_int 0
config LOG_FRONTEND_STMESP_TURBO_LOG
bool "Optimize short_logs"
select LOG_CUSTOM_HEADER
default y if (NRF_ETR || SOC_NRF54H20_CPUPPR || SOC_NRF54H20_CPUFLPR) \
&& LOG_FRONTEND_STMESP_FSC
help
When enabled, then logging messages with 0 and 1 numeric argument are
optimized and handled much faster than others.
config LOG_FRONTEND_STMESP_TURBO_DROP_OTHERS
bool "Drop all logs except turbo logs"
help
Option can be enabled for memory constraint cases to remove all logging
related code except turbo logs.
config LOG_FRONTEND_STMESP_TURBO_LOG_BASE
def_int 32768
config LOG_FRONTEND_STPESP_TURBO_SOURCE_PORT_ID
def_int 65535
depends on LOG_FRONTEND_STMESP_TURBO_LOG
config LOG_FRONTEND_STMESP_GUARANTEED_ACCESS config LOG_FRONTEND_STMESP_GUARANTEED_ACCESS
bool "Use STMESP guaranteed access" bool "Use STMESP guaranteed access"
help help

42
subsys/logging/frontends/log_frontend_stmesp.c
View file

@ -581,7 +581,19 @@ void log_frontend_panic(void)
void log_frontend_init(void) void log_frontend_init(void)
{ {
/* empty */ #if defined(CONFIG_LOG_FRONTEND_STPESP_TURBO_SOURCE_PORT_ID) && !defined(CONFIG_NRF_ETR)
/* Send location of section with constant source data. It is used by the
* application core to retrieve source names of log messages coming from
* coprocessors (FLPR and PPR).
*/
TYPE_SECTION_START_EXTERN(struct log_source_const_data, log_const);
STMESP_Type *stm_esp;
uintptr_t log_const_start;
(void)stmesp_get_port(CONFIG_LOG_FRONTEND_STPESP_TURBO_SOURCE_PORT_ID, &stm_esp);
log_const_start = (uintptr_t)TYPE_SECTION_START(log_const);
STM_D32(stm_esp, log_const_start, false, true);
#endif
} }
void log_frontend_stmesp_dummy_write(void) void log_frontend_stmesp_dummy_write(void)
@ -646,3 +658,31 @@ int log_frontend_stmesp_etr_ready(void)
return 0; return 0;
} }
#endif /* EARLY_BUF_SIZE > 0 */ #endif /* EARLY_BUF_SIZE > 0 */
void log_frontend_stmesp_log0(const void *source, uint32_t x)
{
STMESP_Type *port;
int err = stmesp_get_port((uint32_t)x + 0x8000, &port);
uint16_t source_id = log_source_id(source);
__ASSERT_NO_MSG(err == 0);
if (err == 0) {
stmesp_data16(port, source_id, true, true,
IS_ENABLED(CONFIG_LOG_FRONTEND_STMESP_GUARANTEED_ACCESS));
}
}
void log_frontend_stmesp_log1(const void *source, uint32_t x, uint32_t arg)
{
STMESP_Type *port;
int err = stmesp_get_port((uint32_t)x + 0x8000, &port);
uint16_t source_id = log_source_id(source);
__ASSERT_NO_MSG(err == 0);
if (err == 0) {
stmesp_data16(port, source_id, false, true,
IS_ENABLED(CONFIG_LOG_FRONTEND_STMESP_GUARANTEED_ACCESS));
stmesp_data32(port, arg, true, true,
IS_ENABLED(CONFIG_LOG_FRONTEND_STMESP_GUARANTEED_ACCESS));
}
}