Merge branch 'tracing_test_fixes' into 'master'

Tracing test fixes

See merge request espressif/esp-idf!51601

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

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,

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

examples/system/tracing/esp_trace_custom_library/main/app_main.c

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

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)

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

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

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 <size of core0 data in bytes>
+        ;
+        <core0 data><core1 data>
+
+    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()
 
@@ -202,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)

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