Skip to content

Commit 752f8b0

Browse files
nordic-krchkartben
nordic-krch
authored and
kartben
committed
logging: frontends: stmesp: Add optimized short logs
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 <[email protected]>
1 parent 3f47398 commit 752f8b0

File tree

5 files changed

+280
-3
lines changed

5 files changed

+280
-3
lines changed

‎include/zephyr/linker/common-rom/common-rom-logging.ld‎

Lines changed: 14 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -7,8 +7,22 @@
77
{
88
Z_LINK_ITERABLE(log_strings);
99
} GROUP_ROM_LINK_IN(DEVNULL_REGION, DEVNULL_REGION)
10+
11+
SECTION_PROLOGUE(log_stmesp_ptr,(COPY),SUBALIGN(Z_LINK_ITERABLE_SUBALIGN))
12+
{
13+
Z_LINK_ITERABLE(log_stmesp_ptr);
14+
} GROUP_ROM_LINK_IN(DEVNULL_REGION, DEVNULL_REGION)
15+
16+
SECTION_PROLOGUE(log_stmesp_str,(COPY),SUBALIGN(Z_LINK_ITERABLE_SUBALIGN))
17+
{
18+
Z_LINK_ITERABLE(log_stmesp_str);
19+
} GROUP_ROM_LINK_IN(DEVNULL_REGION, DEVNULL_REGION)
1020
#else
1121
ITERABLE_SECTION_ROM(log_strings, Z_LINK_ITERABLE_SUBALIGN)
22+
23+
ITERABLE_SECTION_ROM(log_stmesp_ptr, Z_LINK_ITERABLE_SUBALIGN)
24+
25+
ITERABLE_SECTION_ROM(log_stmesp_str, Z_LINK_ITERABLE_SUBALIGN)
1226
#endif
1327

1428
ITERABLE_SECTION_ROM(log_const, Z_LINK_ITERABLE_SUBALIGN)

‎include/zephyr/logging/log_frontend_stmesp.h‎

Lines changed: 53 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -44,7 +44,7 @@ void log_frontend_stmesp_dummy_write(void);
4444
/** @brief Trace point
4545
*
4646
* Write a trace point information using STM. Number of unique trace points is limited
47-
* to 65536 - CONFIG_LOG_FRONTEND_STMESP_TP_CHAN_BASE per core.
47+
* to 32768 - CONFIG_LOG_FRONTEND_STMESP_TP_CHAN_BASE per core.
4848
*
4949
* @param x Trace point ID.
5050
*/
@@ -65,7 +65,7 @@ static inline void log_frontend_stmesp_tp(uint16_t x)
6565
/** @brief Trace point with 32 bit data.
6666
*
6767
* Write a trace point information using STM. Number of unique trace points is limited
68-
* to 65536 - CONFIG_LOG_FRONTEND_STMESP_TP_CHAN_BASE per core.
68+
* to 32768 - CONFIG_LOG_FRONTEND_STMESP_TP_CHAN_BASE per core.
6969
*
7070
* @param x Trace point ID.
7171
* @param d Data. 32 bit word.
@@ -84,6 +84,57 @@ static inline void log_frontend_stmesp_tp_d32(uint16_t x, uint32_t d)
8484
#endif
8585
}
8686

87+
/** @brief Function called for log message with no arguments when turbo logging is enabled.
88+
*
89+
* @param source Pointer to the source structure.
90+
* @param x Index of the string used for the log message.
91+
*/
92+
void log_frontend_stmesp_log0(const void *source, uint32_t x);
93+
94+
/** @brief Function called for log message with one argument when turbo logging is enabled.
95+
*
96+
* @param source Pointer to the source structure.
97+
* @param x Index of the string used for the log message.
98+
* @param arg Argument.
99+
*/
100+
void log_frontend_stmesp_log1(const void *source, uint32_t x, uint32_t arg);
101+
102+
TYPE_SECTION_START_EXTERN(const char *, log_stmesp_ptr);
103+
104+
/** @brief Macro for handling a turbo log message with no arguments.
105+
*
106+
* @param _source Pointer to the source structure.
107+
* @param ... String.
108+
*/
109+
#define LOG_FRONTEND_STMESP_LOG0(_source, ...) \
110+
do { \
111+
static const char _str[] __in_section(_log_stmesp_str, static, _) \
112+
__used __noasan __aligned(sizeof(uint32_t)) = GET_ARG_N(1, __VA_ARGS__); \
113+
static const char *_str_ptr __in_section(_log_stmesp_ptr, static, _) \
114+
__used __noasan = _str; \
115+
uint32_t idx = \
116+
((uintptr_t)&_str_ptr - (uintptr_t)TYPE_SECTION_START(log_stmesp_ptr)) / \
117+
sizeof(void *); \
118+
log_frontend_stmesp_log0(_source, idx); \
119+
} while (0)
120+
121+
/** @brief Macro for handling a turbo log message with one argument.
122+
*
123+
* @param _source Pointer to the source structure.
124+
* @param ... String with one numeric argument.
125+
*/
126+
#define LOG_FRONTEND_STMESP_LOG1(_source, ...) \
127+
do { \
128+
static const char _str[] __in_section(_log_stmesp_str, static, _) \
129+
__used __noasan __aligned(sizeof(uint32_t)) = GET_ARG_N(1, __VA_ARGS__); \
130+
static const char *_str_ptr __in_section(_log_stmesp_ptr, static, _) \
131+
__used __noasan = _str; \
132+
uint32_t idx = \
133+
((uintptr_t)&_str_ptr - (uintptr_t)TYPE_SECTION_START(log_stmesp_ptr)) / \
134+
sizeof(void *); \
135+
log_frontend_stmesp_log1(_source, idx, (uintptr_t)GET_ARG_N(2, __VA_ARGS__)); \
136+
} while (0)
137+
87138
#ifdef __cplusplus
88139
}
89140
#endif

