From f2274ef81fc298144db96881bc0b2e4df66c5855 Mon Sep 17 00:00:00 2001 From: Jyri Sarha Date: Wed, 18 Sep 2024 20:13:40 +0300 Subject: [PATCH 1/4] tools: debug_stream.py: Access debug slot directly using cavstool.py Access debug slot directly using cavstool.py, by specifying the debug slot number where the debug_stream data is transferred. Adds one command line parameter for selecting the debug slot directly and adds an alternative mainloop for polling the slot through cavstool.py direct access. The commit also adds quite a few data consistency checks and error handling improvements as with the direct memory access its much more likely to get inconsistent data when the DSP is booting up, and code needs to be robust enough not to crash in such a situation. Also the logging messages about those checks failing has been lowered so that they are not too noisy. Signed-off-by: Jyri Sarha --- tools/debug_stream/debug_stream.py | 66 +++++++++++++++++++++++++++--- 1 file changed, 61 insertions(+), 5 deletions(-) diff --git a/tools/debug_stream/debug_stream.py b/tools/debug_stream/debug_stream.py index 717845dc49e5..bde98bd9c796 100644 --- a/tools/debug_stream/debug_stream.py +++ b/tools/debug_stream/debug_stream.py @@ -10,6 +10,7 @@ import argparse import ctypes import time +import sys import logging @@ -18,6 +19,7 @@ ) DEBUG_STREAM_PAYLOAD_MAGIC = 0x1ED15EED +DEBUG_SLOT_SIZE = 4096 # TODO: python construct would probably be cleaner than ctypes structs @@ -225,7 +227,7 @@ def get_hdr(self, slot, pos): slot[self.boffset + pos * WSIZE :], ctypes.POINTER(DebugStreamRecord) ).contents if header.id > 100 or header.size_words >= self.buf_words: - logging.warning( + logging.info( "Broken record id %u seqno %u size %u", header.id, header.seqno, @@ -286,7 +288,7 @@ def catch_up(self, slot): self.decode_past_records(slot, circ.w_ptr, circ.next_seqno) self.prev_w_ptr = circ.w_ptr self.prev_seqno = circ.next_seqno - 1 - logging.info("seqno %u w_ptr %u", self.prev_seqno, self.prev_w_ptr) + logging.debug("seqno %u w_ptr %u", self.prev_seqno, self.prev_w_ptr) def decode_past_records(self, slot, pos, seqno): """ @@ -373,7 +375,7 @@ class DebugStreamDecoder: Class for decoding debug-stream slot contents """ - file_size = 4096 # ADSP debug slot size + file_size = DEBUG_SLOT_SIZE file = None slot = None descs = [] @@ -393,6 +395,12 @@ def update_slot(self): self.file.seek(0) self.slot = self.file.read(self.file_size) + def set_slot(self, buf): + """ + Update slot contents + """ + self.slot = buf + def get_descriptors(self): """ Read the core specific descriptors and initialize core @@ -403,15 +411,26 @@ def get_descriptors(self): return False hdr = ctypes.cast(self.slot, ctypes.POINTER(DebugStreamSlotHdr)) if hdr.contents.hdr.magic != DEBUG_STREAM_PAYLOAD_MAGIC: - logging.warning("Debug Slot has bad magic 0x%08x", hdr.contents.hdr.magic) + logging.info("Debug Slot has bad magic 0x%08x", hdr.contents.hdr.magic) return False num_sections = hdr.contents.num_sections if num_sections == len(self.descs): return True + if num_sections > 32: + logging.info("Suspiciously many sections %u", num_sections) + return False hsize = ctypes.sizeof(DebugStreamSlotHdr) self.descs = (DebugStreamSectionDescriptor * num_sections).from_buffer_copy( self.slot, hsize ) + for i in range(len(self.descs)): + if (self.descs[i].core_id > 32 or + self.descs[i].buf_words > DEBUG_SLOT_SIZE // WSIZE or + self.descs[i].offset > DEBUG_SLOT_SIZE): + logging.info("Suspicious descriptor %u values %u %u %u", i, + self.descs[i].core_id, self.descs[i].buf_words, + self.descs[i].offset) + return False self.circdec = [ CircularBufferDecoder(self.descs[i], i, self.rec_printer) for i in range(len(self.descs)) @@ -473,6 +492,33 @@ def reset(self): self.file = None self.slot = None +def cavstool_main_loop(my_args): + import cavstool + try: + (hda, sd, dsp, hda_ostream_id) = cavstool.map_regs(True) + except Exception as e: + logging.error("Could not map device in sysfs; run as root?") + logging.error(e) + sys.exit(1) + ADSP_DW_SLOT_DEBUG_STREAM = 0x53523134 + decoder = DebugStreamDecoder() + while True: + if not cavstool.fw_is_alive(dsp): + cavstool.wait_fw_entered(dsp, timeout_s=None) + offset = cavstool.debug_slot_offset(my_args.direct_access_slot) + buf = cavstool.win_read(offset, 0, DEBUG_SLOT_SIZE) + decoder.set_slot(buf) + if not decoder.get_descriptors(): + time.sleep(my_args.update_interval) + continue + decoder.catch_up_all() + while True: + if decoder.poll(): + time.sleep(my_args.update_interval) + buf = cavstool.win_read(offset, 0, DEBUG_SLOT_SIZE) + decoder.set_slot(buf) + if not decoder.check_slot(): + break def main_f(my_args): """ @@ -483,6 +529,8 @@ def main_f(my_args): about the host CPU load. That is why there where no synchronous mechanism done and the host simply polls for new records. """ + if my_args.direct_access_slot >= 0: + return cavstool_main_loop(my_args) decoder = DebugStreamDecoder() prev_error = None while True: @@ -491,7 +539,8 @@ def main_f(my_args): decoder.set_file(file) decoder.update_slot() if not decoder.get_descriptors(): - break + time.sleep(my_args.update_interval) + continue decoder.catch_up_all() while True: if decoder.poll(): @@ -527,6 +576,13 @@ def parse_params(): help="File to read the DebugStream data from, default /sys/kernel/debug/sof/debug_stream", default="/sys/kernel/debug/sof/debug_stream", ) + parser.add_argument( + "-c", + "--direct-access-slot", + help="Access specified debug window slot directly, no need for debugfs file", + type=int, + default=-1, + ) parsed_args = parser.parse_args() return parsed_args From 0b1c4d1cc4af1d173cd5c123241a37e6fa0ee529 Mon Sep 17 00:00:00 2001 From: Jyri Sarha Date: Mon, 23 Sep 2024 23:27:59 +0300 Subject: [PATCH 2/4] app: add new debug_stream_overlay.conf Add overlay to build debug_stream protocol over a debug window slot, make room for the slot, and send thread info data through it. Signed-off-by: Jyri Sarha --- app/debug_stream_overlay.conf | 20 ++++++++++++++++++++ 1 file changed, 20 insertions(+) create mode 100644 app/debug_stream_overlay.conf diff --git a/app/debug_stream_overlay.conf b/app/debug_stream_overlay.conf new file mode 100644 index 000000000000..0195e5070b33 --- /dev/null +++ b/app/debug_stream_overlay.conf @@ -0,0 +1,20 @@ +# Enable debug-stream protocol +CONFIG_SOF_DEBUG_STREAM_SLOT=y +# Add thread_info-client for debug stream +CONFIG_SOF_DEBUG_STREAM_THREAD_INFO=y +# Zephyr option for storing human readable thread names +CONFIG_THREAD_NAME=y + +# Debug window slot configuration 1 +# The CONFIG_SOF_TELEMETRY uses slot 2, but with performance and IO-performance +# it extends beyond slot 3. +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 +#CONFIG_SOF_DEBUG_STREAM_SLOT_NUMBER=2 +#CONFIG_SOF_TELEMETRY=n +#CONFIG_SOF_TELEMETRY_PERFORMANCE_MEASUREMENTS=n +#CONFIG_SOF_TELEMETRY_IO_PERFORMANCE_MEASUREMENTS=n + From 49e74b9c6269d2c087ad467271ef136cd5b008a7 Mon Sep 17 00:00:00 2001 From: Jyri Sarha Date: Wed, 25 Sep 2024 15:44:16 +0300 Subject: [PATCH 3/4] debug: debug_stream_slot: A simple typo fix to a logging message A simple typo fix to a logging message. Signed-off-by: Jyri Sarha --- src/debug/debug_stream/debug_stream_slot.c | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/debug/debug_stream/debug_stream_slot.c b/src/debug/debug_stream/debug_stream_slot.c index bf8a593a348e..349eb2693137 100644 --- a/src/debug/debug_stream/debug_stream_slot.c +++ b/src/debug/debug_stream/debug_stream_slot.c @@ -109,7 +109,7 @@ static int debug_stream_slot_init(void) size_t offset = hdr_size; int i; - LOG_INF("%u sections of %u bytes, hdr %u, secton area %u\n", + LOG_INF("%u sections of %u bytes, hdr %u, section area %u\n", CONFIG_MP_MAX_NUM_CPUS, section_size, hdr_size, section_area_size); From edeff091282673a35cbb9915b2e2ed238b272943 Mon Sep 17 00:00:00 2001 From: Jyri Sarha Date: Thu, 26 Sep 2024 16:44:43 +0300 Subject: [PATCH 4/4] tools: debug_stream.py: Use cavstool.debug_slot_offset_by_type() The new cavstool.debug_slot_offset_by_type() opens an opportunity to improve debug_stream.py usability a bit. If the debugfs file is not found, then try to find the correct debug slot the correct slot using cavstool direct access and debug_slot_offset_by_type(). Signed-off-by: Jyri Sarha --- tools/debug_stream/debug_stream.py | 13 +++++++++++-- 1 file changed, 11 insertions(+), 2 deletions(-) diff --git a/tools/debug_stream/debug_stream.py b/tools/debug_stream/debug_stream.py index bde98bd9c796..752e53a92d1f 100644 --- a/tools/debug_stream/debug_stream.py +++ b/tools/debug_stream/debug_stream.py @@ -11,6 +11,7 @@ import ctypes import time import sys +import os import logging @@ -505,7 +506,15 @@ def cavstool_main_loop(my_args): while True: if not cavstool.fw_is_alive(dsp): cavstool.wait_fw_entered(dsp, timeout_s=None) - offset = cavstool.debug_slot_offset(my_args.direct_access_slot) + if my_args.direct_access_slot < 0: + offset = cavstool.debug_slot_offset_by_type(ADSP_DW_SLOT_DEBUG_STREAM) + if offset is None: + logging.error("Could not find debug_stream slot") + sys.exit(1) + logging.info("Got offset 0x%08x by type 0x%08x", offset, + ADSP_DW_SLOT_DEBUG_STREAM) + else: + offset = cavstool.debug_slot_offset(my_args.direct_access_slot) buf = cavstool.win_read(offset, 0, DEBUG_SLOT_SIZE) decoder.set_slot(buf) if not decoder.get_descriptors(): @@ -529,7 +538,7 @@ def main_f(my_args): about the host CPU load. That is why there where no synchronous mechanism done and the host simply polls for new records. """ - if my_args.direct_access_slot >= 0: + if my_args.direct_access_slot >= 0 or not os.path.isfile(my_args.debugstream_file): return cavstool_main_loop(my_args) decoder = DebugStreamDecoder() prev_error = None