logging: Add Coresight STMESP dictionary-based frontend

Add frontend which is using Coresight STMESP for dictionary based
logging.

Signed-off-by: Krzysztof Chruściński <krzysztof.chruscinski@nordicsemi.no>
This commit is contained in:
Krzysztof Chruściński 2024-04-25 08:46:24 +02:00 committed by Anas Nashif
parent fa8e6d8701
commit 89ef8a097b
4 changed files with 632 additions and 0 deletions

View file

@ -0,0 +1,91 @@
/*
* Copyright (c) 2024 Nordic Semiconductor ASA
*
* SPDX-License-Identifier: Apache-2.0
*/
#ifndef ZEPHYR_INCLUDE_LOGGING_LOG_FRONTEND_STMESP_H_
#define ZEPHYR_INCLUDE_LOGGING_LOG_FRONTEND_STMESP_H_
#include <errno.h>
#include <zephyr/types.h>
#ifdef CONFIG_LOG_FRONTEND_STMESP
#include <zephyr/drivers/misc/coresight/stmesp.h>
#endif
#ifdef __cplusplus
extern "C" {
#endif
/** @brief Notify frontend that ETR/STM is ready.
*
* Log frontend optionally dumps buffered data and start to write to the STM
* stimulus port.
*
* @note Function is applicable only for the domain that performs initial ETR/STM setup.
*
* @retval 0 on success.
* @retval -EIO if there was an internal failure.
*/
int log_frontend_stmesp_etr_ready(void);
/** @brief Hook to be called before going to sleep.
*
* Hook writes dummy data to the STM Stimulus Port to ensure that all logging
* data is flushed.
*/
void log_frontend_stmesp_pre_sleep(void);
/** @brief Perform a dummy write to STMESP.
*
* It can be used to force flushing STM data.
*/
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.
*
* @param x Trace point ID.
*/
static inline void log_frontend_stmesp_tp(uint16_t x)
{
#ifdef CONFIG_LOG_FRONTEND_STMESP
STMESP_Type *port;
int err = stmesp_get_port((uint32_t)x + CONFIG_LOG_FRONTEND_STMESP_TP_CHAN_BASE, &port);
__ASSERT_NO_MSG(err == 0);
if (err == 0) {
stmesp_flag(port, 1, true,
IS_ENABLED(CONFIG_LOG_FRONTEND_STMESP_GUARANTEED_ACCESS));
}
#endif
}
/** @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.
*
* @param x Trace point ID.
* @param d Data. 32 bit word.
*/
static inline void log_frontend_stmesp_tp_d32(uint16_t x, uint32_t d)
{
#ifdef CONFIG_LOG_FRONTEND_STMESP
STMESP_Type *port;
int err = stmesp_get_port((uint32_t)x + CONFIG_LOG_FRONTEND_STMESP_TP_CHAN_BASE, &port);
__ASSERT_NO_MSG(err == 0);
if (err == 0) {
stmesp_data32(port, d, true, true,
IS_ENABLED(CONFIG_LOG_FRONTEND_STMESP_GUARANTEED_ACCESS));
}
#endif
}
#ifdef __cplusplus
}
#endif
#endif /* ZEPHYR_INCLUDE_LOGGING_LOG_FRONTEND_STMESP_H_ */

View file

@ -4,3 +4,8 @@ zephyr_sources_ifdef(
CONFIG_LOG_FRONTEND_DICT_UART
log_frontend_dict_uart.c
)
zephyr_sources_ifdef(
CONFIG_LOG_FRONTEND_STMESP
log_frontend_stmesp.c
)

View file