‎soc/nordic/common/zephyr_custom_log.h‎

Lines changed: 150 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,150 @@
1+
/*
2+
* Copyright (c) 2024 Nordic Semiconductor ASA
3+
* SPDX-License-Identifier: Apache-2.0
4+
*/
5+
6+
/**
7+
* @file
8+
* Custom logging
9+
*/
10+
11+
#ifndef SOC_NORDIC_COMMON_ZEPHYR_CUSTOM_LOG_H_
12+
#define SOC_NORDIC_COMMON_ZEPHYR_CUSTOM_LOG_H_
13+
14+
#include <zephyr/logging/log_frontend_stmesp.h>
15+
#include <zephyr/sys/cbprintf_internal.h>
16+
17+
#ifdef __cplusplus
18+
extern "C" {
19+
#endif
20+
21+
/* Undef to override those macros. */
22+
#undef LOG_ERR
23+
#undef LOG_WRN
24+
#undef LOG_INF
25+
#undef LOG_DBG
26+
#undef LOG_INST_ERR
27+
#undef LOG_INST_WRN
28+
#undef LOG_INST_INF
29+
#undef LOG_INST_DBG
30+
31+
/** @brief Optimized macro for log message with no arguments.
32+
*
33+
* In order to compress information, logging level is stringified and prepended
34+
* to the string.
35+
*
36+
* @param _level Level.
37+
* @param _module_const_source Constant module structure.
38+
* @param _source Source structure (dynamic or constant).
39+
* @param ... String (with no arguments).
40+
*/
41+
#define Z_LOG_STMESP_0(_level, _source, ...) \
42+
do { \
43+
if (!Z_LOG_LEVEL_ALL_CHECK(_level, __log_current_const_data, _source)) { \
44+
break; \
45+
} \
46+
LOG_FRONTEND_STMESP_LOG0(_source, STRINGIFY(_level) __VA_ARGS__); \
47+
} while (0)
48+
49+
/** @brief Determine if first argument is a numeric value that fits in 32 bit word.
50+
*
51+
* @return 1 if yes and 0 if not.
52+
*/
53+
#define Z_LOG_STMESP_1_ARG_CHECK(...) \
54+
COND_CODE_1(NUM_VA_ARGS_LESS_1(__VA_ARGS__), \
55+
(Z_CBPRINTF_IS_WORD_NUM(GET_ARG_N(2, __VA_ARGS__, dummy))), (0))
56+
57+
/** @brief Optimized macro for log message with 1 numeric argument.
58+
*
59+
* In order to compress information, logging level is stringified and prepended
60+
* to the string.
61+
*
62+
* @param _level Level.
63+
* @param _module_const_source Constant module structure.
64+
* @param _source Source structure (dynamic or constant).
65+
* @param ... String (with 1 argument).
66+
*/
67+
#define Z_LOG_STMESP_1(_level, _source, ...) \
68+
do { \
69+
/* Do turbo logging only if argument fits in 32 bit word. */ \
70+
if (!Z_LOG_STMESP_1_ARG_CHECK(__VA_ARGS__)) { \
71+
COND_CODE_1(CONFIG_LOG_FRONTEND_STMESP_TURBO_DROP_OTHERS, (), \
72+
(Z_LOG(_level, __VA_ARGS__))); \
73+
} \
74+
if (!Z_LOG_LEVEL_ALL_CHECK(_level, __log_current_const_data, _source)) { \
75+
break; \
76+
} \
77+
LOG_FRONTEND_STMESP_LOG1(_source, STRINGIFY(_level) __VA_ARGS__, dummy); \
78+
} while (0)
79+
80+
/** @brief Top level logging macro.
81+
*
82+
* Macro is using special approach for short log message (0 or 1 numeric argument)
83+
* and proceeds with standard approach (or optionally drops) for remaining messages.
84+
*
85+
* @param _level Severity level.
86+
* @param _source Pointer to a structure associated with the source.
87+
* @param ... String with arguments.
88+
*/
89+
#define Z_LOG_STMESP(_level, _source, ...) \
90+
COND_CODE_0(NUM_VA_ARGS_LESS_1(__VA_ARGS__), \
91+
(Z_LOG_STMESP_0(_level, _source, __VA_ARGS__)), ( \
92+
COND_CODE_1(NUM_VA_ARGS_LESS_1(__VA_ARGS__), \
93+
(Z_LOG_STMESP_1(_level, _source, __VA_ARGS__)), \
94+
( \
95+
if (!IS_ENABLED(CONFIG_LOG_FRONTEND_STMESP_TURBO_DROP_OTHERS)) { \
96+
Z_LOG(_level, __VA_ARGS__); \
97+
}))))
98+
99+
/* Overridden logging API macros. */
100+
#define LOG_ERR(...) Z_LOG_STMESP(LOG_LEVEL_ERR, Z_LOG_CURRENT_DATA(), __VA_ARGS__)
101+
#define LOG_WRN(...) Z_LOG_STMESP(LOG_LEVEL_WRN, Z_LOG_CURRENT_DATA(), __VA_ARGS__)
102+
#define LOG_INF(...) Z_LOG_STMESP(LOG_LEVEL_INF, Z_LOG_CURRENT_DATA(), __VA_ARGS__)
103+
#define LOG_DBG(...) Z_LOG_STMESP(LOG_LEVEL_DBG, Z_LOG_CURRENT_DATA(), __VA_ARGS__)
104+
105+
#define LOG_INST_ERR(_inst, ...) Z_LOG_STMESP(LOG_LEVEL_ERR, Z_LOG_INST(_inst), __VA_ARGS__)
106+
#define LOG_INST_WRN(_inst, ...) Z_LOG_STMESP(LOG_LEVEL_WRN, Z_LOG_INST(_inst), __VA_ARGS__)
107+
#define LOG_INST_INF(_inst, ...) Z_LOG_STMESP(LOG_LEVEL_INF, Z_LOG_INST(_inst), __VA_ARGS__)
108+
#define LOG_INST_DBG(_inst, ...) Z_LOG_STMESP(LOG_LEVEL_DBG, Z_LOG_INST(_inst), __VA_ARGS__)
109+
110+
#if CONFIG_LOG_FRONTEND_STMESP_TURBO_DROP_OTHERS
111+
#undef LOG_RAW
112+
#undef LOG_PRINTK
113+
#undef LOG_HEXDUMP_ERR
114+
#undef LOG_HEXDUMP_WRN
115+
#undef LOG_HEXDUMP_INF
116+
#undef LOG_HEXDUMP_DBG
117+
#undef LOG_INST_HEXDUMP_ERR
118+
#undef LOG_INST_HEXDUMP_WRN
119+
#undef LOG_INST_HEXDUMP_INF
120+
#undef LOG_INST_HEXDUMP_DBG
121+
122+
#define LOG_RAW(...) \
123+
do { \
124+
if (0) { \
125+
Z_LOG_PRINTK(1, __VA_ARGS__); \
126+
} \
127+
} while (0)
128+
129+
#define LOG_PRINTK(...) \
130+
do { \
131+
if (0) { \
132+
Z_LOG_PRINTK(1, __VA_ARGS__); \
133+
} \
134+
} while (0)
135+
136+
#define LOG_HEXDUMP_ERR(_data, _length, _str) (void)_data
137+
#define LOG_HEXDUMP_WRN(_data, _length, _str) (void)_data
138+
#define LOG_HEXDUMP_INF(_data, _length, _str) (void)_data
139+
#define LOG_HEXDUMP_DBG(_data, _length, _str) (void)_data
140+
#define LOG_INST_HEXDUMP_ERR(_inst, _data, _length, _str) (void)_data
141+
#define LOG_INST_HEXDUMP_WRN(_inst, _data, _length, _str) (void)_data
142+
#define LOG_INST_HEXDUMP_INF(_inst, _data, _length, _str) (void)_data
143+
#define LOG_INST_HEXDUMP_DBG(_inst, _data, _length, _str) (void)_data
144+
#endif
145+
146+
#ifdef __cplusplus
147+
}
148+
#endif
149+
150+
#endif /* SOC_NORDIC_COMMON_ZEPHYR_CUSTOM_LOG_H_ */

