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 <krzysztof.chruscinski@nordicsemi.no>

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

@@ -7,8 +7,22 @@
 	{
 		Z_LINK_ITERABLE(log_strings);
 	} 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
 	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
 
 	ITERABLE_SECTION_ROM(log_const, Z_LINK_ITERABLE_SUBALIGN)

include/zephyr/logging/log_frontend_stmesp.h

@@ -44,7 +44,7 @@ void log_frontend_stmesp_dummy_write(void);
 /** @brief Trace point
  *
  * 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.
  */
@@ -65,7 +65,7 @@ static inline void log_frontend_stmesp_tp(uint16_t x)
 /** @brief Trace point with 32 bit data.
  *
  * 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 d Data. 32 bit word.
@@ -84,6 +84,57 @@ static inline void log_frontend_stmesp_tp_d32(uint16_t x, uint32_t d)
 #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
 }
 #endif

soc/nordic/common/zephyr_custom_log.h

@@ -0,0 +1,148 @@
+/*
+ * 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_ */

subsys/logging/frontends/Kconfig

@@ -67,6 +67,28 @@ config LOG_FRONTEND_STMESP_EARLY_BUF_SIZE
 config LOG_FRONTEND_STMESP_DICT_VER
 	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
 	bool "Use STMESP guaranteed access"
 	help

subsys/logging/frontends/log_frontend_stmesp.c

@@ -565,7 +565,19 @@ void log_frontend_panic(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)
@@ -626,3 +638,31 @@ int log_frontend_stmesp_etr_ready(void)
 	return 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));
+	}
+}