Mirrors/esp-idf
1
0
Fork 0
mirror of https://github.com/espressif/esp-idf.git synced 2026-09-22 13:01:16 +03:00
Code Issues Packages Projects Releases Wiki Activity

fix(esp_trace): send trace data over usb-serial-jtag reliably

Browse Source
This commit is contained in:
Erhan Kurubas
2026-08-06 09:51:33 +02:00
committed by BOT
parent f40df59461
commit da26095bd1
10 changed files with 142 additions and 67 deletions
Download Patch File Download Diff File Expand all files Collapse all files

24
components/app_trace/app_trace_membufs_proto.c
View File

@@ -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;

71
components/esp_trace/adapters/transport/adapter_transport_usb_serial_jtag.c
View File

@@ -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 <stdlib.h>
@@ -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;
}
}

14
components/esp_trace/include/esp_trace_util.h
View File

@@ -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);

8
components/esp_trace/src/ports/port_utils.c
View File

@@ -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;

3
examples/system/tracing/esp_trace_custom_library/components/ext_trace_lib/include/trace_FreeRTOS.h
View File

@@ -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);

42
examples/system/tracing/esp_trace_custom_library/components/ext_trace_lib/src/adapter_encoder_ext_trace_lib.c
View File

@@ -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,

18
examples/system/tracing/esp_trace_custom_library/components/ext_trace_lib/src/trace_FreeRTOS.c
View File

@@ -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();

13
examples/system/tracing/esp_trace_custom_library/main/app_main.c
View File

@@ -5,6 +5,7 @@
*/
#include "sdkconfig.h"
#include <inttypes.h>
#include <stdio.h>
#include <string.h>
@@ -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");
}

10
examples/system/tracing/esp_trace_custom_library/pytest_esp_trace_custom_library.py
View File

@@ -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:
@@ -107,10 +106,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)

6
examples/system/tracing/sysview_tracing/pytest_sysview_tracing.py
View File

@@ -183,7 +183,7 @@ def test_sysview_tracing_uart(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[0])
_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[0])
_validate_trace_data(trace_log, dut.target, is_uart=True)