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 <krzysztof.chruscinski@nordicsemi.no>
This commit is contained in:
Krzysztof Chruściński 2024-10-07 11:24:48 +02:00 committed by Benjamin Cabé
commit 9d478d7675
3 changed files with 232 additions and 18 deletions

View file

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

View file

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

View file

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