Skip to content

[nrf fromlist] logging: STM fixes #2027

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 3 commits into from
Sep 20, 2024
Merged

[nrf fromlist] logging: STM fixes #2027

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
3 commits
Select commit Hold shift + click to select a range
37bddc0
[nrf fromlist] logging: frontend: stmesp_demux: Improve robustness
nordic-krch Sep 12, 2024
b24297b
[nrf fromlist] logging: frontends: stmesp: Run clang-format
nordic-krch Sep 13, 2024
093c96e
[nrf fromlist] logging: frontend_stmesp: Avoid unaligned word access
nordic-krch Sep 12, 2024
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
6 changes: 6 additions & 0 deletions subsys/logging/frontends/Kconfig
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -95,6 +95,12 @@ config LOG_FRONTEND_STMESP_DEMUX_BUFFER_SIZE
config LOG_FRONTEND_STMESP_DEMUX_MAX_UTILIZATION
bool "Track maximum utilization"

config LOG_FRONTEND_STMESP_DEMUX_GC_TIMEOUT
int "Message timeout (in milliseconds)"
default 100
help
If log message is not completed within that time frame it is discarded.

endif # LOG_FRONTEND_STMESP_DEMUX

config LOG_FRONTEND_STMESP_FLUSH_PORT_ID
Expand Down
114 changes: 86 additions & 28 deletions subsys/logging/frontends/log_frontend_stmesp.c
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -26,15 +26,19 @@ BUILD_ASSERT(sizeof(void *) == sizeof(uint32_t));

#define STMESP_FLUSH_WORD 0xaabbccdd

