From 5cea09fbdcc3dfc78b531d063d7cba6be30d093b Mon Sep 17 00:00:00 2001 From: Erhan Kurubas Date: Mon, 2 Feb 2026 13:37:52 +0100 Subject: [PATCH] fix(app_trace): implement uart TX without using ISR --- components/app_trace/port/port_uart.c | 89 +++++++------------ examples/system/.build-test-rules.yml | 12 +++ .../app_trace_basic/pytest_app_trace_basic.py | 8 +- examples/system/gcov/pytest_gcov.py | 1 + .../sysview_tracing/pytest_sysview_tracing.py | 79 +++++++++++----- .../sysview_tracing/sdkconfig.ci.sysview_uart | 2 + .../pytest_sysview_tracing_heap_log.py | 2 + 7 files changed, 111 insertions(+), 82 deletions(-) diff --git a/components/app_trace/port/port_uart.c b/components/app_trace/port/port_uart.c index fa81705320b..004bb8953f1 100644 --- a/components/app_trace/port/port_uart.c +++ b/components/app_trace/port/port_uart.c @@ -1,5 +1,5 @@ /* - * SPDX-FileCopyrightText: 2017-2025 Espressif Systems (Shanghai) CO LTD + * SPDX-FileCopyrightText: 2017-2026 Espressif Systems (Shanghai) CO LTD * * SPDX-License-Identifier: Apache-2.0 */ @@ -19,7 +19,6 @@ #include "soc/gpio_periph.h" #include "esp_rom_gpio.h" #include "hal/uart_ll.h" -#include "esp_intr_alloc.h" #include "esp_heap_caps.h" #include "esp_private/esp_clk_tree_common.h" #include "esp_private/esp_gpio_reserve.h" @@ -45,10 +44,8 @@ typedef struct { typedef struct { int inited; - volatile bool tx_busy; ///< TX busy flag uart_hal_context_t hal_ctx; ///< UART HAL context esp_apptrace_uart_rb_t tx_ring; ///< TX ring buffer - intr_handle_t intr_handle; ///< Interrupt handle /* TX message buffer */ uint8_t *tx_msg_buff; ///< TX message buffer to provide with get_up_buffer @@ -178,31 +175,6 @@ static esp_err_t ring_buffer_init(esp_apptrace_uart_rb_t *rb, uint32_t size) return ESP_OK; } -static void IRAM_ATTR esp_apptrace_uart_isr_handler(void *arg) -{ - esp_apptrace_uart_data_t *uart_data = arg; - esp_apptrace_uart_rb_t *rb = &uart_data->tx_ring; - - uint32_t intr_status = uart_hal_get_intsts_mask(&uart_data->hal_ctx); - - if (intr_status & UART_INTR_TXFIFO_EMPTY) { - uart_hal_clr_intsts_mask(&uart_data->hal_ctx, UART_INTR_TXFIFO_EMPTY); - - uint32_t to_send = ring_buffer_calc_to_send(rb, uart_data->tx_msg_buff_size); - if (to_send > 0) { - uint32_t written = 0; - uart_hal_write_txfifo(&uart_data->hal_ctx, &rb->buffer[rb->tail], to_send, &written); - ring_buffer_advance_tail(rb, written); - } - - /* If ring buffer is empty, disable TX interrupt */ - if (ring_buffer_data_len(rb) == 0) { - uart_ll_disable_intr_mask(uart_data->hal_ctx.dev, UART_INTR_TXFIFO_EMPTY); - uart_data->tx_busy = false; - } - } -} - static esp_err_t esp_apptrace_uart_init(void *hw_data, const esp_apptrace_config_t *config) { esp_err_t ret = ESP_ERR_INVALID_ARG; @@ -294,15 +266,6 @@ static esp_err_t esp_apptrace_uart_init(void *hw_data, const esp_apptrace_config uart_ll_disable_intr_mask(uart_data->hal_ctx.dev, UART_LL_INTR_MASK); uart_ll_clr_intsts_mask(uart_data->hal_ctx.dev, UART_LL_INTR_MASK); - /* Install interrupt handler */ - int intr_alloc_flags = 0; - ret = esp_intr_alloc(uart_periph_signal[uart_config->uart_num].irq, intr_alloc_flags, - esp_apptrace_uart_isr_handler, uart_data, &uart_data->intr_handle); - if (ret != ESP_OK) { - ESP_APPTRACE_LOGE("Failed to allocate interrupt: %s", esp_err_to_name(ret)); - goto err_alloc_intr; - } - /* Reset FIFOs */ uart_hal_rxfifo_rst(&uart_data->hal_ctx); uart_hal_txfifo_rst(&uart_data->hal_ctx); @@ -328,12 +291,9 @@ static esp_err_t esp_apptrace_uart_init(void *hw_data, const esp_apptrace_config } uart_data->inited |= 1 << core_id; - uart_data->tx_busy = false; return ESP_OK; -err_alloc_intr: - heap_caps_free(uart_data->tx_msg_buff); err_alloc_msg_buff: heap_caps_free(uart_data->tx_ring.buffer); err_init_ring_buff: @@ -373,6 +333,22 @@ static uint8_t *esp_apptrace_uart_up_buffer_get(void *hw_data, uint32_t size, es return uart_data->tx_msg_buff; } +static uint32_t esp_apptrace_uart_write_fifo(esp_apptrace_uart_data_t *uart_data, esp_apptrace_uart_rb_t *rb) +{ + if (uart_ll_get_txfifo_len(uart_data->hal_ctx.dev) == 0) { + /* FIFO is full. No blocking. */ + return 0; + } + uint32_t to_send = ring_buffer_calc_to_send(rb, 0); + if (to_send == 0) { + return 0; + } + uint32_t written = 0; + uart_hal_write_txfifo(&uart_data->hal_ctx, &rb->buffer[rb->tail], to_send, &written); + ring_buffer_advance_tail(rb, written); + return written; +} + static esp_err_t esp_apptrace_uart_up_buffer_put(void *hw_data, uint8_t *ptr, esp_apptrace_tmo_t *tmo) { esp_apptrace_uart_data_t *uart_data = hw_data; @@ -387,16 +363,13 @@ static esp_err_t esp_apptrace_uart_up_buffer_put(void *hw_data, uint8_t *ptr, es ring_buffer_put(rb, ptr, uart_data->tx_pending_msg_size); uart_data->tx_pending_msg_size = 0; - esp_apptrace_uart_unlock(uart_data); - - // Trigger transmission if not already in progress - if (!uart_data->tx_busy) { - uart_data->tx_busy = true; - /* Enable TX interrupt */ - uart_ll_clr_intsts_mask(uart_data->hal_ctx.dev, UART_INTR_TXFIFO_EMPTY); - uart_ll_ena_intr_mask(uart_data->hal_ctx.dev, UART_INTR_TXFIFO_EMPTY); + /* Flush ring buffer to UART FIFO */ + while (ring_buffer_data_len(rb) > 0 && esp_apptrace_uart_write_fifo(uart_data, rb) > 0) { + esp_rom_delay_us(100); } + esp_apptrace_uart_unlock(uart_data); + return ESP_OK; } @@ -479,20 +452,22 @@ static esp_err_t esp_apptrace_uart_flush_nolock(void *hw_data, uint32_t min_sz, return ESP_OK; } - /* Trigger transmission if there's data but not busy */ - if (pending > 0 && !uart_data->tx_busy) { - uart_data->tx_busy = true; - uart_ll_clr_intsts_mask(uart_data->hal_ctx.dev, UART_INTR_TXFIFO_EMPTY); - uart_ll_ena_intr_mask(uart_data->hal_ctx.dev, UART_INTR_TXFIFO_EMPTY); - } - - while (uart_data->tx_busy || ring_buffer_data_len(rb) > 0) { + /* Flush ring buffer to HW FIFO */ + while (ring_buffer_data_len(rb) > 0) { + esp_apptrace_uart_write_fifo(uart_data, rb); if (esp_apptrace_tmo_check(tmo) != ESP_OK) { return ESP_ERR_TIMEOUT; } esp_rom_delay_us(100); } + /* Wait until all data is flushed */ + while (uart_ll_get_txfifo_len(uart_data->hal_ctx.dev) < SOC_UART_FIFO_LEN) { + if (esp_apptrace_tmo_check(tmo) != ESP_OK) { + return ESP_ERR_TIMEOUT; + } + esp_rom_delay_us(100); + } return ESP_OK; } diff --git a/examples/system/.build-test-rules.yml b/examples/system/.build-test-rules.yml index 4996efe92b1..758b935c8f4 100644 --- a/examples/system/.build-test-rules.yml +++ b/examples/system/.build-test-rules.yml @@ -8,6 +8,9 @@ examples/system/app_trace_basic: - if: IDF_TARGET == "esp32h4" temporary: true reason: not supported yet #TODO: OCD-1137 + depends_components: + - esp_trace + - app_trace examples/system/base_mac_address: depends_components: @@ -79,6 +82,9 @@ examples/system/gcov: - if: IDF_TARGET == "esp32h4" temporary: true reason: not supported yet #TODO: OCD-1138 + depends_components: + - esp_trace + - app_trace examples/system/heap_task_tracking: disable: @@ -264,6 +270,9 @@ examples/system/sysview_tracing: - if: IDF_TARGET == "esp32h4" temporary: true reason: not supported yet #TODO: OCD-1136 + depends_components: + - esp_trace + - app_trace examples/system/sysview_tracing_heap_log: disable: @@ -275,6 +284,9 @@ examples/system/sysview_tracing_heap_log: - if: IDF_TARGET == "esp32h4" temporary: true reason: not supported yet #TODO: OCD-1136 + depends_components: + - esp_trace + - app_trace examples/system/task_watchdog: disable: diff --git a/examples/system/app_trace_basic/pytest_app_trace_basic.py b/examples/system/app_trace_basic/pytest_app_trace_basic.py index 0790edf528e..5adea1db06e 100644 --- a/examples/system/app_trace_basic/pytest_app_trace_basic.py +++ b/examples/system/app_trace_basic/pytest_app_trace_basic.py @@ -1,4 +1,4 @@ -# SPDX-FileCopyrightText: 2022-2025 Espressif Systems (Shanghai) CO LTD +# SPDX-FileCopyrightText: 2022-2026 Espressif Systems (Shanghai) CO LTD # SPDX-License-Identifier: Unlicense OR CC0-1.0 import os.path import time @@ -14,6 +14,7 @@ if typing.TYPE_CHECKING: def _test_examples_app_trace_basic(openocd_dut: 'OpenOCD', dut: IdfDut) -> None: + time.sleep(1) # Wait for the USJ port to be ready dut.expect_exact('example: Waiting for OpenOCD connection', timeout=5) with openocd_dut.run() as openocd: openocd.write('reset run') @@ -65,15 +66,14 @@ def test_examples_app_trace_basic_usj(openocd_dut: 'OpenOCD', dut: IdfDut) -> No @idf_parametrize('target', ['supported_targets'], indirect=['target']) def test_examples_app_trace_basic_uart(dut: IdfDut) -> None: dut.serial.close() - with serial.Serial(dut.serial.port, baudrate=1000000, timeout=10) as ser: + with serial.Serial(dut.serial.port, baudrate=1000000, timeout=3) as ser: apptrace_log = os.path.join(dut.logdir, 'apptrace_log_uart.txt') # pylint: disable=protected-access with open(apptrace_log, 'w+b') as f: start_time = time.time() while True: try: if ser.in_waiting: - data = ser.read(100) - f.write(data) + f.write(ser.read(ser.in_waiting)) if time.time() - start_time > 5: break except serial.SerialTimeoutException: diff --git a/examples/system/gcov/pytest_gcov.py b/examples/system/gcov/pytest_gcov.py index d32398835e4..d1e090d541c 100644 --- a/examples/system/gcov/pytest_gcov.py +++ b/examples/system/gcov/pytest_gcov.py @@ -108,6 +108,7 @@ def _test_gcov(openocd_dut: 'OpenOCD', dut: IdfDut) -> None: assert os.path.isfile(gcda_path), f'Expected .gcda file not found: {gcda_path}' print('Basic verification passed (all .gcda files exist)') + time.sleep(1) # Wait for the USJ port to be ready dut.expect_exact('example: Ready for OpenOCD connection', timeout=5) with openocd_dut.run() as openocd: openocd.write('reset run') diff --git a/examples/system/sysview_tracing/pytest_sysview_tracing.py b/examples/system/sysview_tracing/pytest_sysview_tracing.py index 8c0d2899903..0a3b1b58526 100644 --- a/examples/system/sysview_tracing/pytest_sysview_tracing.py +++ b/examples/system/sysview_tracing/pytest_sysview_tracing.py @@ -1,4 +1,4 @@ -# SPDX-FileCopyrightText: 2022-2025 Espressif Systems (Shanghai) CO LTD +# SPDX-FileCopyrightText: 2022-2026 Espressif Systems (Shanghai) CO LTD # SPDX-License-Identifier: Unlicense OR CC0-1.0 import os.path import re @@ -15,19 +15,71 @@ if typing.TYPE_CHECKING: from conftest import OpenOCD -def _validate_trace_data(trace_log: list[str], target: str) -> None: +def _validate_trace_data(trace_log: list[str], target: str, is_uart: bool = False) -> None: """Validate SysView trace data in log file(s). Args: trace_log: List of trace log paths target: Target chip name (e.g., 'esp32', 'esp32s3') + is_uart: If True, also validate STOP record at end of file """ + STOP_EVENT_ID = 0x0B # SYSVIEW_EVTID_TRACE_STOP + for idx, log in enumerate(trace_log): with open(log, 'rb') as f: content = f.read() search_str = f'N=FreeRTOS Application,D={target},C=core{idx},O=FreeRTOS'.encode() assert search_str in content, f'SysView trace data not found in {log}' + # For UART transport, validate STOP record at end of file + # TODO: Adapt this to JTAG as well. + if is_uart: + size = len(content) + assert size >= 2, 'Trace file too small to contain STOP record' + assert content[-2] == STOP_EVENT_ID, 'STOP record does not start with STOP eventID' + + +def _capture_sysview_trace(ser: serial.Serial, trace_log_path: str) -> None: + """Capture SysView trace data from serial port. + + Args: + ser: Serial port instance + trace_log_path: Path to save the trace log + """ + START_CMD = b'\x01' + STOP_CMD = b'\x02' + + ser.reset_input_buffer() + # Send Start command to start SysView tracing + ser.write(START_CMD) + + with open(trace_log_path, 'w+b') as f: + # Capture for 3 seconds + end_time = time.time() + 3.0 + while time.time() < end_time: + try: + if ser.in_waiting: + f.write(ser.read(ser.in_waiting)) + except serial.SerialTimeoutException: + assert False, 'Timeout reached while reading from serial port, exiting...' + + # Wait some time to let data accumulate in target's ring buffer + time.sleep(0.2) + + # Send Stop command + ser.write(STOP_CMD) + + # Capture until target flushed data or timeout (3 seconds) + end_time = time.time() + 3.0 + last_data_time = time.time() + while time.time() < end_time and (time.time() - last_data_time) <= 1.0: + try: + if ser.in_waiting: + f.write(ser.read(ser.in_waiting)) + last_data_time = time.time() + except serial.SerialTimeoutException: + assert False, 'Timeout reached while reading from serial port, exiting...' + def _test_sysview_tracing_jtag(openocd_dut: 'OpenOCD', dut: IdfDut) -> None: # Construct trace log paths @@ -52,6 +104,7 @@ def _test_sysview_tracing_jtag(openocd_dut: 'OpenOCD', dut: IdfDut) -> None: def dut_expect_task_event() -> None: dut.expect(re.compile(rb'example: Task\[0x[0-9A-Fa-f]+\]: received event \d+'), timeout=30) + time.sleep(1) # Wait for the USJ port to be ready dut.expect_exact('example: Hello from sysview_tracing example!', timeout=5) with ( openocd_dut.run() as openocd, @@ -94,26 +147,10 @@ def test_sysview_tracing_usj(openocd_dut: 'OpenOCD', dut: IdfDut) -> None: def _test_sysview_tracing_uart(dut: IdfDut) -> None: dut.serial.close() time.sleep(2) # Wait for the DUT to reboot - with serial.Serial(dut.serial.port, baudrate=dut.app.sdkconfig.get('APPTRACE_UART_BAUDRATE'), timeout=10) as ser: + with serial.Serial(dut.serial.port, baudrate=dut.app.sdkconfig.get('APPTRACE_UART_BAUDRATE'), timeout=3) as ser: trace_log = [os.path.join(dut.logdir, 'sys_log_uart.svdat')] # pylint: disable=protected-access - # Send Start command to start SysView tracing - ser.write(b'\x01') - with open(trace_log[0], 'w+b') as f: - start_time = time.time() - while True: - try: - if ser.in_waiting: - data = ser.read(1024) - f.write(data) - if time.time() - start_time > 3: - break - except serial.SerialTimeoutException: - assert False, 'Timeout reached while reading from serial port, exiting...' - - # Send Stop command - ser.write(b'\x02') - - _validate_trace_data(trace_log, dut.target) + _capture_sysview_trace(ser, trace_log[0]) + _validate_trace_data(trace_log, dut.target, is_uart=True) @pytest.mark.generic diff --git a/examples/system/sysview_tracing/sdkconfig.ci.sysview_uart b/examples/system/sysview_tracing/sdkconfig.ci.sysview_uart index c9de8f194bb..15555d5e93a 100644 --- a/examples/system/sysview_tracing/sdkconfig.ci.sysview_uart +++ b/examples/system/sysview_tracing/sdkconfig.ci.sysview_uart @@ -1,3 +1,5 @@ CONFIG_ESP_CONSOLE_NONE=y CONFIG_APPTRACE_DEST_UART=y +CONFIG_APPTRACE_DEST_UART_NUM=0 +CONFIG_APPTRACE_UART_BAUDRATE=1000000 CONFIG_USE_CUSTOM_EVENT_ID=y 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 cb982706e02..cde57b8e888 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,6 +1,7 @@ # SPDX-FileCopyrightText: 2022-2025 Espressif Systems (Shanghai) CO LTD # SPDX-License-Identifier: Unlicense OR CC0-1.0 import os.path +import time import typing import pexpect.fdpexpect @@ -32,6 +33,7 @@ def _test_examples_sysview_tracing_heap_log(openocd_dut: 'OpenOCD', idf_path: st else: f_w.write(line) + time.sleep(1) # Wait for the USJ port to be ready dut.expect_exact('example: Ready for OpenOCD connection', timeout=5) with openocd_dut.run() as oocd: if dut.target == 'esp32p4':