Skip to content

Commit

Permalink
logging: frontends: stmesp_demux: Add support for turbo logs
Browse files Browse the repository at this point in the history 
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>
  • Loading branch information
@nordic-krch
nordic-krch committed Oct 7, 2024
1 parent 25d4293 commit 834b28b
Show file tree
Hide file tree
Showing 2 changed files with 222 additions and 12 deletions.
43 changes: 40 additions & 3 deletions include/zephyr/logging/log_frontend_stmesp_demux.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down Expand Up @@ -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.
Expand Down Expand Up @@ -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)
Expand Down Expand Up @@ -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.
Expand Down
191 changes: 182 additions & 9 deletions subsys/logging/frontends/log_frontend_stmesp_demux.c
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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>
Expand All @@ -14,6 +15,10 @@ 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

#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)
Expand All @@ -22,6 +27,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;
Expand All @@ -30,6 +39,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;
Expand All @@ -46,9 +60,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]
Expand All @@ -64,6 +89,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));
Expand Down Expand Up @@ -116,6 +175,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),
Expand Down Expand Up @@ -194,8 +255,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,
Expand Down Expand Up @@ -252,6 +346,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) {
Expand All @@ -273,6 +430,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 *)*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 *)*data;
}
return 0;
}

if (demux.curr != NULL) {
/* Previous package was incompleted. Finish it and potentially
* mark as incompleted if not all data is received.
Expand All @@ -281,14 +455,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;
}
Expand Down

0 comments on commit 834b28b

Please sign in to comment.