From ba001a4d8e98114ba1a091fcdd6037cf6597f1b6 Mon Sep 17 00:00:00 2001 From: Jyri Sarha Date: Mon, 2 Feb 2026 16:17:01 +0200 Subject: [PATCH 1/5] debug: debug_stream_slot: Use spinlock instead of mutex for ISR Use spinlock instead of mutex to allow ISR context usage. Signed-off-by: Jyri Sarha --- src/debug/debug_stream/debug_stream_slot.c | 16 +++++----------- 1 file changed, 5 insertions(+), 11 deletions(-) diff --git a/src/debug/debug_stream/debug_stream_slot.c b/src/debug/debug_stream/debug_stream_slot.c index 388b7852e6ed..a55c1c1e116d 100644 --- a/src/debug/debug_stream/debug_stream_slot.c +++ b/src/debug/debug_stream/debug_stream_slot.c @@ -10,11 +10,12 @@ #include #include #include +#include LOG_MODULE_REGISTER(debug_stream_slot); struct cpu_mutex { - struct k_mutex m; + struct k_spinlock l; } __aligned(CONFIG_DCACHE_LINE_SIZE); /* CPU specific mutexes for each circular buffer */ @@ -66,6 +67,7 @@ int debug_stream_slot_send_record(struct debug_stream_record *rec) debug_stream_get_circular_buffer(&desc, arch_proc_id()); uint32_t record_size = rec->size_words; uint32_t record_start, buf_remain; + k_spinlock_key_t key; LOG_DBG("Sending record %u id %u len %u", rec->seqno, rec->id, rec->size_words); @@ -77,7 +79,7 @@ int debug_stream_slot_send_record(struct debug_stream_record *rec) desc.buf_words, desc.core_id, desc.buf_words, desc.offset); return -ENOMEM; } - k_mutex_lock(&cpu_mutex[arch_proc_id()].m, K_FOREVER); + key = k_spin_lock(&cpu_mutex[arch_proc_id()].l); rec->seqno = buf->next_seqno++; rec->size_words = record_size + 1; /* +1 for size at the end of record */ @@ -105,7 +107,7 @@ int debug_stream_slot_send_record(struct debug_stream_record *rec) buf->data[buf->w_ptr] = record_size + 1; buf->w_ptr = (buf->w_ptr + 1) % desc.buf_words; - k_mutex_unlock(&cpu_mutex[arch_proc_id()].m); + k_spin_unlock(&cpu_mutex[arch_proc_id()].l, key); LOG_DBG("Record %u id %u len %u sent", rec->seqno, rec->id, record_size); return 0; @@ -159,14 +161,6 @@ static int debug_stream_slot_init(void) buf->next_seqno = 0; buf->w_ptr = 0; - k_mutex_init(&cpu_mutex[i].m); - /* The core specific mutexes are now .bss which is uncached so the - * following line is commented out. However, since the mutexes are - * core specific there should be nothing preventing from having them - * in cached memory. - * - * sys_cache_data_flush_range(&cpu_mutex[i], sizeof(cpu_mutex[i])); - */ } LOG_INF("Debug stream slot initialized"); From 7fb5898da817bcdcedacdef99631041b88669bf6 Mon Sep 17 00:00:00 2001 From: Jyri Sarha Date: Mon, 2 Feb 2026 23:06:19 +0200 Subject: [PATCH 2/5] debug_stream: text_msg: Set exception dump hooks if available Set exception dump hooks if CONFIG_EXCEPTION_DUMP_HOOK=y. This enables sending a simple text report of fatal exceptions. To get this working one needs these config options: CONFIG_EXCEPTION_DUMP_HOOK=y CONFIG_EXCEPTION_DUMP_HOOK_ONLY=y CONFIG_SOF_DEBUG_STREAM_SLOT=y CONFIG_SOF_DEBUG_STREAM_TEXT_MSG=y CONFIG_SOF_DEBUG_STREAM_SLOT_NUMBER=2 CONFIG_SOF_TELEMETRY=n CONFIG_SOF_TELEMETRY_PERFORMANCE_MEASUREMENTS=n CONFIG_SOF_TELEMETRY_IO_PERFORMANCE_MEASUREMENTS=n If system hangs and an the exception is reported successfully the report can be seen with debug_stream.py (which should be installed in the same directory with cavstool.py). It does matter if the tool was not running at the time. The report should be available there in the debug slot window for debug_stream.py to decode as long as system remains up. The report should looks something like this: CPU 2: FATAL EXCEPTION CPU 2 EXCCAUSE 63 (zephyr exception) PC 0xa003048b VADDR 0xa0031020 PS 0x60220 (INTLEVEL:0 EXCM: 0 UM:1 RING:0 WOE:1 OWB:2 CALLINC:2) A0 0xa006c2b8 SP 0xa00dd160 A2 0x4 A3 0xa00dd170 A4 0xa00dd150 A5 0x4 A6 0x6 A7 0x4 A8 0xa006c109 A9 0xa00dd0f0 A10 0xa00a697d A11 0xa00dd170 A12 0xa00dd150 A13 0x4 A14 0x401a6b24 A15 0x401a6b24 LBEG 0xa0044323 LEND 0xa0044330 LCOUNT 0xa006de66 SAR 0x4 THREADPTR (nil) BT 0xa0030488:0xa00dd160 CORRUPTED Signed-off-by: Jyri Sarha --- .../debug_stream/debug_stream_text_msg.c | 84 +++++++++++++++++++ 1 file changed, 84 insertions(+) diff --git a/src/debug/debug_stream/debug_stream_text_msg.c b/src/debug/debug_stream/debug_stream_text_msg.c index 8933df03e6bb..118ef700ecbd 100644 --- a/src/debug/debug_stream/debug_stream_text_msg.c +++ b/src/debug/debug_stream/debug_stream_text_msg.c @@ -8,9 +8,13 @@ #include #include #include +#include +#include #include +LOG_MODULE_REGISTER(debug_stream_text_msg); + void ds_msg(const char *format, ...) { va_list args; @@ -33,3 +37,83 @@ void ds_msg(const char *format, ...) sizeof(buf.msg.hdr.data[0])); debug_stream_slot_send_record(&buf.msg.hdr); } + +#if defined(CONFIG_EXCEPTION_DUMP_HOOK) +/* The debug stream debug window slot is 4k, and when it is split + * between the cores and the header/other overhead is removed, with 5 + * cores the size is 768 bytes. The dump record must be smaller than + * that to get through to the host side. + * + * Also, because of the limited circular buffer size, we should only + * send one exception record. Exceptions often happen in bursts in a + * SOF system, and sending more than one record makes the host-side + * decoder lose track of things. + */ +static struct { + struct debug_stream_text_msg msg; + char text[640]; +} __packed ds_buf; +static int reports_sent_cpu[CONFIG_MP_MAX_NUM_CPUS]; +static size_t ds_pos; + +static void ds_exception_drain(bool flush) +{ + if (flush) { + ds_pos = 0; + return; + } + + if (reports_sent_cpu[arch_proc_id()]++ > 0) + return; + + ds_buf.msg.hdr.id = DEBUG_STREAM_RECORD_ID_TEXT_MSG; + ds_buf.msg.hdr.size_words = SOF_DIV_ROUND_UP(sizeof(ds_buf.msg) + ds_pos, + sizeof(ds_buf.msg.hdr.data[0])); + /* Make sure the possible upto 3 extra bytes at end of msg are '\0' */ + memset(ds_buf.text + ds_pos, 0, ds_buf.msg.hdr.size_words * + sizeof(ds_buf.msg.hdr.data[0]) - ds_pos); + debug_stream_slot_send_record(&ds_buf.msg.hdr); + ds_pos = 0; +} + +static void ds_exception_dump(const char *format, va_list args) +{ + ssize_t len; + size_t avail; + size_t written; + + if (reports_sent_cpu[arch_proc_id()] > 0) + return; + + avail = sizeof(ds_buf.text) - ds_pos; + if (avail == 0) { + ds_exception_drain(false); + return; + } + + len = vsnprintf(ds_buf.text + ds_pos, avail, format, args); + if (len < 0) { + ds_pos = 0; + return; + } + + if ((size_t)len >= avail) + written = avail - 1; + else + written = (size_t)len; + + ds_pos += written; + + if (ds_pos >= sizeof(ds_buf.text)) + ds_exception_drain(false); +} + +static int init_exception_dump_hook(void) +{ + set_exception_dump_hook(ds_exception_dump, ds_exception_drain); + LOG_INF("exception_dump_hook set"); + return 0; +} + +SYS_INIT(init_exception_dump_hook, APPLICATION, CONFIG_KERNEL_INIT_PRIORITY_DEFAULT); +#endif From bbc7cd5441551570e513bddeaef6ddc77a6c0281 Mon Sep 17 00:00:00 2001 From: Jyri Sarha Date: Wed, 11 Feb 2026 00:17:41 +0200 Subject: [PATCH 3/5] debug_stream: text_msg: exception: Skip useless " ** " prefix Skip useless " ** " prefix from exception dumps to save byte is in the debug_stream buffer. Signed-off-by: Jyri Sarha --- src/debug/debug_stream/debug_stream_text_msg.c | 5 +++++ 1 file changed, 5 insertions(+) diff --git a/src/debug/debug_stream/debug_stream_text_msg.c b/src/debug/debug_stream/debug_stream_text_msg.c index 118ef700ecbd..8dea31e75236 100644 --- a/src/debug/debug_stream/debug_stream_text_msg.c +++ b/src/debug/debug_stream/debug_stream_text_msg.c @@ -91,6 +91,11 @@ static void ds_exception_dump(const char *format, va_list args) return; } + /* Skip useless " ** " prefix to save bytes */ + if (strlen(format) >= 4 && + format[0] == ' ' && format[1] == '*' && format[2] == '*' && format[3] == ' ') + format += 4; + len = vsnprintf(ds_buf.text + ds_pos, avail, format, args); if (len < 0) { ds_pos = 0; From 78329315493b4cef53dfb9c3c56cee94ec076965 Mon Sep 17 00:00:00 2001 From: Jyri Sarha Date: Tue, 3 Mar 2026 19:04:33 +0200 Subject: [PATCH 4/5] tools: debug_stream.py: Cut text msg when first '\0' is encountered The utf-8 decoder does not appear to be sensitive to '\0' in the buffer so cut from word boundary may produce unwanted characters at the end of the message. Make also the text message always star from the beginning of the line and not from the same line with "CPU X:" tag. Signed-off-by: Jyri Sarha --- tools/debug_stream/debug_stream.py | 5 +++-- 1 file changed, 3 insertions(+), 2 deletions(-) diff --git a/tools/debug_stream/debug_stream.py b/tools/debug_stream/debug_stream.py index 0191c5cd7be7..39770cab4cd3 100644 --- a/tools/debug_stream/debug_stream.py +++ b/tools/debug_stream/debug_stream.py @@ -162,8 +162,9 @@ def print_text_msg(self, record, cpu): buffer = ( ctypes.c_ubyte * (len(record) - ctypes.sizeof(TextMsg)) ).from_address(ctypes.addressof(record) + ctypes.sizeof(TextMsg)) - msg = bytearray(buffer).decode("utf-8") - print("CPU %u: %s" % (cpu, msg)) + payload = bytes(buffer) + msg = payload.split(b"\0", 1)[0].decode("utf-8", errors="replace") + print("CPU %u:\n%s" % (cpu, msg)) return True class DebugStreamSectionDescriptor(ctypes.Structure): From ded889b49c2d59459e463fb040f9d3d60a80899b Mon Sep 17 00:00:00 2001 From: Jyri Sarha Date: Tue, 3 Mar 2026 22:38:15 +0200 Subject: [PATCH 5/5] app: debug_stream_overlay.conf: Enable exception hook Enabling Zephyr exception hook directs Zephyr exceptions dumps to debug_stream text message. Signed-off-by: Jyri Sarha --- app/debug_stream_overlay.conf | 8 ++++++++ 1 file changed, 8 insertions(+) diff --git a/app/debug_stream_overlay.conf b/app/debug_stream_overlay.conf index e3cb6834320e..c6899670e8b7 100644 --- a/app/debug_stream_overlay.conf +++ b/app/debug_stream_overlay.conf @@ -6,6 +6,8 @@ CONFIG_SOF_DEBUG_STREAM_TEXT_MSG=y CONFIG_SOF_DEBUG_STREAM_THREAD_INFO=y # Zephyr option for storing human readable thread names CONFIG_THREAD_NAME=y +# For Zephyr to compile with thread names on PTL we need to increase THREAD_BYTES +CONFIG_MAX_THREAD_BYTES=4 # Debug window slot configuration 1 # The CONFIG_SOF_TELEMETRY uses slot 2, but with performance and IO-performance @@ -20,3 +22,9 @@ CONFIG_SOF_TELEMETRY_IO_PERFORMANCE_MEASUREMENTS=n #CONFIG_SOF_TELEMETRY_PERFORMANCE_MEASUREMENTS=n #CONFIG_SOF_TELEMETRY_IO_PERFORMANCE_MEASUREMENTS=n +# Enable Zephyr exception printing hook, debug stream is sensitive to this option too +CONFIG_EXCEPTION_DUMP_HOOK=y +# Do not try to sen the exception prints through logs, this causes probles on PTL with mtrace +CONFIG_EXCEPTION_DUMP_HOOK_ONLY=y +# Print also backtrace through the exception hook +CONFIG_XTENSA_BACKTRACE_EXCEPTION_DUMP_HOOK=y