@ -29,4 +29,53 @@ config LOG_FRONTEND_DICT_UART_DROPPED_NOTIFY_PERIOD
in milliseconds.
endif
config LOG_FRONTEND_STMESP
bool "Coresight STM frontend"
imply ARM_ON_ENTER_CPU_IDLE_HOOK if LOG_FRONTEND_STMESP_FLUSH_COUNT > 0
if LOG_FRONTEND_STMESP
config LOG_FRONTEND_STMESP_DICT
bool
default y
select LOG_FRONTEND_OPT_API
select LOG_DICTIONARY_DB
imply LOG_FMT_SECTION
imply LOG_FMT_SECTION_STRIP
config LOG_FRONTEND_STMESP_FLUSH_COUNT
int "Number of flushing words"
default 4
help
Before going to sleep CPU shall write to STM some dummy data to ensure
that any buffered data goes to TPIU/ETR.
config LOG_FRONTEND_STMESP_FLUSH_PORT_ID
def_int 0
config LOG_FRONTEND_STMESP_EARLY_BUF_SIZE
int "Buffer size to store early messages"
default 0
help
Frontend cannot write to STM if it is used with ETR buffer unless ETR is
initialized and memory is properly configured (privileges). Data is stored
in the buffer and flushed to the STMESP once the pipeline is ready.
config LOG_FRONTEND_STMESP_DICT_VER
def_int 0
config LOG_FRONTEND_STMESP_GUARANTEED_ACCESS
bool "Use STMESP guaranteed access"
help
When enabled, accessing STMESP registers will stall if write cannot be
performed (e.g. ETR buffer is full).
config LOG_FRONTEND_STMESP_TP_CHAN_BASE
def_int 255
help
Do not change this value as it is aligned with host decoder (nrfutil trace).
endif # LOG_FRONTEND_STMESP
endmenu

View file

