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 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"); diff --git a/src/debug/debug_stream/debug_stream_text_msg.c b/src/debug/debug_stream/debug_stream_text_msg.c index 8933df03e6bb..8dea31e75236 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,88 @@ 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; + } + + /* 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; + 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 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):