From 313ee9b5db04b8f397d6ee23d50e0eea4bc23bd4 Mon Sep 17 00:00:00 2001 From: Erhan Kurubas Date: Wed, 29 Jul 2026 22:17:08 +0300 Subject: [PATCH 1/4] fix(esp_system): break into the debugger only on the first panic entry --- components/esp_system/panic.c | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/components/esp_system/panic.c b/components/esp_system/panic.c index e3c9ac16f96..2ed1cb89f3c 100644 --- a/components/esp_system/panic.c +++ b/components/esp_system/panic.c @@ -380,7 +380,7 @@ void esp_panic_handler(panic_info_t *info) // then only print up to details. Users should be able to probe for the other information // in debug mode. #if CONFIG_ESP_DEBUG_OCDAWARE - if (esp_cpu_dbgr_is_attached()) { + if (esp_cpu_dbgr_is_attached() && g_panic_entry_count[esp_cpu_get_core_id()] <= 1) { char *panic_reason_str = NULL; if (info->pseudo_excause) { panic_reason_str = (char *)info->reason; From b4d5b133ee1d4717701a9813e26218861483138c Mon Sep 17 00:00:00 2001 From: Erhan Kurubas Date: Fri, 17 Jul 2026 17:06:58 +0200 Subject: [PATCH 2/4] test(sysview_tracing): validate TRACE_STOP per core --- conftest.py | 8 +++ .../pytest_function_tracing.py | 4 +- .../sysview_tracing/pytest_sysview_tracing.py | 72 ++++++++++++++----- 3 files changed, 67 insertions(+), 17 deletions(-) diff --git a/conftest.py b/conftest.py index 0eadd337877..089dad6e3b0 100644 --- a/conftest.py +++ b/conftest.py @@ -271,6 +271,14 @@ class OpenOCD: return '' return to_str(resp) + def consume_output(self, duration: float) -> None: + if self.telnet is None: + return + end = time.time() + duration + while time.time() < end: + self.telnet.read_very_eager() + time.sleep(0.05) + def apptrace_wait_stop(self, timeout: int = 30) -> None: stopped = False end_before = time.time() + timeout diff --git a/examples/system/tracing/function_tracing/pytest_function_tracing.py b/examples/system/tracing/function_tracing/pytest_function_tracing.py index 7e54bdcc38f..f401e47edae 100644 --- a/examples/system/tracing/function_tracing/pytest_function_tracing.py +++ b/examples/system/tracing/function_tracing/pytest_function_tracing.py @@ -129,7 +129,9 @@ def _test_function_tracing_jtag(openocd_dut: 'OpenOCD', idf_path: str, dut: IdfD dut.expect(re.compile(rb'function-tracing: workload iteration \d+'), timeout=30) # Let function-trace samples accumulate while recording. - time.sleep(1) + # Keep reading telnet so OpenOCD's blocking log writes don't stall its + # main loop and leave the 'stop' below unserviced. + openocd.consume_output(1) openocd.write('esp sysview_mcore stop') openocd.apptrace_wait_stop() diff --git a/examples/system/tracing/sysview_tracing/pytest_sysview_tracing.py b/examples/system/tracing/sysview_tracing/pytest_sysview_tracing.py index a60370d909c..068957bc2b0 100644 --- a/examples/system/tracing/sysview_tracing/pytest_sysview_tracing.py +++ b/examples/system/tracing/sysview_tracing/pytest_sysview_tracing.py @@ -16,18 +16,60 @@ if typing.TYPE_CHECKING: from conftest import OpenOCD +STOP_EVENT_ID = 0x0B # SYSVIEW_EVTID_TRACE_STOP + + +def _assert_has_stop_record(segment: bytes, label: str) -> None: + """Assert a SysView data segment ends with a TRACE_STOP record. + + A STOP record is the STOP event ID followed by a variable-length timestamp + delta. Walk back over the trailing continuation bytes (0x80 bit set) to find + the event ID, since its offset is not fixed. + """ + size = len(segment) + assert size >= 2, f'{label}: segment too small to contain STOP record' + i = size - 2 + while i >= 0 and (segment[i] & 0x80): + i -= 1 + assert i >= 0 and segment[i] == STOP_EVENT_ID, f'{label}: does not end with a TRACE_STOP record' + + +def _split_mcore_file(content: bytes) -> list[bytes]: + """Split an ``esp sysview_mcore`` combined file into per-core data segments. + + Layout is an ASCII comment header followed by core0 data then core1 data:: + + ; ... + ; Offset Core0 0 + ; Offset Core1 + ; + + + The header ends at the first line that does not start with ';', (the data + begins with the all-zero sync sequence). + """ + header = re.match(rb'(?:;[^\n]*\n)*', content) + assert header is not None + pos = header.end() + m = re.search(rb';\s*Offset\s+Core1\s+(\d+)', content[:pos]) + assert m is not None, 'mcore file header missing "Offset Core1"' + offset_core1 = int(m.group(1)) + core0 = content[pos : pos + offset_core1] + core1 = content[pos + offset_core1 :] + return [core0, core1] + + def _validate_trace_data(trace_log: str, target: str, dual_core: bool = False, is_uart: bool = False) -> None: """Validate SysView trace data in a single trace log file. Args: trace_log: Path to the trace log file target: Target chip name (e.g., 'esp32', 'esp32s3') - dual_core: If True, expect a per-core description block for both cores - (the ``esp sysview_mcore`` multi-core capture embeds one per core) + dual_core: If True, this is an 'esp sysview_mcore' combined file that + embeds core0 and core1 data segments (see '_split_mcore_file'); + each segment is validated separately. is_uart: If True, also validate STOP record at end of file """ - STOP_EVENT_ID = 0x0B # SYSVIEW_EVTID_TRACE_STOP - with open(trace_log, 'rb') as f: content = f.read() @@ -35,16 +77,13 @@ def _validate_trace_data(trace_log: str, target: str, dual_core: bool = False, i search_str = f'N=FreeRTOS Application,D={target},C=core{idx},O=FreeRTOS'.encode() assert search_str in content, f'SysView core{idx} trace data not found in {trace_log}' - # The file must end with a TRACE_STOP record: the STOP event ID - # followed by a variable-length timestamp delta. Walk back - # over the trailing continuation bytes (0x80 bit set) - # to find the event ID, since its offset is not fixed. - size = len(content) - assert size >= 2, 'Trace file too small to contain STOP record' - i = size - 2 - while i >= 0 and (content[i] & 0x80): - i -= 1 - assert i >= 0 and content[i] == STOP_EVENT_ID, 'STOP record does not start with STOP eventID' + if dual_core: + # Seek to each core's segment via the header offset + # and require each to end with its own TRACE_STOP record. + for idx, segment in enumerate(_split_mcore_file(content)): + _assert_has_stop_record(segment, f'core{idx}') + else: + _assert_has_stop_record(content, 'trace') def _capture_sysview_trace(ser: serial.Serial, trace_log_path: str) -> None: @@ -144,8 +183,9 @@ def _test_sysview_tracing_jtag(openocd_dut: 'OpenOCD', dut: IdfDut) -> None: 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) + # Capture sysview samples and keep reading telnet so OpenOCD's blocking log writes don't stall its + # main loop and leave the 'stop' below unserviced. + openocd.consume_output(3) openocd.write('esp sysview_mcore stop') openocd.apptrace_wait_stop() From 6e94ac4a8b8dd453adac19fb5c7c1ff0f26da924 Mon Sep 17 00:00:00 2001 From: Erhan Kurubas Date: Thu, 6 Aug 2026 08:27:01 +0200 Subject: [PATCH 3/4] change(esp_trace): increase usj tx buffer size in both examples --- components/esp_trace/Kconfig | 5 +++-- .../tracing/esp_trace_custom_library/sdkconfig.defaults | 2 +- .../system/tracing/sysview_tracing/sdkconfig.ci.sysview_usj | 1 + 3 files changed, 5 insertions(+), 3 deletions(-) diff --git a/components/esp_trace/Kconfig b/components/esp_trace/Kconfig index 468bc35ff3e..7a0d8e3c2c8 100644 --- a/components/esp_trace/Kconfig +++ b/components/esp_trace/Kconfig @@ -76,12 +76,13 @@ menu "ESP Trace Configuration" config ESP_TRACE_USJ_TX_BUFFER_SIZE int "TX buffer size" default 2048 - range 256 32768 + range 2048 32768 help Size of the TX ring buffer for USB Serial JTAG trace transport. Larger buffer allows more trace data to be queued before blocking. - Note: Buffer size must be a power of 2. + Note: Buffer size must be a power of 2. Minimum is 2048 since + smaller buffers overflow easily on the USJ transport. endmenu diff --git a/examples/system/tracing/esp_trace_custom_library/sdkconfig.defaults b/examples/system/tracing/esp_trace_custom_library/sdkconfig.defaults index f90dbb5d285..7d0d1656cfd 100644 --- a/examples/system/tracing/esp_trace_custom_library/sdkconfig.defaults +++ b/examples/system/tracing/esp_trace_custom_library/sdkconfig.defaults @@ -3,4 +3,4 @@ CONFIG_ESP_TRACE_LIB_EXTERNAL=y CONFIG_ESP_TRACE_TS_SOURCE_ESP_TIMER=y CONFIG_ESP_CONSOLE_SECONDARY_NONE=y CONFIG_ESP_TRACE_TRANSPORT_USB_SERIAL_JTAG=y -CONFIG_ESP_TRACE_USJ_TX_BUFFER_SIZE=32768 +CONFIG_ESP_TRACE_USJ_TX_BUFFER_SIZE=16384 diff --git a/examples/system/tracing/sysview_tracing/sdkconfig.ci.sysview_usj b/examples/system/tracing/sysview_tracing/sdkconfig.ci.sysview_usj index cafe4275e66..03e38b8478f 100644 --- a/examples/system/tracing/sysview_tracing/sdkconfig.ci.sysview_usj +++ b/examples/system/tracing/sysview_tracing/sdkconfig.ci.sysview_usj @@ -1,3 +1,4 @@ CONFIG_ESP_CONSOLE_SECONDARY_NONE=y CONFIG_ESP_TRACE_TRANSPORT_USB_SERIAL_JTAG=y CONFIG_USE_CUSTOM_EVENT_ID=y +CONFIG_ESP_TRACE_USJ_TX_BUFFER_SIZE=16384 From 256d129ed9842282c94740117d4ae467f52ef5db Mon Sep 17 00:00:00 2001 From: Erhan Kurubas Date: Thu, 6 Aug 2026 09:51:33 +0200 Subject: [PATCH 4/4] fix(esp_trace): send trace data over usb-serial-jtag reliably --- .../app_trace/app_trace_membufs_proto.c | 24 +++---- .../adapter_transport_usb_serial_jtag.c | 71 +++++++++++-------- components/esp_trace/include/esp_trace_util.h | 14 +++- components/esp_trace/src/ports/port_utils.c | 8 +-- .../ext_trace_lib/include/trace_FreeRTOS.h | 3 + .../src/adapter_encoder_ext_trace_lib.c | 42 ++++++++--- .../ext_trace_lib/src/trace_FreeRTOS.c | 18 ++++- .../esp_trace_custom_library/main/app_main.c | 13 +++- .../pytest_esp_trace_custom_library.py | 10 +-- .../sysview_tracing/pytest_sysview_tracing.py | 6 +- 10 files changed, 142 insertions(+), 67 deletions(-) diff --git a/components/app_trace/app_trace_membufs_proto.c b/components/app_trace/app_trace_membufs_proto.c index b535624ec6d..1ad237a898a 100644 --- a/components/app_trace/app_trace_membufs_proto.c +++ b/components/app_trace/app_trace_membufs_proto.c @@ -1,5 +1,5 @@ /* - * SPDX-FileCopyrightText: 2021-2025 Espressif Systems (Shanghai) CO LTD + * SPDX-FileCopyrightText: 2021-2026 Espressif Systems (Shanghai) CO LTD * * SPDX-License-Identifier: Apache-2.0 OR MIT */ @@ -75,7 +75,7 @@ static esp_err_t esp_apptrace_membufs_swap(esp_apptrace_membufs_proto_data_t *pr esp_err_t res = proto->hw->swap_start(proto->state.in_block); if (res != ESP_OK) { - ESP_APPTRACE_LOGE("Failed to swap to new block: %d", res); + ESP_APPTRACE_LOGV("Failed to swap to new block: %s", esp_err_to_name(res)); return res; } @@ -100,7 +100,7 @@ static esp_err_t esp_apptrace_membufs_swap(esp_apptrace_membufs_proto_data_t *pr *(p - 8), *(p - 7), *(p - 6), *(p - 5), *(p - 4), *(p - 3), *(p - 2), *(p - 1)); uint32_t sz = esp_apptrace_membufs_down_buffer_write_nolock(proto, (uint8_t *)(hdr + 1), hdr->block_sz); if (sz != hdr->block_sz) { - ESP_APPTRACE_LOGE("Failed to write %" PRIu32 " bytes to down buffer (%" PRIu16 " %" PRIu32 ")!", + ESP_APPTRACE_LOGE("Failed to write %" PRIu32 " bytes to down buffer (%" PRIu32 " %" PRIu32 ")!", hdr->block_sz - sz, hdr->block_sz, sz); } hdr->block_sz = 0; @@ -149,20 +149,18 @@ uint8_t *esp_apptrace_membufs_down_buffer_get(esp_apptrace_membufs_proto_data_t } break; } - // may need to flush + // may need to flush to expose host down-channel data if (proto->hw->host_data_pending()) { ESP_APPTRACE_LOGD("force flush"); int res = esp_apptrace_membufs_swap_waitus(proto, tmo); - if (res != ESP_OK) { - ESP_APPTRACE_LOGE("Failed to switch to another block to recv data from host!"); - /*do not return error because data can be in down buffer already*/ - } - } else { - // check tmo only if there is no data from host - int res = esp_apptrace_tmo_check(tmo); - if (res != ESP_OK) { - return NULL; + if (res == ESP_OK) { + continue; /* re-check rb_down */ } + ESP_APPTRACE_LOGE("Failed to switch to another block to recv data from host!"); + } + /* Check the timeout even while host data is pending so a zero timeout returns immediately instead of spinning. */ + if (esp_apptrace_tmo_check(tmo) != ESP_OK) { + return NULL; } } return ptr; diff --git a/components/esp_trace/adapters/transport/adapter_transport_usb_serial_jtag.c b/components/esp_trace/adapters/transport/adapter_transport_usb_serial_jtag.c index da3e366bfe5..fd724f84f15 100644 --- a/components/esp_trace/adapters/transport/adapter_transport_usb_serial_jtag.c +++ b/components/esp_trace/adapters/transport/adapter_transport_usb_serial_jtag.c @@ -15,6 +15,8 @@ * is responsible for serializing access using esp_trace_lock_init(), esp_trace_lock_take(), * and esp_trace_lock_give(). All transport operations (read, write, flush_nolock) are * invoked while the encoder holds the lock, so no transport-level locking is required. + * + * Logging: use ESP_EARLY_LOGx only, ESP_LOGx is not safe in ISR context. */ #include @@ -29,6 +31,7 @@ #include "esp_cpu.h" #include "esp_attr.h" #include "esp_rom_caps.h" +#include "esp_rom_sys.h" #include "esp_heap_caps.h" #include "esp_private/periph_ctrl.h" #include "hal/usb_serial_jtag_ll.h" @@ -51,7 +54,6 @@ static const char *TAG = "usj_transport"; */ typedef enum { USJ_TX_IDLE, - USJ_TX_SHORT_PENDING, USJ_TX_ZLP_PENDING, } usj_tx_state_t; @@ -67,11 +69,8 @@ typedef struct { uint32_t flush_thresh; ///< Flush threshold in bytes } usj_ctx_t; -/* - * flush_nolock() runs with interrupts masked, so normal flushes use a short - * fixed timeout even if an encoder requests a longer one. - */ -#define USJ_FLUSH_TIMEOUT_US (1000) // 1 ms +/* Default flush timeout, used on non-masked paths (e.g. panic handler). */ +#define USJ_FLUSH_TIMEOUT_US (1000000) // 1 s #define USJ_FLUSH_THRESH_BYTES (0) // 0 bytes #define USJ_FLUSH_MAX_INTR_MASKED_US (2000) // 2 ms #define USJ_FLUSH_POLL_STEP_US (100) // delay between no-progress polls @@ -84,7 +83,7 @@ typedef struct { static uint32_t usj_write_fifo(usj_ctx_t *ctx, esp_trace_rb_t *rb) { if (!usb_serial_jtag_ll_txfifo_writable()) { - /* FIFO is full, no blocking */ + /* Previous packet is not sent yet */ return 0; } @@ -97,17 +96,21 @@ static uint32_t usj_write_fifo(usj_ctx_t *ctx, esp_trace_rb_t *rb) uint32_t written = usb_serial_jtag_ll_write_txfifo(ptr, to_send); esp_trace_rb_consume(rb, written); - ctx->tx_state = usb_serial_jtag_ll_txfifo_writable() ? USJ_TX_SHORT_PENDING : USJ_TX_ZLP_PENDING; + /* Checked before wr_done, which also clears the writable flag */ + ctx->tx_state = usb_serial_jtag_ll_txfifo_writable() ? USJ_TX_IDLE : USJ_TX_ZLP_PENDING; + + /* Send the packet. A no-op if the HW already flushed a full FIFO. */ + usb_serial_jtag_ll_txfifo_flush(); return written; } -static uint32_t usj_fill_txfifo(usj_ctx_t *ctx, bool commit_short) +static uint32_t usj_fill_txfifo(usj_ctx_t *ctx) { esp_trace_rb_t *rb = &ctx->tx_ring; uint32_t total_written = 0; - while (esp_trace_rb_data_len(rb) > 0 && usb_serial_jtag_ll_txfifo_writable()) { + while (esp_trace_rb_data_len(rb) > 0) { uint32_t written = usj_write_fifo(ctx, rb); if (written == 0) { break; @@ -115,11 +118,6 @@ static uint32_t usj_fill_txfifo(usj_ctx_t *ctx, bool commit_short) total_written += written; } - if (commit_short && ctx->tx_state == USJ_TX_SHORT_PENDING) { - usb_serial_jtag_ll_txfifo_flush(); - ctx->tx_state = USJ_TX_IDLE; - } - return total_written; } @@ -127,7 +125,15 @@ static void usj_read_rx_fifo(usj_ctx_t *ctx) { uint8_t tmp[USJ_HW_FIFO_SIZE]; while (usb_serial_jtag_ll_rxfifo_data_available()) { - uint32_t n = usb_serial_jtag_ll_read_rxfifo(tmp, sizeof(tmp)); + /* Read only what fits, the rest stays in the HW FIFO */ + uint32_t space = esp_trace_rb_free_len(&ctx->rx_ring); + if (space == 0) { + break; + } + if (space > sizeof(tmp)) { + space = sizeof(tmp); + } + uint32_t n = usb_serial_jtag_ll_read_rxfifo(tmp, space); if (n == 0) { break; } @@ -185,22 +191,23 @@ static esp_err_t usj_init(esp_trace_transport_t *tp, const void *tp_cfg) /* Initialize TX ring buffer */ esp_err_t ret = esp_trace_rb_init(&ctx->tx_ring, CONFIG_ESP_TRACE_USJ_TX_BUFFER_SIZE); if (ret != ESP_OK) { - ESP_LOGE(TAG, "Failed to initialize TX ring buffer"); + ESP_EARLY_LOGE(TAG, "Failed to initialize TX ring buffer"); goto err_ctx; } /* Initialize RX ring buffer to capture host commands */ ret = esp_trace_rb_init(&ctx->rx_ring, USJ_RX_BUFFER_SIZE); if (ret != ESP_OK) { - ESP_LOGE(TAG, "Failed to initialize RX ring buffer"); + ESP_EARLY_LOGE(TAG, "Failed to initialize RX ring buffer"); goto err_tx_ring; } -#if ESP_ROM_HAS_ETS_PRINTF_BUG /* Make sure no printf output is sent to USB-Serial-JTAG */ +#if ESP_ROM_HAS_ETS_PRINTF_BUG extern bool g_usb_print; g_usb_print = false; #endif + esp_rom_install_channel_putc(2, NULL); } @@ -267,13 +274,15 @@ static esp_err_t usj_write(esp_trace_transport_t *tp, const void *data, size_t s /* Read any new RX data into the RX ring buffer to avoid losing host commands in case of heavy trace output */ usj_read_rx_fifo(ctx); - /* Add data to TX ring buffer */ - esp_trace_rb_put(rb, (const uint8_t *)data, size); + esp_err_t ret = esp_trace_rb_put(rb, (const uint8_t *)data, size); + if (ret != ESP_OK) { + /* Free what the HW can take, then retry before dropping the record */ + usj_fill_txfifo(ctx); + ret = esp_trace_rb_put(rb, (const uint8_t *)data, size); + } + usj_fill_txfifo(ctx); - /* Try to move data to HW FIFO immediately, without forcing a short packet. */ - usj_fill_txfifo(ctx, false); - - return ESP_OK; + return ret; } static esp_err_t usj_down_buffer_config(esp_trace_transport_t *tp, uint8_t *buf, uint32_t size) @@ -292,7 +301,7 @@ static esp_err_t usj_flush_with_timeout(usj_ctx_t *ctx, uint32_t tmo_us) esp_trace_rb_t *rb = &ctx->tx_ring; uint32_t pending = esp_trace_rb_data_len(rb); - if (pending < ctx->flush_thresh && ctx->tx_state == USJ_TX_IDLE) { + if ((pending == 0 || pending < ctx->flush_thresh) && ctx->tx_state == USJ_TX_IDLE) { return ESP_OK; } @@ -300,9 +309,11 @@ static esp_err_t usj_flush_with_timeout(usj_ctx_t *ctx, uint32_t tmo_us) esp_trace_tmo_init(&timeout, tmo_us); while (esp_trace_rb_data_len(rb) > 0 || ctx->tx_state != USJ_TX_IDLE) { - uint32_t written = usj_fill_txfifo(ctx, true); + uint32_t written = usj_fill_txfifo(ctx); - if (ctx->tx_state == USJ_TX_ZLP_PENDING && usb_serial_jtag_ll_txfifo_writable()) { + /* Ring is empty: send a ZLP if the last packet filled the endpoint */ + if (esp_trace_rb_data_len(rb) == 0 && ctx->tx_state == USJ_TX_ZLP_PENDING + && usb_serial_jtag_ll_txfifo_writable()) { usb_serial_jtag_ll_txfifo_flush(); ctx->tx_state = USJ_TX_IDLE; continue; @@ -363,7 +374,7 @@ static esp_err_t usj_set_config(esp_trace_transport_t *tp, esp_trace_transport_c ctx->flush_thresh = *(const uint32_t *)value; return ESP_OK; default: - ESP_LOGE(TAG, "Key %d is not supported", key); + ESP_EARLY_LOGE(TAG, "Key %d is not supported", key); return ESP_ERR_NOT_SUPPORTED; } } @@ -387,7 +398,7 @@ static esp_err_t usj_get_config(esp_trace_transport_t *tp, esp_trace_transport_c *(uint32_t *)value = ctx->flush_thresh; return ESP_OK; default: - ESP_LOGE(TAG, "Key %d is not supported", key); + ESP_EARLY_LOGE(TAG, "Key %d is not supported", key); return ESP_ERR_NOT_SUPPORTED; } } diff --git a/components/esp_trace/include/esp_trace_util.h b/components/esp_trace/include/esp_trace_util.h index e95d5ceea37..5e814731363 100644 --- a/components/esp_trace/include/esp_trace_util.h +++ b/components/esp_trace/include/esp_trace_util.h @@ -157,12 +157,22 @@ static inline uint32_t esp_trace_rb_data_len(const esp_trace_rb_t *rb) } /** - * @brief Write data into the ring buffer (overwrites oldest data if full) + * @brief Get number of bytes that can still be written to the ring buffer + */ +static inline uint32_t esp_trace_rb_free_len(const esp_trace_rb_t *rb) +{ + return rb->max_size - rb->count; +} + +/** + * @brief Write data into the ring buffer, all of it or none + * + * Data already in the buffer is never overwritten. * * @param rb Ring buffer * @param data Source data * @param len Number of bytes to write - * @return ESP_OK always (data is always accepted; oldest data may be dropped) + * @return ESP_OK on success, ESP_ERR_NO_MEM if the data does not fit */ esp_err_t esp_trace_rb_put(esp_trace_rb_t *rb, const uint8_t *data, uint32_t len); diff --git a/components/esp_trace/src/ports/port_utils.c b/components/esp_trace/src/ports/port_utils.c index f2cc592c681..4870016b95c 100644 --- a/components/esp_trace/src/ports/port_utils.c +++ b/components/esp_trace/src/ports/port_utils.c @@ -195,10 +195,10 @@ esp_err_t esp_trace_rb_init(esp_trace_rb_t *rb, uint32_t size) esp_err_t esp_trace_rb_put(esp_trace_rb_t *rb, const uint8_t *data, uint32_t len) { - /* Drop oldest data if needed to make room */ - uint32_t free_len = rb->max_size - rb->count; - if (len > free_len) { - rb_advance_tail(rb, len - free_len); + /* Drop the new record instead of overwriting old ones, so that the records + * in the buffer stay complete */ + if (len > rb->max_size - rb->count) { + return ESP_ERR_NO_MEM; } uint32_t head = rb->head; diff --git a/examples/system/tracing/esp_trace_custom_library/components/ext_trace_lib/include/trace_FreeRTOS.h b/examples/system/tracing/esp_trace_custom_library/components/ext_trace_lib/include/trace_FreeRTOS.h index c49ca59bf49..3dc5381597a 100644 --- a/examples/system/tracing/esp_trace_custom_library/components/ext_trace_lib/include/trace_FreeRTOS.h +++ b/examples/system/tracing/esp_trace_custom_library/components/ext_trace_lib/include/trace_FreeRTOS.h @@ -36,6 +36,9 @@ void init_trace_lib(esp_trace_encoder_t *enc); void trace_lib_start(void); void trace_lib_stop(void); +/* @brief Get the number of trace lines written to and dropped by the transport */ +void trace_lib_get_stats(uint32_t *written, uint32_t *dropped); + /* Hook implementations — defined in trace_FreeRTOS.c. * Kept void*-typed to avoid depending on FreeRTOS types in this header. */ void trace_lib_task_switched_in(void); diff --git a/examples/system/tracing/esp_trace_custom_library/components/ext_trace_lib/src/adapter_encoder_ext_trace_lib.c b/examples/system/tracing/esp_trace_custom_library/components/ext_trace_lib/src/adapter_encoder_ext_trace_lib.c index 976704b44e4..cc227ba465e 100644 --- a/examples/system/tracing/esp_trace_custom_library/components/ext_trace_lib/src/adapter_encoder_ext_trace_lib.c +++ b/examples/system/tracing/esp_trace_custom_library/components/ext_trace_lib/src/adapter_encoder_ext_trace_lib.c @@ -85,14 +85,6 @@ static esp_err_t stop(esp_trace_encoder_t *enc) return ESP_OK; } -static esp_err_t flush(esp_trace_encoder_t *enc) -{ - if (!enc || !enc->tp || !enc->tp->vt->flush_nolock) { - return ESP_ERR_NOT_SUPPORTED; - } - return enc->tp->vt->flush_nolock(enc->tp); -} - /** * @brief Panic handler * @@ -104,7 +96,11 @@ static esp_err_t flush(esp_trace_encoder_t *enc) static void panic_handler(esp_trace_encoder_t *enc, const void *info) { (void)info; - flush(enc); + + /* No lock here, the panicking core may already hold it */ + if (enc && enc->tp && enc->tp->vt->flush_nolock) { + enc->tp->vt->flush_nolock(enc->tp); + } } static unsigned int take_lock(esp_trace_encoder_t *enc, uint32_t tmo_us) @@ -127,6 +123,34 @@ static void give_lock(esp_trace_encoder_t *enc, unsigned int int_state) esp_trace_lock_give(&ctx->lock); } +/* Total time for the flush, split over several flush_nolock() calls */ +#define EXT_TRACE_LIB_FLUSH_TMO_US (1000000) + +static esp_err_t flush(esp_trace_encoder_t *enc) +{ + if (!enc || !enc->tp || !enc->tp->vt->flush_nolock) { + return ESP_ERR_NOT_SUPPORTED; + } + + /* One call may be too short to send all the data, so repeat it and release + * the lock in between to keep interrupts enabled */ + esp_trace_tmo_t tmo; + esp_trace_tmo_init(&tmo, EXT_TRACE_LIB_FLUSH_TMO_US); + + esp_err_t err; + do { + unsigned int int_state = take_lock(enc, ESP_TRACE_TMO_INFINITE); + err = enc->tp->vt->flush_nolock(enc->tp); + give_lock(enc, int_state); + + if (err != ESP_ERR_TIMEOUT) { + break; /* done, or an error that repeating cannot fix */ + } + } while (esp_trace_tmo_check(&tmo) == ESP_OK); + + return err; +} + static const esp_trace_encoder_vtable_t s_ext_trace_lib_vt = { .init = init, .write = write, diff --git a/examples/system/tracing/esp_trace_custom_library/components/ext_trace_lib/src/trace_FreeRTOS.c b/examples/system/tracing/esp_trace_custom_library/components/ext_trace_lib/src/trace_FreeRTOS.c index 5e88bf6df37..d8f12035a9a 100644 --- a/examples/system/tracing/esp_trace_custom_library/components/ext_trace_lib/src/trace_FreeRTOS.c +++ b/examples/system/tracing/esp_trace_custom_library/components/ext_trace_lib/src/trace_FreeRTOS.c @@ -35,6 +35,8 @@ static esp_trace_encoder_t *s_enc = NULL; static uint32_t s_ts_freq_hz = 1000000; /* default assume 1 MHz */ static uint32_t s_last_ts = 0; static volatile bool s_enabled = false; +static uint32_t s_written = 0; +static uint32_t s_dropped = 0; void init_trace_lib(esp_trace_encoder_t *enc) { @@ -87,12 +89,26 @@ static void encode(const char *type, const char *detail) if (n >= (int)sizeof(line)) { n = (int)sizeof(line) - 1; } - esp_trace_write(s_esp_trace_handle, line, (size_t)n, 0); + if (esp_trace_write(s_esp_trace_handle, line, (size_t)n, 0) == ESP_OK) { + s_written++; + } else { + s_dropped++; /* transport buffer was full, line dropped */ + } } s_enc->vt->give_lock(s_enc, int_state); } +void trace_lib_get_stats(uint32_t *written, uint32_t *dropped) +{ + if (written) { + *written = s_written; + } + if (dropped) { + *dropped = s_dropped; + } +} + void trace_lib_task_switched_in(void) { TaskHandle_t h = xTaskGetCurrentTaskHandle(); diff --git a/examples/system/tracing/esp_trace_custom_library/main/app_main.c b/examples/system/tracing/esp_trace_custom_library/main/app_main.c index 28d7c07aa27..265bb4b6e9b 100644 --- a/examples/system/tracing/esp_trace_custom_library/main/app_main.c +++ b/examples/system/tracing/esp_trace_custom_library/main/app_main.c @@ -5,6 +5,7 @@ */ #include "sdkconfig.h" +#include #include #include @@ -13,6 +14,7 @@ #include "freertos/queue.h" #include "esp_log.h" #include "esp_trace.h" +#include "trace_FreeRTOS.h" static const char *TAG = "main"; @@ -70,7 +72,16 @@ void app_main(void) vTaskDelay(1000 / portTICK_PERIOD_MS); esp_trace_stop(); - esp_trace_flush(); + esp_err_t err = esp_trace_flush(); + + /* Logged from task context, so it goes to the console UART and not to the + * trace port. Shows whether the device sent the trace data or not. */ + uint32_t written = 0; + uint32_t dropped = 0; + trace_lib_get_stats(&written, &dropped); + ESP_LOGI(TAG, "Trace flush: %s, host connected: %d, lines written: %" PRIu32 ", dropped: %" PRIu32, + esp_err_to_name(err), (int)esp_trace_is_host_connected(esp_trace_get_active_handle()), + written, dropped); ESP_LOGI(TAG, "End of trace session"); } diff --git a/examples/system/tracing/esp_trace_custom_library/pytest_esp_trace_custom_library.py b/examples/system/tracing/esp_trace_custom_library/pytest_esp_trace_custom_library.py index 83e7682160d..c927890b4b6 100644 --- a/examples/system/tracing/esp_trace_custom_library/pytest_esp_trace_custom_library.py +++ b/examples/system/tracing/esp_trace_custom_library/pytest_esp_trace_custom_library.py @@ -76,7 +76,6 @@ def _validate_trace_data(trace_log_path: str) -> None: def _capture_trace(ser: serial.Serial, trace_log_path: str, capture_s: float = 5.0) -> None: """Capture trace output from the USB-Serial-JTAG endpoint.""" - ser.reset_input_buffer() with open(trace_log_path, 'w+b') as f: end_time = time.time() + capture_s while time.time() < end_time: @@ -106,10 +105,13 @@ def _capture_trace(ser: serial.Serial, trace_log_path: str, capture_s: float = 5 def test_esp_trace_ext_lib_usj(dut: IdfDut) -> None: dut.expect('Start of trace session', timeout=5) - time.sleep(1) # wait for USJ port to be ready + # Open the port before the DUT starts tracing usj_port = '/dev/serial_ports/ttyACM-esp32' - ser = serial.Serial(usj_port, baudrate=1000000, timeout=10) trace_log_path = os.path.join(dut.logdir, 'ext_trace.log') + time.sleep(1) # Wait for the USJ port to be ready + with serial.Serial(usj_port, baudrate=1000000, timeout=10) as ser: + # Discard data from before this test, the DUT is not tracing yet + ser.reset_input_buffer() + _capture_trace(ser, trace_log_path) - _capture_trace(ser, trace_log_path) _validate_trace_data(trace_log_path) diff --git a/examples/system/tracing/sysview_tracing/pytest_sysview_tracing.py b/examples/system/tracing/sysview_tracing/pytest_sysview_tracing.py index 068957bc2b0..dd651d56612 100644 --- a/examples/system/tracing/sysview_tracing/pytest_sysview_tracing.py +++ b/examples/system/tracing/sysview_tracing/pytest_sysview_tracing.py @@ -242,7 +242,7 @@ def test_sysview_tracing_uart_c2(dut: IdfDut) -> None: def test_sysview_tracing_usj_serial(dut: IdfDut) -> None: time.sleep(1) # wait for USJ port to be ready usj_port = '/dev/serial_ports/ttyACM-esp32' - ser = serial.Serial(usj_port, baudrate=1000000, timeout=10) trace_log = os.path.join(dut.logdir, 'sys_log_usj.svdat') # pylint: disable=protected-access - _capture_sysview_trace(ser, trace_log) - _validate_trace_data(trace_log, dut.target, is_uart=True) + with serial.Serial(usj_port, baudrate=1000000, timeout=10) as ser: + _capture_sysview_trace(ser, trace_log) + _validate_trace_data(trace_log, dut.target, is_uart=True)