‎subsys/logging/frontends/Kconfig‎

Lines changed: 22 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -67,6 +67,28 @@ config LOG_FRONTEND_STMESP_EARLY_BUF_SIZE
6767
config LOG_FRONTEND_STMESP_DICT_VER
6868
def_int 0
6969

70+
config LOG_FRONTEND_STMESP_TURBO_LOG
71+
bool "Optimize short_logs"
72+
select LOG_CUSTOM_HEADER
73+
default y if (NRF_ETR || SOC_NRF54H20_CPUPPR || SOC_NRF54H20_CPUFLPR) \
74+
&& LOG_FRONTEND_STMESP_FSC
75+
help
76+
When enabled, then logging messages with 0 and 1 numeric argument are
77+
optimized and handled much faster than others.
78+
79+
config LOG_FRONTEND_STMESP_TURBO_DROP_OTHERS
80+
bool "Drop all logs except turbo logs"
81+
help
82+
Option can be enabled for memory constraint cases to remove all logging
83+
related code except turbo logs.
84+
85+
config LOG_FRONTEND_STMESP_TURBO_LOG_BASE
86+
def_int 32768
87+
88+
config LOG_FRONTEND_STPESP_TURBO_SOURCE_PORT_ID
89+
def_int 65535
90+
depends on LOG_FRONTEND_STMESP_TURBO_LOG
91+
7092
config LOG_FRONTEND_STMESP_GUARANTEED_ACCESS
7193
bool "Use STMESP guaranteed access"
7294
help

