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 136858968163dab8fa63cbb642625c94c60cf6fa 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 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 not 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 look 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 | 105 ++++++++++++++++++ 1 file changed, 105 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..b0d519266f11 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,104 @@ 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[CONFIG_MP_MAX_NUM_CPUS]; +static int reports_sent_cpu[CONFIG_MP_MAX_NUM_CPUS]; +static size_t ds_pos[CONFIG_MP_MAX_NUM_CPUS]; + +static void ds_exception_drain(bool flush) +{ + unsigned int cpu = arch_proc_id(); + + if (cpu >= CONFIG_MP_MAX_NUM_CPUS) + return; + + if (flush) { + ds_pos[cpu] = 0; + reports_sent_cpu[cpu] = 0; + return; + } + + if (ds_pos[cpu] == 0) + return; + + if (reports_sent_cpu[cpu] > 0) + return; + + ds_buf[cpu].msg.hdr.id = DEBUG_STREAM_RECORD_ID_TEXT_MSG; + ds_buf[cpu].msg.hdr.size_words = + SOF_DIV_ROUND_UP(sizeof(ds_buf[cpu].msg) + ds_pos[cpu], + sizeof(ds_buf[cpu].msg.hdr.data[0])); + /* Make sure the possible up to 3 extra bytes at end of msg are '\0' */ + memset(ds_buf[cpu].text + ds_pos[cpu], 0, + ds_buf[cpu].msg.hdr.size_words * sizeof(ds_buf[cpu].msg.hdr.data[0]) - ds_pos[cpu]); + debug_stream_slot_send_record(&ds_buf[cpu].msg.hdr); + reports_sent_cpu[cpu] = 1; + ds_pos[cpu] = 0; +} + +static void ds_exception_dump(const char *format, va_list args) +{ + ssize_t len; + size_t avail; + size_t written; + unsigned int cpu = arch_proc_id(); + + if (cpu >= CONFIG_MP_MAX_NUM_CPUS) + return; + + if (reports_sent_cpu[cpu] > 0) + return; + + avail = sizeof(ds_buf[cpu].text) - ds_pos[cpu]; + if (avail == 0) { + ds_exception_drain(false); + return; + } + + if (format[0] == '\0') + return; + + len = vsnprintf(ds_buf[cpu].text + ds_pos[cpu], avail, format, args); + if (len < 0) { + ds_pos[cpu] = 0; + return; + } + + if (len == 0) + return; + + if ((size_t)len >= avail) + written = avail - 1; + else + written = (size_t)len; + + ds_pos[cpu] += written; + + if (ds_pos[cpu] >= sizeof(ds_buf[cpu].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 6854c28c4627ec4fbd3ac1a4a461fc3aeaddb6dc 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 b0d519266f11..a563215a2af2 100644 --- a/src/debug/debug_stream/debug_stream_text_msg.c +++ b/src/debug/debug_stream/debug_stream_text_msg.c @@ -109,6 +109,11 @@ static void ds_exception_dump(const char *format, va_list args) if (format[0] == '\0') 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[cpu].text + ds_pos[cpu], avail, format, args); if (len < 0) { ds_pos[cpu] = 0; From dbb88d75189b443b04b910d4509594660f9ec4fe 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 4ba333c3d41a4de42384123f5c3e4ca9b5fd4df9 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 | 10 +++++++++- 1 file changed, 9 insertions(+), 1 deletion(-) diff --git a/app/debug_stream_overlay.conf b/app/debug_stream_overlay.conf index e3cb6834320e..cd310b9a7fa8 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 @@ -14,9 +16,15 @@ CONFIG_MEMORY_WIN_2_SIZE=16384 CONFIG_SOF_TELEMETRY_PERFORMANCE_MEASUREMENTS=n CONFIG_SOF_TELEMETRY_IO_PERFORMANCE_MEASUREMENTS=n -# If we turn telemetry off all together, we can use slot 2. Slot 1 is used by mtrace +# If we turn telemetry off altogether, we can use slot 2. Slot 1 is used by mtrace #CONFIG_SOF_DEBUG_STREAM_SLOT_NUMBER=2 #CONFIG_SOF_TELEMETRY=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 send exception prints through logs; this causes problems on PTL with mtrace +CONFIG_EXCEPTION_DUMP_HOOK_ONLY=y +# Print also backtrace through the exception hook +CONFIG_XTENSA_BACKTRACE_EXCEPTION_DUMP_HOOK=y