#define STM_FLAG(reg) \
#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, \
#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, \
#define STM_D16(reg, data, timestamp, marked) \
stmesp_data16(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.
Expand Down Expand Up @@ -95,7 +99,7 @@ union stm_log_dict_hdr {
/* Dictionary header initializer. */
#define DICT_HDR_INITIALIZER(_level, _source_id, _data_len) \
{ \
.hdr = {.ver = CONFIG_LOG_FRONTEND_STMESP_DICT_VER, \
.hdr = {.ver = CONFIG_LOG_FRONTEND_STMESP_DICT_VER, \
.type = STM_MSG_TYPE_LOG_DICT, \
.level = _level, \
.data_len = _data_len, \
Expand Down Expand Up @@ -211,18 +215,72 @@ static int early_package_cb(const void *buf, size_t len, void *ctx)

static inline void write_data(const void *data, size_t len, STMESP_Type *const stm_esp)
{
uint32_t *p32 = (uint32_t *)data;
const uint8_t *p8 = data;
const uint32_t *p32;
uint32_t unaligned;

if (!len) {
return;
}

/* Start by writing using D8 or D16 until pointer is word aligned. */
unaligned = (uintptr_t)data & 0x00000003UL;
if (unaligned != 0) {
unaligned = 4 - unaligned;
unaligned = MIN(len, unaligned);

len -= unaligned;

switch (unaligned) {
case 3:
STM_D8(stm_esp, *p8++, false, false);
STM_D16(stm_esp, *(uint16_t *)p8, false, false);
p8 += sizeof(uint16_t);
break;
case 2:
if (len) {
STM_D16(stm_esp, *(uint16_t *)p8, false, false);
p8 += sizeof(uint16_t);
} else {
/* If len 0 then it means that even though 2 bytes are
* to be copied we can have address which is not aligned
* to 2 bytes.
*/
STM_D8(stm_esp, *p8++, false, false);
STM_D8(stm_esp, *p8++, false, false);
}
break;
default:
/* 1 byte to align. */
STM_D8(stm_esp, *p8++, false, false);
}
}

p32 = (const uint32_t *)p8;

/* Use D32 to write as much data as possible. */
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--;
/* Write tail using D16 or D8. Address is word aligned at that point. */
if (len) {
p8 = (const uint8_t *)p32;
switch (len) {
case 2:
STM_D16(stm_esp, *(uint16_t *)p8, false, false);
p8 += sizeof(uint16_t);
break;
case 3:
STM_D16(stm_esp, *(uint16_t *)p8, false, false);
p8 += sizeof(uint16_t);
/* fallthrough */
default:
/* 1 byte to align. */
STM_D8(stm_esp, *p8++, false, false);
break;
}
}
}

Expand Down Expand Up @@ -281,8 +339,8 @@ void log_frontend_msg(const void *source, const struct log_msg_desc desc, uint8_
size_t sname_len;
int package_len;
int total_len;
static const uint32_t flags = CBPRINTF_PACKAGE_CONVERT_RW_STR |
CBPRINTF_PACKAGE_CONVERT_RO_STR;
static const uint32_t flags =
CBPRINTF_PACKAGE_CONVERT_RW_STR | CBPRINTF_PACKAGE_CONVERT_RO_STR;

sname = log_source_name_get(0, get_source_id(source));
if (sname) {
Expand All @@ -293,8 +351,8 @@ void log_frontend_msg(const void *source, const struct log_msg_desc desc, uint8_
}
total_len = desc.data_len + sname_len /* null terminator */;

package_len = cbprintf_package_convert(package, desc.package_len, NULL, NULL, flags,
strl, ARRAY_SIZE(strl));
package_len = cbprintf_package_convert(package, desc.package_len, NULL, NULL, flags, strl,
ARRAY_SIZE(strl));
hdr.log.total_len = total_len + package_len;
hdr.log.package_len = package_len;

Expand All @@ -308,8 +366,8 @@ void log_frontend_msg(const void *source, const struct log_msg_desc desc, uint8_
}

STM_D32(stm_esp, hdr.raw, use_timestamp, true);
(void)cbprintf_package_convert(package, desc.package_len,
package_cb, stm_esp, flags, strl, ARRAY_SIZE(strl));
(void)cbprintf_package_convert(package, desc.package_len, package_cb, stm_esp,
flags, strl, ARRAY_SIZE(strl));
write_data(sname, sname_len, stm_esp);
if (data) {
write_data(data, desc.data_len, stm_esp);
Expand All @@ -327,8 +385,8 @@ void log_frontend_msg(const void *source, const struct log_msg_desc desc, uint8_
}

early_buf_put_data((const uint8_t *)&hdr, sizeof(hdr));
(void)cbprintf_package_convert(package, desc.package_len, early_package_cb,
NULL, flags, strl, ARRAY_SIZE(strl));
(void)cbprintf_package_convert(package, desc.package_len, early_package_cb, NULL,
flags, strl, ARRAY_SIZE(strl));
early_buf_put_data(sname, sname_len);
if (data) {
early_buf_put_data(data, desc.data_len);
Expand Down Expand Up @@ -357,8 +415,8 @@ void log_frontend_msg(const void *source, const struct log_msg_desc desc, uint8_
}

STM_D32(stm_esp, dict_desc.raw, true, true);
(void)cbprintf_package_convert(package, desc.package_len, package_cb,
stm_esp, flags, NULL, 0);
(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);
}
Expand All @@ -370,8 +428,8 @@ void log_frontend_msg(const void *source, const struct log_msg_desc desc, uint8_
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);
(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);
}
Expand All @@ -383,8 +441,8 @@ void log_frontend_msg(const void *source, const struct log_msg_desc desc, uint8_
/* 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)
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;
Expand All @@ -398,8 +456,8 @@ static inline uint32_t *early_msg_start(uint32_t level, const void *source,
}

/* 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)
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);
Expand Down
35 changes: 34 additions & 1 deletion subsys/logging/frontends/log_frontend_stmesp_demux.c
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -25,6 +25,7 @@ BUILD_ASSERT(sizeof(struct log_frontend_stmesp_demux_log_header) == sizeof(uint3
struct log_frontend_stmesp_demux_active_entry {
sys_snode_t node;
uint32_t m_ch;
uint32_t ts;
struct log_frontend_stmesp_demux_log *packet;
int off;
};
Expand Down Expand Up @@ -221,6 +222,36 @@ static void log_frontend_stmesp_demux_hw_event(uint64_t *ts, uint8_t data)
mpsc_pbuf_put_data(&demux.pbuf, (const uint32_t *)&packet, wlen);
}

/* Check if there are any active messages which are not completed for a significant
* amount of time. It may indicate that part of message was lost (due to reset,
* fault in the core or fault on the bus). In that case message shall be closed as
* incomplete to not block processing of other messages.
*/
static void garbage_collector(uint32_t now)
{
sys_snode_t *node;

SYS_SLIST_FOR_EACH_NODE(&demux.active_entries, node) {
struct log_frontend_stmesp_demux_active_entry *entry =
CONTAINER_OF(node, struct log_frontend_stmesp_demux_active_entry, node);

if ((now - entry->ts) > CONFIG_LOG_FRONTEND_STMESP_DEMUX_GC_TIMEOUT) {
union log_frontend_stmesp_demux_packet p = {.log = entry->packet};

sys_slist_find_and_remove(&demux.active_entries, node);
entry->packet->content_invalid = 1;
mpsc_pbuf_commit(&demux.pbuf, p.generic);
demux.dropped++;
k_mem_slab_free(&demux.mslab, entry);
/* After removing one we need to stop as removing disrupts
* iterating over the list as current node is no longer in
* the list.
*/
break;
}
}
}

int log_frontend_stmesp_demux_packet_start(uint32_t *data, uint64_t *ts)
{
if (skip) {
Expand Down Expand Up @@ -265,9 +296,10 @@ int log_frontend_stmesp_demux_packet_start(uint32_t *data, uint64_t *ts)
union log_frontend_stmesp_demux_header hdr = {.raw = *data};
uint32_t pkt_len = hdr.log.total_len + offsetof(struct log_frontend_stmesp_demux_log, data);
uint32_t wlen = calc_wlen(pkt_len);
uint32_t now = k_uptime_get_32();

garbage_collector(now);
err = k_mem_slab_alloc(&demux.mslab, (void **)&entry, K_NO_WAIT);

if (err < 0) {
goto on_nomem;
}
Expand All @@ -288,6 +320,7 @@ int log_frontend_stmesp_demux_packet_start(uint32_t *data, uint64_t *ts)
}
entry->packet->hdr = hdr.log;
entry->packet->hdr.major = m;
entry->ts = now;
demux.curr = entry;
sys_slist_append(&demux.active_entries, &entry->node);

Expand Down
Loading