@ -0,0 +1,487 @@
/*
* Copyright (c) 2024 Nordic Semiconductor ASA
*
* SPDX-License-Identifier: Apache-2.0
*/
#include <zephyr/kernel.h>
#include <zephyr/logging/log_frontend.h>
#include <zephyr/logging/log_frontend_stmesp.h>
#include <zephyr/logging/log_output_dict.h>
#include <zephyr/logging/log_ctrl.h>
#include <zephyr/logging/log_msg.h>
#include <zephyr/sys/cbprintf.h>
/* Only 32 bit platforms supported. */
BUILD_ASSERT(sizeof(void *) == sizeof(uint32_t));
#define LOG_FRONTEND_STM_NO_SOURCE 0xFFFF
#define EARLY_BUF_SIZE CONFIG_LOG_FRONTEND_STMESP_EARLY_BUF_SIZE
#define LEN_SZ sizeof(uint32_t)
#define STMESP_FLUSH_WORD 0xaabbccdd
#define STM_FLAG(reg) \
stmesp_flag(reg, 1, false, IS_ENABLED(CONFIG_LOG_FRONTEND_STMESP_GUARANTEED_ACCESS))
#define STM_D8(reg, data, timestamp, marked) \
stmesp_data8(reg, data, timestamp, marked, \
IS_ENABLED(CONFIG_LOG_FRONTEND_STMESP_GUARANTEED_ACCESS))
#define STM_D32(reg, data, timestamp, marked) \
stmesp_data32(reg, data, timestamp, marked, \
IS_ENABLED(CONFIG_LOG_FRONTEND_STMESP_GUARANTEED_ACCESS))
/* Buffer for storing frontend data before STM/ETR is ready for usage.
* When notification about ETR readiness is received content of this buffer is
* written to the STM stimulus port.
*/
static atomic_t stmesp_chan_cnt;
static uint8_t early_buf[EARLY_BUF_SIZE] __aligned(sizeof(uint32_t));
static uint32_t early_buf_idx;
static struct k_spinlock lock;
/* Flag indicating that STM/ETR is ready for use. */
static bool etr_rdy;
/* Number of messages dropped due to too small early buffer. */
static uint32_t dropped;
/* Flag indicating that logging is in the panic mode. */
static bool in_panic;
static atomic_t new_data;
/* Enum used for type bit field in the message. */
enum stm_msg_type_log_dict {
/* Dictionary-based log message */
STM_MSG_TYPE_LOG_DICT = 0,
/* Reserved for future use. */
STM_MSG_TYPE_RESERVED = 1,
};
/* Descriptor of the dictionary based logging message. */
struct stm_log_dict_msg_desc {
/* Structure version. Current version 0. */
uint32_t ver: 2;
/* Type. Set 0 as this is a logging message descriptor. */
uint32_t type: 1;
/* Severity level. */
uint32_t level: 3;
/* Data length, non-zero fox hexdump message. */
uint32_t data_len: 12;
/* Source ID. Source index as ordered in the memory section. */
uint32_t source_id: 12;
/* Reserved for future use. */
uint32_t reserved: 2;
};
union stm_log_dict_hdr {
struct stm_log_dict_msg_desc hdr;
uint32_t raw;
};
/* Dictionary header initializer. */
#define DICT_HDR_INITIALIZER(_level, _source_id, _data_len) \
{ \
.hdr = {.ver = CONFIG_LOG_FRONTEND_STMESP_DICT_VER, \
.type = STM_MSG_TYPE_LOG_DICT, \
.level = _level, \
.data_len = _data_len, \
.source_id = _source_id, \
.reserved = 0 } \
}
/* Align early buffer index to a 32 bit word. */
static inline void early_buf_align_idx(void)
{
uint32_t rem = early_buf_idx & 0x3;
if (rem) {
early_buf_idx += (sizeof(uint32_t) - rem);
}
}
/* Get address where length is written. Location is used in the dictionary mode
* where length of the message is only known once whole message is written.
* Calculated length is written to the length field location.
*/
static inline uint32_t *early_buf_len_loc(void)
{
early_buf_align_idx();
uint32_t *loc = (uint32_t *)&early_buf[early_buf_idx];
early_buf_idx += LEN_SZ;
return loc;
}
/* Check if there is space for requested amount of data. */
static inline bool early_buf_has_space(uint32_t len)
{
return (EARLY_BUF_SIZE - early_buf_idx) >= len;
}
/* Calculate length of the message. It is calculated by taking current write
* location and length location (which is at the beginning of the current message.
* Used in dictionary mode.
*/
static inline uint32_t early_buf_get_len(uint32_t *len_loc)
{
if (early_buf_idx == EARLY_BUF_SIZE) {
return 0;
}
return (uint32_t)((uintptr_t)&early_buf[early_buf_idx] - (uintptr_t)len_loc - LEN_SZ);
}
/* Check if there is available space for the message. If yes, write length field
* and return true. If allocation fails it sets next length field to 0 to indicate
* that the buffer is full.
*/
static inline bool early_buf_alloc(uint32_t len)
{
early_buf_align_idx();
if (early_buf_has_space(len + LEN_SZ)) {
*(uint32_t *)&early_buf[early_buf_idx] = len;
early_buf_idx += LEN_SZ;
return true;
}
if (early_buf_has_space(LEN_SZ)) {
*(uint32_t *)&early_buf[early_buf_idx] = 0;
}
return false;
}
/* Switch to read mode. Start reading from the beginning. */
static inline void early_buf_read_mode(void)
{
early_buf_idx = 0;
}
/* Get message. Returns 0 if no messages. */
static inline uint32_t early_buf_get_data(void **buf)
{
early_buf_align_idx();
if (early_buf_has_space(LEN_SZ)) {
uint32_t len = *(uint32_t *)&early_buf[early_buf_idx];
*buf = &early_buf[early_buf_idx + LEN_SZ];
early_buf_idx += len + LEN_SZ;
return len;
}
return 0;
}
static int early_package_cb(const void *buf, size_t len, void *ctx)
{
ARG_UNUSED(ctx);
if (early_buf_has_space(len)) {
memcpy(&early_buf[early_buf_idx], buf, len);
early_buf_idx += len;
} else {
early_buf_idx = EARLY_BUF_SIZE;
}
return 0;
}
static inline void write_data(const void *data, size_t len, STMESP_Type *const stm_esp)
{
uint32_t *p32 = (uint32_t *)data;
while (len >= sizeof(uint32_t)) {
STM_D32(stm_esp, *p32++, false, false);
len -= sizeof(uint32_t);
}
uint8_t *p8 = (uint8_t *)p32;
while (len > 0) {
STM_D8(stm_esp, *p8++, false, false);
len--;
}
}
static int package_cb(const void *buf, size_t len, void *ctx)
{
write_data(buf, len, (STMESP_Type *const)ctx);
return len;
}
/* Get STM channel to use. Ensure that channel is unique for given priority level.
* This way we know that writing to that channel will not be interrupted by
* another log message writing to the same channel.
*/
static inline uint16_t get_channel(void)
{
return (atomic_inc(&stmesp_chan_cnt) & 0x7F) + 1;
}
/* Convert pointer to the source structure to the source ID. */
static inline int16_t get_source_id(const void *source)
{
if (source != NULL) {
return IS_ENABLED(CONFIG_LOG_RUNTIME_FILTERING)
? log_dynamic_source_id((void *)source)
: log_const_source_id(source);
}
return LOG_FRONTEND_STM_NO_SOURCE;
}
static void packet_end(STMESP_Type *stm_esp)
{
STM_FLAG(stm_esp);
atomic_set(&new_data, 1);
}
/* Common function to end the message when STMESP is not ready. */
static inline void early_msg_end(uint32_t *len_loc)
{
*len_loc = early_buf_get_len(len_loc);
if (*len_loc == 0) {
dropped++;
}
}
void log_frontend_msg(const void *source, const struct log_msg_desc desc, uint8_t *package,
const void *data)
{
static const uint32_t flags = CBPRINTF_PACKAGE_CONVERT_RW_STR;
union stm_log_dict_hdr dict_desc =
DICT_HDR_INITIALIZER(desc.level, get_source_id(source), 0);
if ((EARLY_BUF_SIZE == 0) || etr_rdy) {
STMESP_Type *stm_esp;
int err;
err = stmesp_get_port(get_channel(), &stm_esp);
if (err < 0) {
return;
}
STM_D32(stm_esp, dict_desc.raw, true, true);
(void)cbprintf_package_convert(package, desc.package_len, package_cb,
stm_esp, flags, NULL, 0);
if (data) {
package_cb(data, desc.data_len, stm_esp);
}
packet_end(stm_esp);
} else {
k_spinlock_key_t key;
uint32_t *len_loc;
key = k_spin_lock(&lock);
len_loc = early_buf_len_loc();
early_package_cb(&dict_desc.raw, sizeof(dict_desc.raw), NULL);
(void)cbprintf_package_convert(package, desc.package_len, early_package_cb,
NULL, flags, NULL, 0);
if (data) {
early_package_cb(data, desc.data_len, NULL);
}
early_msg_end(len_loc);
k_spin_unlock(&lock, key);
}
}
/* Common function for optimized message (log with 0-2 arguments) which is used in
* case when STMESP is not yet ready.
*/
static inline uint32_t *early_msg_start(uint32_t level, const void *source,
uint32_t package_hdr, const char *fmt)
{
union stm_log_dict_hdr dict_desc = DICT_HDR_INITIALIZER(level, get_source_id(source), 0);
uint32_t fmt32 = (uint32_t)fmt;
uint32_t *len_loc = early_buf_len_loc();
early_package_cb(&dict_desc.raw, sizeof(dict_desc.raw), NULL);
early_package_cb(&package_hdr, sizeof(package_hdr), NULL);
early_package_cb(&fmt32, sizeof(fmt32), NULL);
return len_loc;
}
/* Common function for optimized message (log with 0-2 arguments) which writes to STMESP */
static inline void msg_start(STMESP_Type *stm_esp, uint32_t level,
const void *source, uint32_t package_hdr, const char *fmt)
{
union stm_log_dict_hdr dict_desc = DICT_HDR_INITIALIZER(level, get_source_id(source), 0);
STM_D32(stm_esp, dict_desc.raw, true, true);
STM_D32(stm_esp, package_hdr, false, false);
STM_D32(stm_esp, (uint32_t)fmt, false, false);
}
void log_frontend_simple_0(const void *source, uint32_t level, const char *fmt)
{
static const union cbprintf_package_hdr package_hdr = {.desc = {.len = 2}};
if ((EARLY_BUF_SIZE == 0) || etr_rdy) {
STMESP_Type *stm_esp;
int err;
err = stmesp_get_port(get_channel(), &stm_esp);
if (err < 0) {
return;
}
msg_start(stm_esp, level, source, (uint32_t)package_hdr.raw, fmt);
packet_end(stm_esp);
return;
}
uint32_t *len_loc;
k_spinlock_key_t key;
key = k_spin_lock(&lock);
len_loc = early_msg_start(level, source, (uint32_t)package_hdr.raw, fmt);
early_msg_end(len_loc);
k_spin_unlock(&lock, key);
}
void log_frontend_simple_1(const void *source, uint32_t level, const char *fmt, uint32_t arg)
{
static const union cbprintf_package_hdr package_hdr = {.desc = {.len = 2 + 1}};
if ((EARLY_BUF_SIZE == 0) || etr_rdy) {
STMESP_Type *stm_esp;
int err;
err = stmesp_get_port(get_channel(), &stm_esp);
if (err < 0) {
return;
}
msg_start(stm_esp, level, source, (uint32_t)package_hdr.raw, fmt);
STM_D32(stm_esp, arg, false, false);
packet_end(stm_esp);
return;
}
uint32_t *len_loc;
k_spinlock_key_t key;
key = k_spin_lock(&lock);
len_loc = early_msg_start(level, source, (uint32_t)package_hdr.raw, fmt);
early_package_cb(&arg, sizeof(arg), NULL);
early_msg_end(len_loc);
k_spin_unlock(&lock, key);
}
void log_frontend_simple_2(const void *source, uint32_t level, const char *fmt, uint32_t arg0,
uint32_t arg1)
{
static const union cbprintf_package_hdr package_hdr = {.desc = {.len = 2 + 2}};
if ((EARLY_BUF_SIZE == 0) || etr_rdy) {
STMESP_Type *stm_esp;
int err;
err = stmesp_get_port(get_channel(), &stm_esp);
if (err < 0) {
return;
}
msg_start(stm_esp, level, source, (uint32_t)package_hdr.raw, fmt);
STM_D32(stm_esp, arg0, false, false);
STM_D32(stm_esp, arg1, false, false);
packet_end(stm_esp);
return;
}
uint32_t *len_loc;
k_spinlock_key_t key;
key = k_spin_lock(&lock);
len_loc = early_msg_start(level, source, (uint32_t)package_hdr.raw, fmt);
early_package_cb(&arg0, sizeof(arg0), NULL);
early_package_cb(&arg1, sizeof(arg1), NULL);
early_msg_end(len_loc);
k_spin_unlock(&lock, key);
}
void log_frontend_panic(void)
{
in_panic = true;
}
void log_frontend_init(void)
{
/* empty */
}
void log_frontend_stmesp_dummy_write(void)
{
#define STMESP_DUMMY_WORD 0xaabbccdd
STMESP_Type *stm_esp;
(void)stmesp_get_port(CONFIG_LOG_FRONTEND_STMESP_FLUSH_PORT_ID, &stm_esp);
STM_D32(stm_esp, STMESP_DUMMY_WORD, false, false);
}
void log_frontend_stmesp_pre_sleep(void)
{
bool use_stm = etr_rdy || (EARLY_BUF_SIZE == 0);
if (!use_stm || new_data == 0) {
return;
}
for (uint32_t i = 0; i < CONFIG_LOG_FRONTEND_STMESP_FLUSH_COUNT; i++) {
log_frontend_stmesp_dummy_write();
}
atomic_set(&new_data, 0);
}
#if EARLY_BUF_SIZE > 0
int log_frontend_stmesp_etr_ready(void)
{
STMESP_Type *stm_esp;
uint16_t len;
uint32_t *buf = NULL;
int err;
err = stmesp_get_port(get_channel(), &stm_esp);
if (err < 0) {
return -EIO;
}
early_buf_read_mode();
while ((len = early_buf_get_data((void **)&buf)) > 0) {
/* Write first word with Marked and timestamp. */
STM_D32(stm_esp, *buf, true, true);
buf++;
len -= sizeof(uint32_t);
/* Write remaining data as raw data. */
write_data(buf, len, stm_esp);
/* Flag the end. */
packet_end(stm_esp);
}
etr_rdy = true;
return 0;
}
#endif /* EARLY_BUF_SIZE > 0 */