logging: frontends: stmesp_demux: Add support for turbo logs

Add support for handling optimized short log messages (aka turbo logs).
There are 2 types of turbo log messages:
- No arguments. D16MTS is used for that on channel > 32768
- One numeric argument. DM16 followed by D32MTS is used.

Additionally, in order to be able to get source name for log messages
coming from owned by cpuapp co-processors (PPR and FLPR) there must
be a way of passing location of constant source data from PPR/FLPR to
cpuapp which handles ETR data. This method is added in the commit as
well. PPR/FLPR sends D32M during the boot with address of constant
source data section. Demultiplexer stores those addresses and it is
able to retrieve source name for log messages from PPR/FLPR.

Signed-off-by: Krzysztof Chruściński <[email protected]>

Author: nordic-krch

include/zephyr/logging/log_frontend_stmesp_demux.h

@@ -121,11 +121,14 @@ struct log_frontend_stmesp_demux_trace_point {
 	/** Flag indicating if trace point includes data. */
 	uint64_t has_data: 1;
 
-	/** Timestamp. */
-	uint64_t timestamp: 58;
+	/** Timestamp. 54 bits at 40MHz is >14 years. */
+	uint64_t timestamp: 54;
 
 	/** Major ID. */
-	uint16_t major;
+	uint64_t major: 4;
+
+	/** Source ID - used for compressed logging. */
+	uint16_t source_id;
 
 	/** ID */
 	uint16_t id;
@@ -180,6 +183,12 @@ struct log_frontend_stmesp_demux_config {
 
 	/** Array length. Must be not bigger than @ref LOG_FRONTEND_STMESP_DEMUX_MAJOR_MAX. */
 	uint32_t m_ids_cnt;
+
+	/** Buffer for storing source ID's. Used for turbo logging. */
+	uint32_t *source_id_buf;
+
+	/** It must be multiple of number of major ID's count. */
+	size_t source_id_buf_len;
 };
 
 /** @brief Initialize the demultiplexer.
@@ -210,6 +219,19 @@ void log_frontend_stmesp_demux_channel(uint16_t id);
  */
 int log_frontend_stmesp_demux_packet_start(uint32_t *data, uint64_t *ts);
 
+/** @brief Indicate optimized log message with no arguments.
+ *
+ * @param source_id Source ID.
+ * @param ts	Timestamp. Can be NULL.
+ */
+int log_frontend_stmesp_demux_log0(uint16_t source_id, uint64_t *ts);
+
+/** @brief Indicate source ID.
+ *
+ * @param source_id Source ID.
+ */
+void log_frontend_stmesp_demux_source_id(uint16_t source_id);
+
 /** @brief Indicate timestamp.
  *
  * Timestamp is separated from packet start because according to STM spec (3.2.2)
@@ -254,6 +276,21 @@ union log_frontend_stmesp_demux_packet log_frontend_stmesp_demux_claim(void);
  */
 void log_frontend_stmesp_demux_free(union log_frontend_stmesp_demux_packet packet);
 
+/** @brief Get source name for a turbo log message.
+ *
+ * During a boot cooprocessors (FLPR and PPR) are sending location in memory where
+ * their source data is stored. If application core is an owner of those cores
+ * it has access to that memory and based on chip ID and source ID it can retrieve
+ * the source name.
+ *
+ * @param m_id Major ID.
+ * @param s_id Source ID.
+ *
+ * @return Pointer to a string which is a source name or unknown name if source name
+ *         cannot be retrieved.
+ */
+const char *log_frontend_stmesp_demux_sname_get(uint32_t m_id, uint16_t s_id);
+
 /** @brief Check if there are any started but not completed log messages.
  *
  * @retval True There is no pending started log message.

subsys/logging/frontends/log_frontend_stmesp_demux.c

@@ -5,6 +5,7 @@
  */
 
 #include <zephyr/logging/log_frontend_stmesp_demux.h>
+#include <zephyr/logging/log_ctrl.h>
 #include <zephyr/sys/mpsc_pbuf.h>
 #include <zephyr/sys/__assert.h>
 #include <zephyr/logging/log_msg.h>
@@ -14,6 +15,14 @@ LOG_MODULE_REGISTER(stmesp_demux);
 BUILD_ASSERT(sizeof(struct log_frontend_stmesp_demux_log_header) == sizeof(uint32_t),
 		"Must fit in a word");
 
+#ifndef CONFIG_LOG_FRONTEND_STPESP_TURBO_SOURCE_PORT_ID
+#define CONFIG_LOG_FRONTEND_STPESP_TURBO_SOURCE_PORT_ID 0
+#endif
+
+#ifndef CONFIG_LOG_FRONTEND_STMESP_TURBO_LOG_BASE
+#define CONFIG_LOG_FRONTEND_STMESP_TURBO_LOG_BASE 0x8000
+#endif
+
 #define NUM_OF_ACTIVE CONFIG_LOG_FRONTEND_STMESP_DEMUX_ACTIVE_PACKETS
 #define M_ID_OFF      16
 #define M_ID_MASK     (BIT_MASK(16) << M_ID_OFF)
@@ -22,6 +31,10 @@ BUILD_ASSERT(sizeof(struct log_frontend_stmesp_demux_log_header) == sizeof(uint3
 #define M_CH_HW_EVENT 0x00800000
 #define M_CH_INVALID  0xFFFFFFFF
 
+#define APP_M_ID  0x22
+#define FLPR_M_ID 0x2D
+#define PPR_M_ID  0x2E
+
 struct log_frontend_stmesp_demux_active_entry {
 	sys_snode_t node;
 	uint32_t m_ch;
@@ -30,6 +43,11 @@ struct log_frontend_stmesp_demux_active_entry {
 	int off;
 };
 
+struct log_frontend_stmesp_coop_sources {
+	uint32_t m_id;
+	const struct log_source_const_data *log_const;
+};
+
 struct log_frontend_stmesp_demux {
 	/* Pool for active entries. */
 	struct k_mem_slab mslab;
@@ -46,9 +64,20 @@ struct log_frontend_stmesp_demux {
 
 	const uint16_t *m_ids;
 
-	uint32_t m_ids_cnt;
+	uint32_t *source_ids;
+
+	uint16_t m_ids_cnt;
+
+	uint16_t source_id_len;
 
 	uint32_t dropped;
+
+	struct log_frontend_stmesp_coop_sources coop_sources[2];
+};
+
+struct log_frontend_stmesp_entry_source_pair {
+	uint16_t entry_id;
+	uint16_t source_id;
 };
 
 static uint32_t buffer[CONFIG_LOG_FRONTEND_STMESP_DEMUX_BUFFER_SIZE]
@@ -64,6 +93,40 @@ static void notify_drop(const struct mpsc_pbuf_buffer *buffer,
 	demux.dropped++;
 }
 
+static void store_source_id(uint16_t m_id, uint16_t entry_id, uint16_t source_id)
+{
+	uint32_t *source_ids_data = &demux.source_ids[m_id * (demux.source_id_len + 1)];
+	uint32_t *wr_idx = source_ids_data;
+	struct log_frontend_stmesp_entry_source_pair *source_ids =
+		(struct log_frontend_stmesp_entry_source_pair *)&source_ids_data[1];
+
+	source_ids[*wr_idx].entry_id = entry_id;
+	source_ids[*wr_idx].source_id = source_id;
+	*wr_idx = *wr_idx + 1;
+	if (*wr_idx == (demux.source_id_len)) {
+		*wr_idx = 0;
+	}
+}
+
+static uint16_t get_source_id(uint16_t m_id, uint16_t entry_id)
+{
+	uint32_t *source_ids_data = &demux.source_ids[m_id * (demux.source_id_len + 1)];
+	int32_t rd_idx = source_ids_data[0];
+	uint32_t cnt = demux.source_id_len;
+	struct log_frontend_stmesp_entry_source_pair *source_ids =
+		(struct log_frontend_stmesp_entry_source_pair *)&source_ids_data[1];
+
+	do {
+		rd_idx = (rd_idx == 0) ? (demux.source_id_len - 1) : (rd_idx - 1);
+		if (source_ids[rd_idx].entry_id == entry_id) {
+			return source_ids[rd_idx].source_id;
+		}
+		cnt--;
+	} while (cnt);
+
+	return 0;
+}
+
 static uint32_t calc_wlen(uint32_t total_len)
 {
 	return DIV_ROUND_UP(ROUND_UP(total_len, Z_LOG_MSG_ALIGNMENT), sizeof(uint32_t));
@@ -116,6 +179,8 @@ int log_frontend_stmesp_demux_init(const struct log_frontend_stmesp_demux_config
 	demux.dropped = 0;
 	demux.curr_m_ch = M_CH_INVALID;
 	demux.curr = NULL;
+	demux.source_ids = config->source_id_buf;
+	demux.source_id_len = config->source_id_buf_len / config->m_ids_cnt - 1;
 
 	err = k_mem_slab_init(&demux.mslab, slab_buf,
 			      sizeof(struct log_frontend_stmesp_demux_active_entry),
@@ -194,8 +259,41 @@ static uint8_t get_major_id(uint16_t m_id)
 	return 0;
 }
 
-static void log_frontend_stmesp_demux_trace_point(uint16_t m_id, uint16_t id, uint64_t *ts,
-						  uint32_t *data)
+static void store_turbo_log0(uint16_t m_id, uint16_t id, uint64_t *ts, uint16_t source_id)
+{
+	struct log_frontend_stmesp_demux_trace_point packet = {
+		.valid = 1,
+		.type = LOG_FRONTEND_STMESP_DEMUX_TYPE_TRACE_POINT,
+		.content_invalid = 0,
+		.has_data = 0,
+		.timestamp = ts ? *ts : 0,
+		.major = m_id,
+		.source_id = source_id,
+		.id = id,
+		.data = 0};
+	static const size_t wlen = sizeof(packet) / sizeof(uint32_t);
+
+	mpsc_pbuf_put_data(&demux.pbuf, (const uint32_t *)&packet, wlen);
+}
+
+static void store_turbo_log1(uint16_t m_id, uint16_t id, uint64_t *ts, uint32_t data)
+{
+	struct log_frontend_stmesp_demux_trace_point packet = {
+		.valid = 1,
+		.type = LOG_FRONTEND_STMESP_DEMUX_TYPE_TRACE_POINT,
+		.content_invalid = 0,
+		.has_data = 0,
+		.timestamp = ts ? *ts : 0,
+		.major = m_id,
+		.source_id = get_source_id(m_id, id),
+		.id = id,
+		.data = data};
+	static const size_t wlen = sizeof(packet) / sizeof(uint32_t);
+
+	mpsc_pbuf_put_data(&demux.pbuf, (const uint32_t *)&packet, wlen);
+}
+
+static void store_tracepoint(uint16_t m_id, uint16_t id, uint64_t *ts, uint32_t *data)
 {
 	struct log_frontend_stmesp_demux_trace_point packet = {.valid = 1,
 					       .type = LOG_FRONTEND_STMESP_DEMUX_TYPE_TRACE_POINT,
@@ -252,6 +350,69 @@ static void garbage_collector(uint32_t now)
 	}
 }
 
+int log_frontend_stmesp_demux_log0(uint16_t source_id, uint64_t *ts)
+{
+	if (skip) {
+		return 0;
+	}
+
+	if (demux.curr_m_ch == M_CH_INVALID) {
+		return -EINVAL;
+	}
+
+	if (demux.curr != NULL) {
+		/* Previous package was incompleted. Finish it and potentially
+		 * mark as incompleted if not all data is received.
+		 */
+		log_frontend_stmesp_demux_packet_end();
+		return -EINVAL;
+	}
+
+	uint16_t ch = demux.curr_m_ch & C_ID_MASK;
+	uint16_t m = get_major_id(demux.curr_m_ch >> M_ID_OFF);
+
+	if (ch < CONFIG_LOG_FRONTEND_STMESP_TURBO_LOG_BASE) {
+		return -EINVAL;
+	}
+
+	store_turbo_log0(m, ch, ts, source_id);
+
+	return 1;
+}
+
+void log_frontend_stmesp_demux_source_id(uint16_t data)
+{
+	if (skip) {
+		return;
+	}
+
+	if (demux.curr_m_ch == M_CH_INVALID) {
+		return;
+	}
+
+	uint16_t ch = demux.curr_m_ch & C_ID_MASK;
+	uint16_t m = get_major_id(demux.curr_m_ch >> M_ID_OFF);
+
+	store_source_id(m, ch, data);
+}
+
+const char *log_frontend_stmesp_demux_sname_get(uint32_t m_id, uint16_t s_id)
+{
+	if (!IS_ENABLED(CONFIG_LOG_FRONTEND_STMESP_TURBO_LOG)) {
+		return "";
+	}
+
+	if (demux.m_ids[m_id] == APP_M_ID) {
+		return log_source_name_get(0, s_id);
+	} else if (m_id == demux.coop_sources[0].m_id) {
+		return demux.coop_sources[0].log_const[s_id].name;
+	} else if (m_id == demux.coop_sources[1].m_id) {
+		return demux.coop_sources[1].log_const[s_id].name;
+	}
+
+	return "unknown";
+}
+
 int log_frontend_stmesp_demux_packet_start(uint32_t *data, uint64_t *ts)
 {
 	if (skip) {
@@ -273,6 +434,23 @@ int log_frontend_stmesp_demux_packet_start(uint32_t *data, uint64_t *ts)
 		return 1;
 	}
 
+	uint16_t ch = demux.curr_m_ch & C_ID_MASK;
+	uint16_t m = get_major_id(demux.curr_m_ch >> M_ID_OFF);
+
+	if (IS_ENABLED(CONFIG_LOG_FRONTEND_STMESP_TURBO_LOG) &&
+	    (ch == CONFIG_LOG_FRONTEND_STPESP_TURBO_SOURCE_PORT_ID)) {
+		if (demux.m_ids[m] == FLPR_M_ID) {
+			demux.coop_sources[0].m_id = m;
+			demux.coop_sources[0].log_const =
+				(const struct log_source_const_data *)(uintptr_t)*data;
+		} else if (demux.m_ids[m] == PPR_M_ID) {
+			demux.coop_sources[1].m_id = m;
+			demux.coop_sources[1].log_const =
+				(const struct log_source_const_data *)(uintptr_t)*data;
+		}
+		return 0;
+	}
+
 	if (demux.curr != NULL) {
 		/* Previous package was incompleted. Finish it and potentially
 		 * mark as incompleted if not all data is received.
@@ -281,14 +459,13 @@ int log_frontend_stmesp_demux_packet_start(uint32_t *data, uint64_t *ts)
 		return -EINVAL;
 	}
 
-	uint16_t ch = demux.curr_m_ch & C_ID_MASK;
-	uint16_t m = get_major_id(demux.curr_m_ch >> M_ID_OFF);
-
 	if (ch >= CONFIG_LOG_FRONTEND_STMESP_TP_CHAN_BASE) {
-		uint32_t id = (uint32_t)ch - CONFIG_LOG_FRONTEND_STMESP_TP_CHAN_BASE;
-
 		/* Trace point */
-		log_frontend_stmesp_demux_trace_point(m, id, ts, data);
+		if (ch >= CONFIG_LOG_FRONTEND_STMESP_TURBO_LOG_BASE) {
+			store_turbo_log1(m, ch, ts, *data);
+		} else {
+			store_tracepoint(m, ch, ts, data);
+		}
 
 		return 1;
 	}

tests/subsys/logging/log_frontend_stmesp_demux/src/main.c

@@ -408,12 +408,12 @@ ZTEST(log_frontend_stmesp_demux_test, test_trace_point)
 	err = write_trace_point(&m_id1, &c_id1, NULL, t1);
 	zassert_equal(err, 1);
 
-	CLAIM_TRACE_POINT(m_id0, id0, t0, NULL);
-	CLAIM_TRACE_POINT(m_id0, id0, t0, NULL);
-	CLAIM_TRACE_POINT(m_id0, id0, t0, &data);
-	CLAIM_TRACE_POINT(m_id0, id1, t1, &data);
-	CLAIM_TRACE_POINT(m_id1, id0, t0, NULL);
-	CLAIM_TRACE_POINT(m_id1, id1, t1, NULL);
+	CLAIM_TRACE_POINT(m_id0, c_id0, t0, NULL);
+	CLAIM_TRACE_POINT(m_id0, c_id0, t0, NULL);
+	CLAIM_TRACE_POINT(m_id0, c_id0, t0, &data);
+	CLAIM_TRACE_POINT(m_id0, c_id1, t1, &data);
+	CLAIM_TRACE_POINT(m_id1, c_id0, t0, NULL);
+	CLAIM_TRACE_POINT(m_id1, c_id1, t1, NULL);
 
 	DEMUX_EMPTY();
 }