‎subsys/logging/frontends/log_frontend_stmesp.c‎

Lines changed: 41 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -581,7 +581,19 @@ void log_frontend_panic(void)
581581

582582
void log_frontend_init(void)
583583
{
584-
/* empty */
584+
#if defined(CONFIG_LOG_FRONTEND_STPESP_TURBO_SOURCE_PORT_ID) && !defined(CONFIG_NRF_ETR)
585+
/* Send location of section with constant source data. It is used by the
586+
* application core to retrieve source names of log messages coming from
587+
* coprocessors (FLPR and PPR).
588+
*/
589+
TYPE_SECTION_START_EXTERN(struct log_source_const_data, log_const);
590+
STMESP_Type *stm_esp;
591+
uintptr_t log_const_start;
592+
593+
(void)stmesp_get_port(CONFIG_LOG_FRONTEND_STPESP_TURBO_SOURCE_PORT_ID, &stm_esp);
594+
log_const_start = (uintptr_t)TYPE_SECTION_START(log_const);
595+
STM_D32(stm_esp, log_const_start, false, true);
596+
#endif
585597
}
586598

587599
void log_frontend_stmesp_dummy_write(void)
@@ -646,3 +658,31 @@ int log_frontend_stmesp_etr_ready(void)
646658
return 0;
647659
}
648660
#endif /* EARLY_BUF_SIZE > 0 */
661+
662+
void log_frontend_stmesp_log0(const void *source, uint32_t x)
663+
{
664+
STMESP_Type *port;
665+
int err = stmesp_get_port((uint32_t)x + 0x8000, &port);
666+
uint16_t source_id = log_source_id(source);
667+
668+
__ASSERT_NO_MSG(err == 0);
669+
if (err == 0) {
670+
stmesp_data16(port, source_id, true, true,
671+
IS_ENABLED(CONFIG_LOG_FRONTEND_STMESP_GUARANTEED_ACCESS));
672+
}
673+
}
674+
675+
void log_frontend_stmesp_log1(const void *source, uint32_t x, uint32_t arg)
676+
{
677+
STMESP_Type *port;
678+
int err = stmesp_get_port((uint32_t)x + 0x8000, &port);
679+
uint16_t source_id = log_source_id(source);
680+
681+
__ASSERT_NO_MSG(err == 0);
682+
if (err == 0) {
683+
stmesp_data16(port, source_id, false, true,
684+
IS_ENABLED(CONFIG_LOG_FRONTEND_STMESP_GUARANTEED_ACCESS));
685+
stmesp_data32(port, arg, true, true,
686+
IS_ENABLED(CONFIG_LOG_FRONTEND_STMESP_GUARANTEED_ACCESS));
687+
}
688+
}

0 commit comments

Comments
 (0)