From c9cf11cd1cc5b38f89ef370c8fc2633d5638b8f7 Mon Sep 17 00:00:00 2001 From: Samuel Obuch Date: Mon, 28 Apr 2025 15:58:35 +0200 Subject: [PATCH] ci: enable sysview examples for all chips --- examples/system/.build-test-rules.yml | 19 +- .../sysview_tracing/main/sysview_tracing.c | 4 +- .../sysview_tracing/pytest_sysview_tracing.py | 195 +++++++++++++++--- .../system/sysview_tracing/sdkconfig.defaults | 2 - .../main/sysview_heap_log.c | 2 + .../pytest_sysview_tracing_heap_log.py | 181 +++++++++++++--- 6 files changed, 335 insertions(+), 68 deletions(-) diff --git a/examples/system/.build-test-rules.yml b/examples/system/.build-test-rules.yml index 636f2ce2b5..788150186c 100644 --- a/examples/system/.build-test-rules.yml +++ b/examples/system/.build-test-rules.yml @@ -259,17 +259,32 @@ examples/system/sysview_tracing: disable: - if: SOC_GPTIMER_SUPPORTED != 1 disable_test: - - if: IDF_TARGET != "esp32" + - if: IDF_TARGET == "esp32p4" temporary: true reason: lack of runners + - if: IDF_TARGET == "esp32h21" + temporary: true + reason: not supported yet #TODO: OCD-1082 + - if: IDF_TARGET == "esp32h4" + temporary: true + reason: not supported yet #TODO: OCD-1136 examples/system/sysview_tracing_heap_log: disable: - if: SOC_GPTIMER_SUPPORTED != 1 disable_test: - - if: IDF_TARGET != "esp32" + - if: IDF_TARGET == "esp32p4" temporary: true reason: lack of runners + - if: IDF_TARGET == "esp32s3" + temporary: true + reason: unstable, known data corruption issue #TODO: OCD-992 + - if: IDF_TARGET == "esp32h21" + temporary: true + reason: not supported yet #TODO: OCD-1082 + - if: IDF_TARGET == "esp32h4" + temporary: true + reason: not supported yet #TODO: OCD-1136 examples/system/task_watchdog: disable: diff --git a/examples/system/sysview_tracing/main/sysview_tracing.c b/examples/system/sysview_tracing/main/sysview_tracing.c index 5a68888bfe..115224fb97 100644 --- a/examples/system/sysview_tracing/main/sysview_tracing.c +++ b/examples/system/sysview_tracing/main/sysview_tracing.c @@ -134,11 +134,13 @@ static void example_task(void *p) void app_main(void) { + ESP_LOGI(TAG, "Ready for OpenOCD connection"); + static example_event_data_t event_data[CONFIG_FREERTOS_NUMBER_OF_CORES]; #if CONFIG_APPTRACE_SV_ENABLE && CONFIG_USE_CUSTOM_EVENT_ID // Currently OpenOCD does not support requesting module info from target. So do the following... - // Wait untill SystemView module receives START command from host, + // Wait until SystemView module receives START command from host, // after that data can be sent to the host using onboard API, // so user module description does not need to be requested by OpenOCD itself. while (!SEGGER_SYSVIEW_Started()) { diff --git a/examples/system/sysview_tracing/pytest_sysview_tracing.py b/examples/system/sysview_tracing/pytest_sysview_tracing.py index 570d941039..015e030d55 100644 --- a/examples/system/sysview_tracing/pytest_sysview_tracing.py +++ b/examples/system/sysview_tracing/pytest_sysview_tracing.py @@ -1,48 +1,175 @@ # SPDX-FileCopyrightText: 2022-2025 Espressif Systems (Shanghai) CO LTD # SPDX-License-Identifier: Unlicense OR CC0-1.0 +import json +import logging +import os.path import re +import signal import time +from telnetlib import Telnet +from typing import Any +from typing import Optional -import pexpect.fdpexpect +import pexpect import pytest +from pytest_embedded.utils import to_bytes +from pytest_embedded.utils import to_str from pytest_embedded_idf import IdfDut from pytest_embedded_idf.utils import idf_parametrize +MAX_RETRIES = 3 +RETRY_DELAY = 1 +TELNET_PORT = 4444 + + +class OpenOCD: + def __init__(self, dut: 'IdfDut'): + self.dut = dut + self.telnet: Optional[Telnet] = None + self.log_file = os.path.join(self.dut.logdir, 'ocd.txt') + self.proc: Optional[pexpect.spawn] = None + + def run(self) -> Optional['OpenOCD']: + desc_path = os.path.join(self.dut.app.binary_path, 'project_description.json') + + try: + with open(desc_path, 'r') as f: + project_desc = json.load(f) + except FileNotFoundError: + logging.error('Project description file not found at %s', desc_path) + return None + + openocd_scripts = os.getenv('OPENOCD_SCRIPTS') + if not openocd_scripts: + logging.error('OPENOCD_SCRIPTS environment variable is not set.') + return None + + debug_args = project_desc.get('debug_arguments_openocd') + if not debug_args: + logging.error("'debug_arguments_openocd' key is missing in project_description.json") + return None + + # For debug purposes, make the value '4' + ocd_env = os.environ.copy() + ocd_env['LIBUSB_DEBUG'] = '1' + + for _ in range(1, MAX_RETRIES + 1): + try: + self.proc = pexpect.spawn( + command='openocd', + args=['-s', openocd_scripts] + debug_args.split(), + timeout=5, + encoding='utf-8', + codec_errors='ignore', + env=ocd_env, + ) + if self.proc and self.proc.isalive(): + self.proc.expect_exact('Info : Listening on port 3333 for gdb connections', timeout=5) + return self + except (pexpect.exceptions.EOF, pexpect.exceptions.TIMEOUT) as e: + logging.error('Error running OpenOCD: %s', str(e)) + if self.proc and self.proc.isalive(): + self.proc.terminate() + time.sleep(RETRY_DELAY) + + logging.error('Failed to run OpenOCD after %d attempts.', MAX_RETRIES) + return None + + def connect_telnet(self) -> None: + for attempt in range(1, MAX_RETRIES + 1): + try: + self.telnet = Telnet('127.0.0.1', TELNET_PORT, 5) + break + except ConnectionRefusedError as e: + logging.error('Error telnet connection: %s in attempt:%d', e, attempt) + time.sleep(1) + else: + raise ConnectionRefusedError + + def write(self, s: str) -> Any: + if self.telnet is None: + logging.error('Telnet connection is not established.') + return '' + resp = self.telnet.read_very_eager() + self.telnet.write(to_bytes(s, '\n')) + resp += self.telnet.read_until(b'>') + return to_str(resp) + + def apptrace_wait_stop(self, timeout: int = 30) -> None: + stopped = False + end_before = time.time() + timeout + while not stopped: + cmd_out = self.write('esp apptrace status') + for line in cmd_out.splitlines(): + if line.startswith('Tracing is STOPPED.'): + stopped = True + break + if not stopped and time.time() > end_before: + raise pexpect.TIMEOUT('Failed to wait for apptrace stop!') + time.sleep(1) + + def kill(self) -> None: + # Check if the process is still running + if self.proc and self.proc.isalive(): + self.proc.terminate() + self.proc.kill(signal.SIGKILL) + + +def _test_examples_sysview_tracing(dut: IdfDut) -> None: + # Construct trace log paths + trace_log = [ + os.path.join(dut.logdir, 'sys_log0.svdat') # pylint: disable=protected-access + ] + if not dut.app.sdkconfig.get('ESP_SYSTEM_SINGLE_CORE_MODE') or dut.target == 'esp32s3': + trace_log.append(os.path.join(dut.logdir, 'sys_log1.svdat')) # pylint: disable=protected-access + trace_files = ' '.join([f'file://{log}' for log in trace_log]) + + # Prepare gdbinit file + gdb_logfile = os.path.join(dut.logdir, 'gdb.txt') + gdbinit_orig = os.path.join(os.path.dirname(os.path.abspath(__file__)), 'gdbinit') + gdbinit = os.path.join(dut.logdir, 'gdbinit') + with open(gdbinit_orig, 'r') as f_r, open(gdbinit, 'w') as f_w: + for line in f_r: + if line.startswith('mon esp sysview start'): + f_w.write(f'mon esp sysview start {trace_files}\n') + else: + f_w.write(line) + + def dut_expect_task_event() -> None: + dut.expect(re.compile(rb'example: Task\[0x[0-9A-Fa-f]+\]: received event \d+'), timeout=30) + + dut.expect_exact('example: Ready for OpenOCD connection', timeout=5) + openocd = OpenOCD(dut).run() + assert openocd + try: + openocd.connect_telnet() + openocd.write('log_output {}'.format(openocd.log_file)) + + with open(gdb_logfile, 'w') as gdb_log, pexpect.spawn( + f'idf.py -B {dut.app.binary_path} gdb --batch -x {gdbinit}', + timeout=60, + logfile=gdb_log, + encoding='utf-8', + codec_errors='ignore', + ) as p: + p.expect_exact('hit Breakpoint 1, app_main ()') + dut.expect('example: Created task') # dut has been restarted by gdb since the last dut.expect() + dut_expect_task_event() + + # Do a sleep while sysview samples are captured. + time.sleep(3) + openocd.write('esp sysview stop') + finally: + openocd.kill() + @pytest.mark.jtag -@pytest.mark.parametrize( - 'embedded_services', - [ - 'esp,idf,jtag', - ], - indirect=True, -) -@idf_parametrize('target', ['esp32'], indirect=['target']) +@idf_parametrize('target', ['esp32', 'esp32c2', 'esp32s2'], indirect=['target']) def test_examples_sysview_tracing(dut: IdfDut) -> None: - def dut_expect_task_event() -> None: - dut.expect(re.compile(rb'example: Task\[0x3[0-9A-Fa-f]+\]: received event \d+'), timeout=30) + _test_examples_sysview_tracing(dut) - dut.gdb.write('mon reset halt') - dut.gdb.write('maintenance flush register-cache') - dut.gdb.write('b app_main') - dut.gdb.write('commands', non_blocking=True) - dut.gdb.write( - 'mon esp sysview start file:///tmp/sysview_example0.svdat file:///tmp/sysview_example1.svdat', non_blocking=True - ) - dut.gdb.write('c', non_blocking=True) - dut.gdb.write('end') - - dut.gdb.write('c', non_blocking=True) - time.sleep(1) # to avoid EOF file error - with open(dut.gdb._logfile, encoding='utf-8') as fr: # pylint: disable=protected-access - gdb_pexpect_proc = pexpect.fdpexpect.fdspawn(fr.fileno()) - gdb_pexpect_proc.expect('Thread 2 "main" hit Breakpoint 1, app_main ()') - - dut.expect('example: Created task') # dut has been restarted by gdb since the last dut.expect() - dut_expect_task_event() - - # Do a sleep while sysview samples are captured. - time.sleep(3) - # GDB isn't responding now to any commands, therefore, the following command is issued to openocd - dut.openocd.write('esp sysview stop') +@pytest.mark.usb_serial_jtag +@idf_parametrize('target', ['esp32s3', 'esp32c3', 'esp32c5', 'esp32c6', 'esp32c61', 'esp32h2'], indirect=['target']) +def test_examples_sysview_tracing_usj(dut: IdfDut) -> None: + _test_examples_sysview_tracing(dut) diff --git a/examples/system/sysview_tracing/sdkconfig.defaults b/examples/system/sysview_tracing/sdkconfig.defaults index d93b1caeb7..a08cc7e128 100644 --- a/examples/system/sysview_tracing/sdkconfig.defaults +++ b/examples/system/sysview_tracing/sdkconfig.defaults @@ -1,5 +1,3 @@ -# Enable single core mode by default -CONFIG_FREERTOS_UNICORE=y # 1ms tick period CONFIG_FREERTOS_HZ=1000 # Enable application tracing by default diff --git a/examples/system/sysview_tracing_heap_log/main/sysview_heap_log.c b/examples/system/sysview_tracing_heap_log/main/sysview_heap_log.c index 87b0031d07..aecf041da5 100644 --- a/examples/system/sysview_tracing_heap_log/main/sysview_heap_log.c +++ b/examples/system/sysview_tracing_heap_log/main/sysview_heap_log.c @@ -73,6 +73,8 @@ static void alloc_task(void *p) void app_main(void) { + ESP_LOGI(TAG, "Ready for OpenOCD connection"); + const int num_allocers = 3; char task_name[20]; // redirect log messages to the host using SystemView tracing module diff --git a/examples/system/sysview_tracing_heap_log/pytest_sysview_tracing_heap_log.py b/examples/system/sysview_tracing_heap_log/pytest_sysview_tracing_heap_log.py index 79871369d5..748733e202 100644 --- a/examples/system/sysview_tracing_heap_log/pytest_sysview_tracing_heap_log.py +++ b/examples/system/sysview_tracing_heap_log/pytest_sysview_tracing_heap_log.py @@ -1,48 +1,157 @@ # SPDX-FileCopyrightText: 2022-2025 Espressif Systems (Shanghai) CO LTD # SPDX-License-Identifier: Unlicense OR CC0-1.0 +import json +import logging import os.path +import signal import time +from telnetlib import Telnet +from typing import Any +from typing import Optional import pexpect.fdpexpect import pytest +from pytest_embedded.utils import to_bytes +from pytest_embedded.utils import to_str from pytest_embedded_idf import IdfDut from pytest_embedded_idf.utils import idf_parametrize +MAX_RETRIES = 3 +RETRY_DELAY = 1 +TELNET_PORT = 4444 -@pytest.mark.jtag -@pytest.mark.parametrize('config', ['app_trace_jtag'], indirect=True) -@pytest.mark.parametrize('embedded_services', ['esp,idf,jtag'], indirect=True) -@idf_parametrize('target', ['esp32'], indirect=['target']) -def test_examples_sysview_tracing_heap_log(idf_path: str, dut: IdfDut) -> None: + +class OpenOCD: + def __init__(self, dut: 'IdfDut'): + self.dut = dut + self.telnet: Optional[Telnet] = None + self.log_file = os.path.join(self.dut.logdir, 'ocd.txt') + self.proc: Optional[pexpect.spawn] = None + + def run(self) -> Optional['OpenOCD']: + desc_path = os.path.join(self.dut.app.binary_path, 'project_description.json') + + try: + with open(desc_path, 'r') as f: + project_desc = json.load(f) + except FileNotFoundError: + logging.error('Project description file not found at %s', desc_path) + return None + + openocd_scripts = os.getenv('OPENOCD_SCRIPTS') + if not openocd_scripts: + logging.error('OPENOCD_SCRIPTS environment variable is not set.') + return None + + debug_args = project_desc.get('debug_arguments_openocd') + if not debug_args: + logging.error("'debug_arguments_openocd' key is missing in project_description.json") + return None + + # For debug purposes, make the value '4' + ocd_env = os.environ.copy() + ocd_env['LIBUSB_DEBUG'] = '1' + + for _ in range(1, MAX_RETRIES + 1): + try: + self.proc = pexpect.spawn( + command='openocd', + args=['-s', openocd_scripts] + debug_args.split(), + timeout=5, + encoding='utf-8', + codec_errors='ignore', + env=ocd_env, + ) + if self.proc and self.proc.isalive(): + self.proc.expect_exact('Info : Listening on port 3333 for gdb connections', timeout=5) + return self + except (pexpect.exceptions.EOF, pexpect.exceptions.TIMEOUT) as e: + logging.error('Error running OpenOCD: %s', str(e)) + if self.proc and self.proc.isalive(): + self.proc.terminate() + time.sleep(RETRY_DELAY) + + logging.error('Failed to run OpenOCD after %d attempts.', MAX_RETRIES) + return None + + def connect_telnet(self) -> None: + for attempt in range(1, MAX_RETRIES + 1): + try: + self.telnet = Telnet('127.0.0.1', TELNET_PORT, 5) + break + except ConnectionRefusedError as e: + logging.error('Error telnet connection: %s in attempt:%d', e, attempt) + time.sleep(1) + else: + raise ConnectionRefusedError + + def write(self, s: str) -> Any: + if self.telnet is None: + logging.error('Telnet connection is not established.') + return '' + resp = self.telnet.read_very_eager() + self.telnet.write(to_bytes(s, '\n')) + resp += self.telnet.read_until(b'>') + return to_str(resp) + + def apptrace_wait_stop(self, timeout: int = 30) -> None: + stopped = False + end_before = time.time() + timeout + while not stopped: + cmd_out = self.write('esp apptrace status') + for line in cmd_out.splitlines(): + if line.startswith('Tracing is STOPPED.'): + stopped = True + break + if not stopped and time.time() > end_before: + raise pexpect.TIMEOUT('Failed to wait for apptrace stop!') + time.sleep(1) + + def kill(self) -> None: + # Check if the process is still running + if self.proc and self.proc.isalive(): + self.proc.terminate() + self.proc.kill(signal.SIGKILL) + + +def _test_examples_sysview_tracing_heap_log(idf_path: str, dut: IdfDut) -> None: # Construct trace log paths trace_log = [ - os.path.join(os.path.dirname(dut.gdb._logfile), 'heap_log0.svdat') # pylint: disable=protected-access + os.path.join(dut.logdir, 'heap_log0.svdat') # pylint: disable=protected-access ] - if dut.target in ['esp32', 'esp32s3', 'esp32p4']: - trace_log.append(os.path.join(os.path.dirname(dut.gdb._logfile), 'heap_log1.svdat')) # pylint: disable=protected-access - - # Set up GDB - dut.gdb.write('set width unlimited') # Don't split output lines for easy parsing - dut.gdb.write('mon reset halt') - dut.gdb.write('maintenance flush register-cache') - - # Start sysview tracing - dut.gdb.write('tb heap_trace_start') - dut.gdb.write('commands', non_blocking=True) + if not dut.app.sdkconfig.get('ESP_SYSTEM_SINGLE_CORE_MODE') or dut.target == 'esp32s3': + trace_log.append(os.path.join(dut.logdir, 'heap_log1.svdat')) # pylint: disable=protected-access trace_files = ' '.join([f'file://{log}' for log in trace_log]) - dut.gdb.write(f'mon esp sysview start {trace_files}', non_blocking=True) - dut.gdb.write('c', non_blocking=True) - dut.gdb.write('end') - # Stop sysview tracing - dut.gdb.write('tb heap_trace_stop') - dut.gdb.write('commands', non_blocking=True) - dut.gdb.write('mon esp sysview stop', non_blocking=True) - dut.gdb.write('end') - dut.gdb.write('c', non_blocking=True) + # Prepare gdbinit file + gdb_logfile = os.path.join(dut.logdir, 'gdb.txt') + gdbinit_orig = os.path.join(os.path.dirname(os.path.abspath(__file__)), 'gdbinit') + gdbinit = os.path.join(dut.logdir, 'gdbinit') + with open(gdbinit_orig, 'r') as f_r, open(gdbinit, 'w') as f_w: + for line in f_r: + if line.startswith('mon esp sysview start'): + f_w.write(f'mon esp sysview start {trace_files}\n') + else: + f_w.write(line) - # Wait for sysview files to be generated - time.sleep(1) + dut.expect_exact('example: Ready for OpenOCD connection', timeout=5) + openocd = OpenOCD(dut).run() + assert openocd + try: + openocd.connect_telnet() + openocd.write('log_output {}'.format(openocd.log_file)) + + with open(gdb_logfile, 'w') as gdb_log, pexpect.spawn( + f'idf.py -B {dut.app.binary_path} gdb --batch -x {gdbinit}', + timeout=60, + logfile=gdb_log, + encoding='utf-8', + codec_errors='ignore', + ) as p: + # Wait for sysview files to be generated + p.expect_exact('Tracing is STOPPED') + finally: + openocd.kill() # Process sysview trace logs command = [os.path.join(idf_path, 'tools', 'esp_app_trace', 'sysviewtrace_proc.py'), '-p'] + trace_log @@ -50,9 +159,23 @@ def test_examples_sysview_tracing_heap_log(idf_path: str, dut: IdfDut) -> None: sysviewtrace.expect(r'Found \d+ leaked bytes in \d+ blocks.', timeout=120) # Validate GDB logs - with open(dut.gdb._logfile, encoding='utf-8') as fr: # pylint: disable=protected-access + with open(gdb_logfile, encoding='utf-8') as fr: # pylint: disable=protected-access gdb_pexpect_proc = pexpect.fdpexpect.fdspawn(fr.fileno()) gdb_pexpect_proc.expect_exact( 'Thread 2 "main" hit Temporary breakpoint 1, heap_trace_start (mode_param', timeout=10 ) # should be (mode_param=HEAP_TRACE_ALL) # TODO GCC-329 gdb_pexpect_proc.expect_exact('Thread 2 "main" hit Temporary breakpoint 2, heap_trace_stop ()', timeout=10) + + +@pytest.mark.parametrize('config', ['app_trace_jtag'], indirect=True) +@pytest.mark.jtag +@idf_parametrize('target', ['esp32', 'esp32c2', 'esp32s2'], indirect=['target']) +def test_examples_sysview_tracing_heap_log(idf_path: str, dut: IdfDut) -> None: + _test_examples_sysview_tracing_heap_log(idf_path, dut) + + +@pytest.mark.parametrize('config', ['app_trace_jtag'], indirect=True) +@pytest.mark.usb_serial_jtag +@idf_parametrize('target', ['esp32c3', 'esp32c5', 'esp32c6', 'esp32c61', 'esp32h2'], indirect=['target']) +def test_examples_sysview_tracing_heap_log_usj(idf_path: str, dut: IdfDut) -> None: + _test_examples_sysview_tracing_heap_log(idf_path, dut)