Skip to content

Exception dump hook #10517

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
lgirdwood merged 5 commits into from
Mar 12, 2026
+121 −14
Merged

Exception dump hook #10517

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
5 commits
Select commit Hold shift + click to select a range
ba001a4
debug: debug_stream_slot: Use spinlock instead of mutex for ISR
Feb 2, 2026
809a04d
debug_stream: text_msg: Set exception dump hooks if available
Feb 2, 2026
56104c5
debug_stream: text_msg: exception: Skip useless " ** " prefix
Feb 10, 2026
06ce324
tools: debug_stream.py: Cut text msg when first '\0' is encountered
Mar 3, 2026
4b39680
app: debug_stream_overlay.conf: Enable exception hook
Mar 3, 2026
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
10 changes: 9 additions & 1 deletion app/debug_stream_overlay.conf
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand All @@ -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
Copy link
Collaborator

@kv2019i kv2019i Mar 9, 2026

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Hmm, this is ok for this overlay, but needs attention when/if we try to make this the default. The CI systems we have in place do not have debugstream runnign on DUTs, only mtrace, so this would in effect make dumps unavailable in CI.

Copy link
Contributor Author

@jsarha jsarha Mar 11, 2026

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I should probably test still if this is needed, but with the earlier version it looked like on PTL the dumping hung in the middle of the logging was used.

Copy link
Contributor Author

@jsarha jsarha Mar 12, 2026 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yep, the normal dumping still hangs on PTL after first line if logging is on.

# Print also backtrace through the exception hook
CONFIG_XTENSA_BACKTRACE_EXCEPTION_DUMP_HOOK=y
16 changes: 5 additions & 11 deletions src/debug/debug_stream/debug_stream_slot.c
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -10,11 +10,12 @@
#include <rtos/string.h>
#include <user/debug_stream.h>
#include <user/debug_stream_slot.h>
#include <zephyr/kernel.h>

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 */
Expand Down Expand Up @@ -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);

Expand All @@ -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 */
Expand Down Expand Up @@ -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;
Expand Down Expand Up @@ -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]));
*/
Copy link
Collaborator

@lyakh lyakh Feb 5, 2026

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

k_spinlock_init()

Copy link
Contributor Author

@jsarha jsarha Feb 10, 2026 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Hrm, I forgot that I already checked first time around that Zephyr spinlocks do not have such function or anything like it.

Copy link
Collaborator

@lyakh lyakh Mar 5, 2026

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

SOF has one

sof/zephyr/include/rtos/spinlock.h

Line 13 in a32d983

static inline void k_spinlock_init(struct k_spinlock *lock)
- you need it if you re-initialise a spinlock, or in fact if your spinlock isn't zero-initialised at all

Copy link
Collaborator

@kv2019i kv2019i Mar 9, 2026

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It's arguably quite confusing we use Zephyr native calls, but have a SOF extension. I'd only use k_spinlock_init if we really need to re-initialize.

}
LOG_INF("Debug stream slot initialized");

Expand Down
104 changes: 104 additions & 0 deletions src/debug/debug_stream/debug_stream_text_msg.c
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -8,9 +8,13 @@
#include <soc.h>
#include <adsp_debug_window.h>
#include <sof/common.h>
#include <zephyr/logging/log.h>
#include <zephyr/arch/exception.h>

#include <user/debug_stream_text_msg.h>

LOG_MODULE_REGISTER(debug_stream_text_msg);

void ds_msg(const char *format, ...)
{
va_list args;
Expand All @@ -33,3 +37,103 @@ 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. On some situations the exceptions happen
* in bursts, and sending more than one record in short time 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 (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 (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;

/* 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;
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
5 changes: 3 additions & 2 deletions tools/debug_stream/debug_stream.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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):
Expand Down
Loading