diff --git a/subsys/logging/frontends/Kconfig b/subsys/logging/frontends/Kconfig index e984532d6f2..89f03ea2d69 100644 --- a/subsys/logging/frontends/Kconfig +++ b/subsys/logging/frontends/Kconfig @@ -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 diff --git a/subsys/logging/frontends/log_frontend_stmesp.c b/subsys/logging/frontends/log_frontend_stmesp.c index 389f0f72aeb..4042fac853c 100644 --- a/subsys/logging/frontends/log_frontend_stmesp.c +++ b/subsys/logging/frontends/log_frontend_stmesp.c @@ -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. @@ -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, \ @@ -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; + } } } @@ -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) { @@ -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; @@ -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); @@ -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); @@ -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); } @@ -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); } @@ -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; @@ -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); diff --git a/subsys/logging/frontends/log_frontend_stmesp_demux.c b/subsys/logging/frontends/log_frontend_stmesp_demux.c index ed09f89ec8e..a3c052eab25 100644 --- a/subsys/logging/frontends/log_frontend_stmesp_demux.c +++ b/subsys/logging/frontends/log_frontend_stmesp_demux.c @@ -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; }; @@ -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) { @@ -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; } @@ -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);