diff --git a/components/esp_trace/CMakeLists.txt b/components/esp_trace/CMakeLists.txt index c976fc497ba..9b3e3ac5ae7 100644 --- a/components/esp_trace/CMakeLists.txt +++ b/components/esp_trace/CMakeLists.txt @@ -19,6 +19,10 @@ if(CONFIG_ESP_TRACE_ENABLE) if(CONFIG_ESP_TRACE_TRANSPORT_USB_SERIAL_JTAG) list(APPEND srcs "adapters/transport/adapter_transport_usb_serial_jtag.c") endif() + + if(CONFIG_ESP_TRACE_FUNCTION_TRACE) + list(APPEND srcs "src/function_trace.c") + endif() endif() set(includes @@ -32,7 +36,7 @@ set(priv_requires "esp_timer" "esp_system" ) -set(priv_includes "") +set(priv_includes "private_include") set(requires "app_trace") idf_component_register(SRCS ${srcs} diff --git a/components/esp_trace/Kconfig b/components/esp_trace/Kconfig index f37761be603..17ff851a229 100644 --- a/components/esp_trace/Kconfig +++ b/components/esp_trace/Kconfig @@ -85,6 +85,57 @@ menu "ESP Trace Configuration" endmenu + menu "Function Tracing" + depends on ESP_TRACE_ENABLE + + config ESP_TRACE_FUNCTION_TRACE + bool "Enable compiler-instrumented function tracing" + default n + help + Trace when functions are entered and exited. + + When you build a component with the compiler flag + -finstrument-functions, the compiler inserts a call at the start + and end of every function in that component. These calls go to + hooks provided by esp_trace, which forward the events to the + active trace encoder (for example SystemView). + + Enabling this option compiles the hook functions and the + function-trace runtime into the build. It does not add + -finstrument-functions to any code, so on its own it produces no + events. + + To trace a component or file, add the GCC function instrumentation flag + from that component's CMakeLists.txt. See the Application Level Tracing + guide and examples/system/function_tracing for CMake examples. + + Use the GCC -finstrument-functions-exclude-file-list and + -finstrument-functions-exclude-function-list flags to skip + specific files or functions. + + config ESP_TRACE_FUNCTION_TRACE_AUTO_START + bool "Start function tracing automatically when the host starts recording" + depends on ESP_TRACE_FUNCTION_TRACE + default y + help + Controls when function tracing begins recording once a trace + session is active. + + When enabled, function tracing follows the encoder's recording + state and begins as soon as the host starts the session (for + example OpenOCD "mon esp sysview_mcore start"), without an + application call. + + When disabled, function-trace events are dropped until the + application calls esp_trace_function_trace_start(), even if a host + trace session is already recording. esp_trace_function_trace_stop() + stops recording again. + + An active trace session (encoder recording) is required in both + cases. + + endmenu + choice ESP_TRACE_TIMESTAMP_SOURCE depends on ESP_TRACE_ENABLE prompt "Trace timestamp source" diff --git a/components/esp_trace/README.md b/components/esp_trace/README.md index 7ec47c6bf8d..bc7181b40fc 100644 --- a/components/esp_trace/README.md +++ b/components/esp_trace/README.md @@ -231,7 +231,7 @@ The `esp_trace` component supports integration of external trace libraries throu > > Encoder and transport callbacks invoked from the hot path — `write`, `flush` / `flush_nolock`, `read`, `take_lock` / `give_lock`, `panic_handler` — run from inside FreeRTOS trace hooks (and from ISR context for `traceISR_ENTER` / `traceISR_EXIT`). They are also called while the encoder's lock is held. > -> Do **not** call FreeRTOS / IDF APIs that themselves trigger trace hooks from these callbacks. Anything that would emit a `trace*()` macro re-enters the tracing path: it can recurse into your own encoder, deadlock on the encoder's non-recursive spinlock, or call a task-only API from ISR context. +> Do **not** call FreeRTOS / IDF APIs that themselves trigger trace hooks from these callbacks. Anything that would invoke a `trace*()` macro re-enters the tracing path: it can recurse into your own encoder, deadlock on the encoder's non-recursive spinlock, or call a task-only API from ISR context. > > Specifically avoid: > - Task APIs: `vTaskDelay`, `vTaskSuspend`, `xTaskNotify*`, anything that yields. @@ -411,6 +411,57 @@ target_link_libraries(${esp_trace_lib} INTERFACE $ Do not instrument `esp_trace`, encoders, transports, or SEGGER sources. They must stay free of `-finstrument-functions` to avoid recursion. The target sends addresses, not symbol names. If supported, the host viewer can resolve them from the ELF. + +### Limitations + +- No early-boot tracing. Events are recorded only after a trace session and the encoder are running. +- The target sends addresses, not symbol strings. The host viewer can optionally resolve them from the ELF. +- Instrumentation adds hook overhead to every traced call and increases code size and stack usage. +- Whole-IDF instrumentation is not recommended. Instrument selected components or files only. + ## Documentation For detailed usage instructions, see: diff --git a/components/esp_trace/include/esp_trace_function_trace.h b/components/esp_trace/include/esp_trace_function_trace.h new file mode 100644 index 00000000000..d430246de29 --- /dev/null +++ b/components/esp_trace/include/esp_trace_function_trace.h @@ -0,0 +1,35 @@ +/* + * SPDX-FileCopyrightText: 2025-2026 Espressif Systems (Shanghai) CO LTD + * + * SPDX-License-Identifier: Apache-2.0 + */ +#pragma once + +#ifdef __cplusplus +extern "C" { +#endif + +#include "esp_err.h" + +/** + * @brief Start recording compiler-instrumented function events. + * + * Resolves the active encoder's function-trace capability once and enables the + * hooks. Requires an active trace session. + * + * @return ESP_OK on success, + * ESP_ERR_INVALID_STATE if no trace session is active, + * ESP_ERR_NOT_SUPPORTED if the encoder lacks function-trace callbacks. + */ +esp_err_t esp_trace_function_trace_start(void); + +/** + * @brief Stop recording function events. + * + * @return ESP_OK on success. + */ +esp_err_t esp_trace_function_trace_stop(void); + +#ifdef __cplusplus +} +#endif diff --git a/components/esp_trace/include/esp_trace_port_encoder.h b/components/esp_trace/include/esp_trace_port_encoder.h index 5f1365d51e6..57a1f1336a2 100644 --- a/components/esp_trace/include/esp_trace_port_encoder.h +++ b/components/esp_trace/include/esp_trace_port_encoder.h @@ -11,6 +11,7 @@ extern "C" { #endif #include +#include #include "esp_err.h" #include "esp_trace_types.h" @@ -24,7 +25,7 @@ typedef struct esp_trace_transport esp_trace_transport_t; * Defines the interface for trace encoders (libraries). * * @warning Runtime callbacks (write, flush, take_lock, give_lock, panic_handler) - * must not call FreeRTOS / IDF APIs that themselves emit trace hooks + * must not call FreeRTOS / IDF APIs that themselves trigger trace hooks * (e.g. vTaskDelay, xQueue*, xSemaphore*) — doing so re-enters the * tracing path and can deadlock on the encoder lock or crash in ISR * context. @@ -82,6 +83,31 @@ typedef struct { */ void (*give_lock)(esp_trace_encoder_t *enc, unsigned int_state); + /* + * Optional function-trace callbacks. Leave NULL if unsupported. + * + * Capability contract: an encoder supports function tracing when both + * function_enter and function_exit are set. The runtime checks these once at + * start and returns ESP_ERR_NOT_SUPPORTED otherwise. Callbacks receive raw + * addresses. The backend stays free to choose its own payload encoding. + */ + + /** + * @brief Send a function entry event + * @param enc Encoder instance + * @param func Start address of the entered function + * @param call_site Return address in the caller + */ + void (*function_enter)(esp_trace_encoder_t *enc, void *func, void *call_site); + + /** + * @brief Send a function exit event + * @param enc Encoder instance + * @param func Start address of the exited function + * @param call_site Return address in the caller + */ + void (*function_exit)(esp_trace_encoder_t *enc, void *func, void *call_site); + } esp_trace_encoder_vtable_t; /** @@ -93,6 +119,17 @@ struct esp_trace_encoder { void *ctx; ///< Encoder specific context }; +/** + * @brief Report a change in the encoder's recording state. + * + * Encoders whose recording is controlled by the host (e.g. SystemView start/stop + * over JTAG or UART) call this so dependent features such as function tracing can + * follow the actual recording state. + * + * @param active true if the encoder is now recording, false otherwise. + */ +void esp_trace_notify_recording_state(bool active); + #ifdef __cplusplus } #endif diff --git a/components/esp_trace/include/esp_trace_port_transport.h b/components/esp_trace/include/esp_trace_port_transport.h index 8385ce4a396..44d6a5a9e74 100644 --- a/components/esp_trace/include/esp_trace_port_transport.h +++ b/components/esp_trace/include/esp_trace_port_transport.h @@ -35,7 +35,7 @@ typedef enum { * Defines the interface for trace transports. * * @warning Runtime callbacks (read, write, flush_nolock, panic_handler) must - * not call FreeRTOS / IDF APIs that themselves emit trace hooks + * not call FreeRTOS / IDF APIs that themselves trigger trace hooks * (e.g. vTaskDelay, xQueue*, xSemaphore*) — they are invoked from * inside the encoder's lock and from ISR context, so re-entering * the tracing path can deadlock or assert. diff --git a/components/esp_trace/private_include/esp_trace_internal.h b/components/esp_trace/private_include/esp_trace_internal.h new file mode 100644 index 00000000000..6f57c0a8c0d --- /dev/null +++ b/components/esp_trace/private_include/esp_trace_internal.h @@ -0,0 +1,28 @@ +/* + * SPDX-FileCopyrightText: 2026 Espressif Systems (Shanghai) CO LTD + * + * SPDX-License-Identifier: Apache-2.0 + */ +#pragma once + +#ifdef __cplusplus +extern "C" { +#endif + +#include +#include "esp_err.h" +#include "esp_trace_port_encoder.h" + +/** + * @brief Returns the active encoder instance, or NULL if no session exists. + * + * @return The active encoder instance, or NULL if no session exists. + */ +esp_trace_encoder_t *esp_trace_get_active_encoder(void); + +/** + * @brief Notify the function-trace runtime of the encoder's recording state. + * + * @param active True if the encoder is recording, false otherwise. + */ +void esp_trace_function_trace_notify_recording(bool active); diff --git a/components/esp_trace/src/core/esp_trace_core.c b/components/esp_trace/src/core/esp_trace_core.c index 47e76b946a8..87897bf3748 100644 --- a/components/esp_trace/src/core/esp_trace_core.c +++ b/components/esp_trace/src/core/esp_trace_core.c @@ -22,6 +22,7 @@ #include "esp_trace_registry.h" #include "esp_trace.h" #include "esp_trace_port_transport.h" +#include "esp_trace_internal.h" #include "esp_private/startup_internal.h" #include "esp_private/esp_sys_event_system_init.h" #include "esp_private/esp_sys_event_panic.h" @@ -164,7 +165,11 @@ esp_err_t esp_trace_start(void) return ESP_ERR_NOT_SUPPORTED; } - return h->encoder.vt->start(&h->encoder); + esp_err_t err = h->encoder.vt->start(&h->encoder); + if (err == ESP_OK) { + esp_trace_notify_recording_state(true); + } + return err; } esp_err_t esp_trace_stop(void) @@ -178,7 +183,11 @@ esp_err_t esp_trace_stop(void) return ESP_ERR_NOT_SUPPORTED; } - return h->encoder.vt->stop(&h->encoder); + esp_err_t err = h->encoder.vt->stop(&h->encoder); + if (err == ESP_OK) { + esp_trace_notify_recording_state(false); + } + return err; } esp_err_t esp_trace_flush(void) @@ -218,6 +227,20 @@ esp_trace_handle_t esp_trace_get_active_handle(void) return s_active_handle; } +esp_trace_encoder_t *esp_trace_get_active_encoder(void) +{ + return s_active_handle ? &s_active_handle->encoder : NULL; +} + +void esp_trace_notify_recording_state(bool active) +{ +#if CONFIG_ESP_TRACE_FUNCTION_TRACE + esp_trace_function_trace_notify_recording(active); +#else + (void)active; +#endif +} + void esp_trace_panic_handler(const void *info) { esp_trace_handle_t h = s_active_handle; diff --git a/components/esp_trace/src/function_trace.c b/components/esp_trace/src/function_trace.c new file mode 100644 index 00000000000..afc89b82839 --- /dev/null +++ b/components/esp_trace/src/function_trace.c @@ -0,0 +1,143 @@ +/* + * SPDX-FileCopyrightText: 2026 Espressif Systems (Shanghai) CO LTD + * + * SPDX-License-Identifier: Apache-2.0 + */ + +/* + * Compiler-instrumented function tracing runtime. + * + * When a component is built with -finstrument-functions, the compiler inserts a + * call to __cyg_profile_func_enter/exit at the start and end of every function. + * These hooks gate the events and forward them to the active trace encoder. + */ + +#include +#include +#include "sdkconfig.h" +#include "soc/soc_caps.h" +#include "esp_cpu.h" +#include "esp_err.h" +#include "freertos/FreeRTOS.h" +#include "esp_trace_port_encoder.h" +#include "esp_trace_function_trace.h" +#include "esp_trace_internal.h" + +#define NO_INSTRUMENT __attribute__((no_instrument_function)) + +static volatile bool s_hook_active; + +#if CONFIG_ESP_TRACE_FUNCTION_TRACE_AUTO_START +/* Auto start: function tracing follows the encoder recording state. */ +static bool s_app_enabled = true; +#else +/* Manual start: enabled only when the application calls esp_trace_function_trace_start(). */ +static bool s_app_enabled; +#endif +/* Encoder recording state. Defaults true for encoders that do not report it. */ +static bool s_encoder_recording = true; + +/* Per-core re-entry guard so an interrupt cannot run the hooks recursively. */ +static volatile bool s_in_hook[SOC_CPU_CORES_NUM]; + +static esp_trace_encoder_t *s_enc; +static void (*s_fn_enter)(esp_trace_encoder_t *enc, void *func, void *call_site); +static void (*s_fn_exit)(esp_trace_encoder_t *enc, void *func, void *call_site); + +static esp_err_t resolve_encoder(void) +{ + if (s_enc) { + return ESP_OK; + } + + esp_trace_encoder_t *enc = esp_trace_get_active_encoder(); + if (!enc || !enc->vt) { + return ESP_ERR_INVALID_STATE; + } + + const esp_trace_encoder_vtable_t *vt = enc->vt; + if (!vt->function_enter || !vt->function_exit) { + return ESP_ERR_NOT_SUPPORTED; + } + + s_enc = enc; + s_fn_enter = vt->function_enter; + s_fn_exit = vt->function_exit; + return ESP_OK; +} + +static void update_hook_state(void) +{ + s_hook_active = s_app_enabled && s_encoder_recording && (s_enc != NULL); +} + +void esp_trace_function_trace_notify_recording(bool active) +{ + s_encoder_recording = active; +#if CONFIG_ESP_TRACE_FUNCTION_TRACE_AUTO_START + if (active) { + (void)resolve_encoder(); + } +#endif + update_hook_state(); +} + +esp_err_t esp_trace_function_trace_start(void) +{ + esp_err_t err = resolve_encoder(); + if (err != ESP_OK) { + return err; + } + s_app_enabled = true; + update_hook_state(); + return ESP_OK; +} + +esp_err_t esp_trace_function_trace_stop(void) +{ + s_app_enabled = false; + update_hook_state(); + return ESP_OK; +} + +static inline NO_INSTRUMENT bool hook_acquire(void) +{ + UBaseType_t irq = portSET_INTERRUPT_MASK_FROM_ISR(); + bool acquired = false; + int core = esp_cpu_get_core_id(); + if (!s_in_hook[core]) { + s_in_hook[core] = true; + acquired = true; + } + portCLEAR_INTERRUPT_MASK_FROM_ISR(irq); + return acquired; +} + +static inline NO_INSTRUMENT void hook_release(void) +{ + s_in_hook[esp_cpu_get_core_id()] = false; +} + +NO_INSTRUMENT void __cyg_profile_func_enter(void *func, void *call_site) +{ + if (!s_hook_active) { + return; + } + if (!hook_acquire()) { + return; + } + s_fn_enter(s_enc, func, call_site); + hook_release(); +} + +NO_INSTRUMENT void __cyg_profile_func_exit(void *func, void *call_site) +{ + if (!s_hook_active) { + return; + } + if (!hook_acquire()) { + return; + } + s_fn_exit(s_enc, func, call_site); + hook_release(); +} diff --git a/docs/en/api-guides/app_trace.rst b/docs/en/api-guides/app_trace.rst index 5c4818c121c..44e515cf7fd 100644 --- a/docs/en/api-guides/app_trace.rst +++ b/docs/en/api-guides/app_trace.rst @@ -557,11 +557,42 @@ Good instructions on how to install, configure, and visualize data in Impulse fr If you have problems with visualization (no data is shown or strange behaviors of zoom action are observed), you can try to delete current signal hierarchy and double-click on the necessary file or port. Eclipse will ask you to create a new signal hierarchy. +.. _app_trace-function-tracing: + +Compiler-Instrumented Function Tracing +"""""""""""""""""""""""""""""""""""""" + +Function tracing records every function entry and exit automatically, without manual trace points. When a source file is built with the GCC flag ``-finstrument-functions``, the compiler inserts a call at the start and end of each function. These calls go to hooks provided by the ``esp_trace`` component, which forward the events to the active trace encoder (for example SystemView). The events carry the raw function and call-site addresses. SystemView records them as raw addresses. Resolving the addresses to function names is done separately against the ELF file (for example with ``addr2line`` or a custom tool). + +Enable it under ``Component config`` > ``ESP Trace Configuration`` > ``Function Tracing``. The following options control function tracing: + +- :ref:`CONFIG_ESP_TRACE_FUNCTION_TRACE` - build the function-trace hooks and runtime. +- :ref:`CONFIG_ESP_TRACE_FUNCTION_TRACE_AUTO_START` - when enabled (default), recording follows the encoder's state and begins as soon as the host starts the session. When disabled, drop events until the application calls :cpp:func:`esp_trace_function_trace_start`; an active host session alone is not enough. + +Enabling the option compiles the hooks and runtime into the build. It does not add ``-finstrument-functions`` to any code, so on its own it produces no events. To trace a component or file, add the flag from its own ``CMakeLists.txt`` for the sources you want traced: + +.. code-block:: cmake + + if(CONFIG_ESP_TRACE_FUNCTION_TRACE) + target_compile_options(${COMPONENT_LIB} PRIVATE -finstrument-functions) + endif() + +Use the GCC ``-finstrument-functions-exclude-file-list`` and ``-finstrument-functions-exclude-function-list`` flags to skip specific files or functions. Keep instrumentation scoped to your own components, and do not instrument code that runs with the flash cache disabled (IRAM ISRs, SPI flash operations). + +After collecting a SystemView capture (see `Application Specific Tracing`_), decode the function-trace events with the processing script: + +.. code-block:: bash + + $IDF_PATH/tools/esp_app_trace/sysviewtrace_proc.py -i func -b -t {IDF_TARGET_TOOLCHAIN_PREFIX}- file:///path/to/trace.svdat + +The ``-i func`` option selects the function-trace event stream. The script uses the ELF file and toolchain prefix to resolve addresses, then prints a per-function report listing each traced function with its address, entry and exit counts, and source location. + Application Examples """""""""""""""""""" - :example:`system/sysview_tracing` demonstrates how to trace FreeRTOS task and system events using SEGGER SystemView. - :example:`system/sysview_tracing_heap_log` demonstrates heap allocation tracing alongside SystemView events. +- :example:`system/function_tracing` demonstrates compiler-instrumented function entry/exit tracing and how to control which code is instrumented. .. _app_trace-gcov-source-code-coverage: diff --git a/examples/system/.build-test-rules.yml b/examples/system/.build-test-rules.yml index b2c62dbac44..5b641d6d7c3 100644 --- a/examples/system/.build-test-rules.yml +++ b/examples/system/.build-test-rules.yml @@ -89,6 +89,15 @@ examples/system/flash_suspend: temporary: true reason: the other targets are not tested yet +examples/system/function_tracing: + disable_test: + - if: IDF_TARGET == "esp32h21" + temporary: true + reason: lack of runners + depends_components: + - esp_trace + - app_trace + examples/system/gcov: disable_test: - if: IDF_TARGET == "esp32h21" diff --git a/examples/system/function_tracing/CMakeLists.txt b/examples/system/function_tracing/CMakeLists.txt new file mode 100644 index 00000000000..11f77dfeef4 --- /dev/null +++ b/examples/system/function_tracing/CMakeLists.txt @@ -0,0 +1,8 @@ +# The following lines of boilerplate have to be in your project's CMakeLists +# in this exact order for cmake to work correctly +cmake_minimum_required(VERSION 3.22) + +include($ENV{IDF_PATH}/tools/cmake/project.cmake) +# "Trim" the build. Include the minimal set of components, main, and anything it depends on. +idf_build_set_property(MINIMAL_BUILD ON) +project(function_tracing) diff --git a/examples/system/function_tracing/README.md b/examples/system/function_tracing/README.md new file mode 100644 index 00000000000..6d5be8e927c --- /dev/null +++ b/examples/system/function_tracing/README.md @@ -0,0 +1,138 @@ +| Supported Targets | ESP32 | ESP32-C2 | ESP32-C3 | ESP32-C5 | ESP32-C6 | ESP32-C61 | ESP32-H2 | ESP32-H21 | ESP32-H4 | ESP32-P4 | ESP32-S2 | ESP32-S3 | ESP32-S31 | +| ----------------- | ----- | -------- | -------- | -------- | -------- | --------- | -------- | --------- | -------- | -------- | -------- | -------- | --------- | + +# Example: Compiler-Instrumented Function Tracing (function_tracing) + +This example shows how to trace function entry/exit automatically with the `esp_trace` compiler-instrumented function tracing feature, and how to control **which** code is instrumented. + +When a source file is built with the GCC flag `-finstrument-functions`, the compiler inserts a call at the start and end of every function. Those calls go to hooks provided by `esp_trace`, which forward the events to the active trace encoder (SystemView here). The events carry the raw function and call-site addresses. SystemView shows the enter/exit sequence with those addresses. Resolving the addresses to function names is done separately against the ELF file (for example with `addr2line` or a custom tool). + +Unlike RTOS-aware tracing (task switches, semaphores, etc.), function tracing needs no manual trace points. You add one compile flag to a component and the whole call flow is captured. + +## What this example demonstrates + +- Instrument a whole component (`components/ft_demo`) by adding `-finstrument-functions` to its build. +- Instrument only selected sources (`main`) by setting the flag per source file. +- `-finstrument-functions-exclude-file-list` — exclude whole files as a comma-separated list (`ft_demo_hot.c`, `ft_demo_quiet.c`). +- `-finstrument-functions-exclude-function-list` — exclude a single function by name (`ft_demo_secret`). + +The workload (`example_workload()`) calls four things every iteration: + +| Call | Instrumented? | Why | +| --------------------- | ------------- | ------------------------------------------------ | +| `ft_demo_run()` | yes | component is instrumented, appears as enter/exit | +| `ft_demo_secret()` | no | excluded by `-...-exclude-function-list` | +| `ft_demo_hot_loop()` | no | its file is excluded by `-...-exclude-file-list` | +| `ft_demo_quiet_path()`| no | its file is the 2nd `-...-exclude-file-list` entry | + +So in the captured trace you should see `ft_demo_run -> ft_demo_level1 -> ft_demo_level2`, but **not** `ft_demo_secret`, `ft_demo_hot_loop` or `ft_demo_quiet_path`. + +The same workload task is created pinned to each core, so on a dual-core target the multi-core capture shows function tracing on both cores (one task per core). On a single-core target it is one task on core 0. + +## Project layout + +``` +function_tracing/ +├── main/ +│ ├── function_tracing_example_main.c # workload + trace setup +│ └── CMakeLists.txt # instruments this source only +├── components/ +│ └── ft_demo/ +│ ├── ft_demo.c # instrumented call graph + excluded-by-name function +│ ├── ft_demo_hot.c # excluded-by-file (1st exclude-file-list entry) +│ ├── ft_demo_quiet.c # excluded-by-file (2nd exclude-file-list entry) +│ └── CMakeLists.txt # instruments the whole component + exclude flags +├── sdkconfig.defaults # enables function tracing +├── sdkconfig.ci.jtag # apptrace over JTAG +├── SYSVIEW_FreeRTOS.txt # event names for the function-trace module +└── gdbinit +``` + +## Instrumenting your code + +A component is instrumented from its own `CMakeLists.txt`, after `idf_component_register()`, by adding `-finstrument-functions` to its build. Guard it with the config so the flag is absent when the feature is off — otherwise the `__cyg_profile_*` hooks are undefined at link time: + +```cmake +# whole component (see components/ft_demo/CMakeLists.txt) +if(CONFIG_ESP_TRACE_FUNCTION_TRACE) + target_compile_options(${COMPONENT_LIB} PRIVATE -finstrument-functions) +endif() + +# or only specific sources (see main/CMakeLists.txt) +if(CONFIG_ESP_TRACE_FUNCTION_TRACE) + set_source_files_properties(my_file.c PROPERTIES + COMPILE_OPTIONS "-finstrument-functions") +endif() +``` + +Instrumentation is applied per component, so you trace only your own code. ESP-IDF internals are not instrumented (this keeps event volume manageable and avoids tracing code that runs with the flash cache disabled). + +To exclude individual files or functions from an otherwise-instrumented component, add the GCC blocklist flags: + +```cmake +if(CONFIG_ESP_TRACE_FUNCTION_TRACE) + target_compile_options(${COMPONENT_LIB} PRIVATE + -finstrument-functions + -finstrument-functions-exclude-file-list=ft_demo_hot,ft_demo_quiet + -finstrument-functions-exclude-function-list=ft_demo_secret) +endif() +``` + +Each list is a comma-separated set of substrings matched against the source file path / function name, so a single entry can cover several files and you can list several at once. + +## How recording starts + +This example records when the **host** starts the SystemView session over JTAG (OpenOCD `mon esp sysview_mcore start`). Because `CONFIG_ESP_TRACE_FUNCTION_TRACE_AUTO_START` is enabled, no explicit `esp_trace_function_trace_start()` call is needed. Recording follows the encoder's recording state. + +## Build, run and capture (JTAG + OpenOCD) + +1. Connect a JTAG interface and [run OpenOCD](https://docs.espressif.com/projects/esp-idf/en/latest/api-guides/jtag-debugging/index.html#run-openocd). + +2. Build and flash with the JTAG config: + + ``` + idf.py set-target + idf.py -D SDKCONFIG_DEFAULTS="sdkconfig.defaults;sdkconfig.ci.jtag" build flash monitor + ``` + +3. Start tracing automatically from GDB using the provided `gdbinit` (it breaks at `app_main` and runs `mon esp sysview_mcore start`): + + ``` + riscv32-esp-elf-gdb -x gdbinit build/function_tracing.elf + ``` + + Replace the GDB binary with the one matching your target (e.g. `xtensa-esp32-elf-gdb`). Trace data is written to `/tmp/function_tracing.svdat`. + + This example uses `esp sysview_mcore`, which captures all cores into a single file in SEGGER's official multi-core format. It requires SystemView **v3.60 or later**. On a dual-core target the one file holds both cores. For older SystemView versions, use `mon esp sysview start [core1_file]` instead to write a separate file per core. + +4. When enough data is captured, stop tracing: + + ``` + mon esp sysview_mcore stop + ``` + +## Viewing in SystemView and naming the events + +Open the `.svdat` file in the SEGGER SystemView application. + +The function-trace events arrive as numeric module event IDs. To show them as names, copy this example's `SYSVIEW_FreeRTOS.txt` into your SystemView installation directory (or merge its entries): + +``` +512 function_enter func=%p call_site=%p +513 function_exit func=%p call_site=%p +``` + +`func` is the traced function start address. `call_site` is the caller return address. SystemView records both as raw addresses. Map them to function names offline against the ELF file (for example with `addr2line`). + +The IDs are not chosen by the application: SystemView assigns each registered module an `EventOffset` (the first module gets `512`) and events are `EventOffset + index`. In this example the function-trace module is the only one registered, so it occupies `512-513`. + +## Configuration + +Function tracing is configured under **Component config → ESP Trace Configuration → Function Tracing** in `menuconfig`. Each option has built-in help. This example enables it and relies on the default `CONFIG_ESP_TRACE_FUNCTION_TRACE_AUTO_START` so recording follows the host session. File/function exclusion uses the `-finstrument-functions-exclude-*` compile flags (see [Instrumenting your code](#instrumenting-your-code)). + +For the full feature description and option reference, see the *Compiler-Instrumented Function Tracing* section of the [Application Level Tracing guide](https://docs.espressif.com/projects/esp-idf/en/latest/api-guides/app_trace.html#compiler-instrumented-function-tracing). + +## Limitations + +- Instrumentation adds overhead to every traced function call and increases code size and stack usage. +- Do not instrument code that runs with the flash cache disabled (IRAM ISRs, SPI flash operations). Keep instrumentation scoped to your own components. diff --git a/examples/system/function_tracing/SYSVIEW_FreeRTOS.txt b/examples/system/function_tracing/SYSVIEW_FreeRTOS.txt new file mode 100644 index 00000000000..fd576e7e2bd --- /dev/null +++ b/examples/system/function_tracing/SYSVIEW_FreeRTOS.txt @@ -0,0 +1,2 @@ +512 function_enter func=%p call_site=%p +513 function_exit func=%p call_site=%p diff --git a/examples/system/function_tracing/components/ft_demo/CMakeLists.txt b/examples/system/function_tracing/components/ft_demo/CMakeLists.txt new file mode 100644 index 00000000000..d2b8b7bfef6 --- /dev/null +++ b/examples/system/function_tracing/components/ft_demo/CMakeLists.txt @@ -0,0 +1,15 @@ +idf_component_register(SRCS "ft_demo.c" "ft_demo_hot.c" "ft_demo_quiet.c" + INCLUDE_DIRS "include") + +# Opt the whole component into compiler-instrumented function tracing by adding +# -finstrument-functions to its build. The guard keeps the flag out when the +# feature is off, otherwise the __cyg_profile_* hooks would be undefined at link. +# The exclude-list flags skip specific files / functions: +# - ft_demo_hot.c and ft_demo_quiet.c are excluded by file (comma-separated) +# - ft_demo_secret is excluded by function name +if(CONFIG_ESP_TRACE_FUNCTION_TRACE) + target_compile_options(${COMPONENT_LIB} PRIVATE + -finstrument-functions + -finstrument-functions-exclude-file-list=ft_demo_hot,ft_demo_quiet + -finstrument-functions-exclude-function-list=ft_demo_secret) +endif() diff --git a/examples/system/function_tracing/components/ft_demo/ft_demo.c b/examples/system/function_tracing/components/ft_demo/ft_demo.c new file mode 100644 index 00000000000..54f7c1368ae --- /dev/null +++ b/examples/system/function_tracing/components/ft_demo/ft_demo.c @@ -0,0 +1,34 @@ +/* + * SPDX-FileCopyrightText: 2026 Espressif Systems (Shanghai) CO LTD + * + * SPDX-License-Identifier: Apache-2.0 + * + * Function Tracing Example - demo library +*/ + +#include "ft_demo.h" + +/* noinline keeps each function as a distinct call so the compiler inserts + * enter/exit hooks instead of inlining them away. */ +static uint32_t __attribute__((noinline)) ft_demo_level2(uint32_t v) +{ + return v * 3u + 1u; +} + +static uint32_t __attribute__((noinline)) ft_demo_level1(uint32_t v) +{ + return ft_demo_level2(v) + ft_demo_level2(v + 1u); +} + +void ft_demo_run(uint32_t iteration) +{ + volatile uint32_t r = ft_demo_level1(iteration); + (void)r; +} + +void __attribute__((noinline)) ft_demo_secret(void) +{ + /* Excluded from instrumentation by name, so no enter/exit is recorded even + * though this file is compiled with -finstrument-functions. */ + __asm__ volatile(""); +} diff --git a/examples/system/function_tracing/components/ft_demo/ft_demo_hot.c b/examples/system/function_tracing/components/ft_demo/ft_demo_hot.c new file mode 100644 index 00000000000..e44dccd5f14 --- /dev/null +++ b/examples/system/function_tracing/components/ft_demo/ft_demo_hot.c @@ -0,0 +1,21 @@ +/* + * SPDX-FileCopyrightText: 2026 Espressif Systems (Shanghai) CO LTD + * + * SPDX-License-Identifier: Apache-2.0 + * + * Function Tracing Example - demo library (excluded file) +*/ + +#include "ft_demo.h" + +/* This whole file is listed in the component's -finstrument-functions-exclude-file-list + * flag, so none of its functions are instrumented even though the component opts + * in. Use this for hot paths you do not want to trace. */ +uint32_t ft_demo_hot_loop(uint32_t n) +{ + uint32_t acc = 0; + for (uint32_t i = 0; i < n; i++) { + acc += i * i; + } + return acc; +} diff --git a/examples/system/function_tracing/components/ft_demo/ft_demo_quiet.c b/examples/system/function_tracing/components/ft_demo/ft_demo_quiet.c new file mode 100644 index 00000000000..3fad79370e7 --- /dev/null +++ b/examples/system/function_tracing/components/ft_demo/ft_demo_quiet.c @@ -0,0 +1,21 @@ +/* + * SPDX-FileCopyrightText: 2026 Espressif Systems (Shanghai) CO LTD + * + * SPDX-License-Identifier: Apache-2.0 + * + * Function Tracing Example - demo library (second excluded file) +*/ + +#include "ft_demo.h" + +/* A second file added to the component's -finstrument-functions-exclude-file-list + * as a separate, comma-separated entry. It shows the exclude list accepts more + * than one substring. Like ft_demo_hot.c, none of its functions are instrumented. */ +uint32_t ft_demo_quiet_path(uint32_t n) +{ + uint32_t acc = 1; + for (uint32_t i = 1; i <= n; i++) { + acc = (acc * i) % 1000u; + } + return acc; +} diff --git a/examples/system/function_tracing/components/ft_demo/include/ft_demo.h b/examples/system/function_tracing/components/ft_demo/include/ft_demo.h new file mode 100644 index 00000000000..f8f8da6f89b --- /dev/null +++ b/examples/system/function_tracing/components/ft_demo/include/ft_demo.h @@ -0,0 +1,34 @@ +/* + * SPDX-FileCopyrightText: 2026 Espressif Systems (Shanghai) CO LTD + * + * SPDX-License-Identifier: Apache-2.0 + * + * Function Tracing Example - demo library +*/ +#pragma once + +#include + +#ifdef __cplusplus +extern "C" { +#endif + +/* Runs a small nested call graph (ft_demo_run -> level1 -> level2). These + * functions are instrumented and appear as function_enter/function_exit. */ +void ft_demo_run(uint32_t iteration); + +/* Instrumented file, but excluded by name through the component's + * -finstrument-functions-exclude-function-list flag: it produces no events. */ +void ft_demo_secret(void); + +/* Lives in ft_demo_hot.c, which is excluded as a whole through the component's + * -finstrument-functions-exclude-file-list flag: it produces no events. */ +uint32_t ft_demo_hot_loop(uint32_t n); + +/* Lives in ft_demo_quiet.c, a second comma-separated entry in the component's + * -finstrument-functions-exclude-file-list flag: it also produces no events. */ +uint32_t ft_demo_quiet_path(uint32_t n); + +#ifdef __cplusplus +} +#endif diff --git a/examples/system/function_tracing/gdbinit b/examples/system/function_tracing/gdbinit new file mode 100644 index 00000000000..48cecaa4026 --- /dev/null +++ b/examples/system/function_tracing/gdbinit @@ -0,0 +1,13 @@ +set pagination off +target remote :3333 + +mon reset halt +maintenance flush register-cache + +b app_main +commands +mon esp sysview_mcore start file:///tmp/function_tracing.svdat +c +end + +c diff --git a/examples/system/function_tracing/main/CMakeLists.txt b/examples/system/function_tracing/main/CMakeLists.txt new file mode 100644 index 00000000000..d9fbd0a6a69 --- /dev/null +++ b/examples/system/function_tracing/main/CMakeLists.txt @@ -0,0 +1,9 @@ +idf_component_register(SRCS "function_tracing_example_main.c" + PRIV_REQUIRES ft_demo + INCLUDE_DIRS ".") + +# Demonstrate file-level instrumentation. It instruments only this source. +if(CONFIG_ESP_TRACE_FUNCTION_TRACE) + set_source_files_properties(function_tracing_example_main.c PROPERTIES + COMPILE_OPTIONS "-finstrument-functions") +endif() diff --git a/examples/system/function_tracing/main/function_tracing_example_main.c b/examples/system/function_tracing/main/function_tracing_example_main.c new file mode 100644 index 00000000000..a9b71a9ef4d --- /dev/null +++ b/examples/system/function_tracing/main/function_tracing_example_main.c @@ -0,0 +1,72 @@ +/* + * SPDX-FileCopyrightText: 2026 Espressif Systems (Shanghai) CO LTD + * + * SPDX-License-Identifier: Apache-2.0 + * + * Function Tracing Example +*/ + +#include +#include +#include "sdkconfig.h" +#include "esp_log.h" +#include "freertos/FreeRTOS.h" +#include "freertos/task.h" +#include "esp_trace.h" +#include "ft_demo.h" + +static const char *TAG = "function-tracing"; + +static void __attribute__((noinline)) example_workload(uint32_t iteration) +{ + ft_demo_run(iteration); /* traced: ft_demo_run -> level1 -> level2 */ + ft_demo_secret(); /* excluded by function name: not traced */ + ft_demo_hot_loop(64); /* excluded by file: not traced */ + ft_demo_quiet_path(8); /* excluded by file (2nd list entry): not traced */ +} + +static void example_task(void *arg) +{ + (void)arg; + uint32_t iteration = 0; + + while (1) { + example_workload(iteration); + ESP_LOGI(TAG, "workload iteration %" PRIu32 " on core %d", iteration, xPortGetCoreID()); + iteration++; + vTaskDelay(pdMS_TO_TICKS(200)); + } +} + +#if CONFIG_ESP_TRACE_TRANSPORT_APPTRACE +#include "esp_app_trace.h" +esp_trace_open_params_t esp_trace_get_user_params(void) +{ + static esp_apptrace_config_t app_trace_config = APPTRACE_CONFIG_DEFAULT(); + + esp_trace_open_params_t trace_params = { + .core_cfg = NULL, + .encoder_name = "sysview", + .encoder_cfg = NULL, + .transport_name = "apptrace", + .transport_cfg = &app_trace_config, + }; + return trace_params; +} +#endif + +void app_main(void) +{ + ESP_LOGI(TAG, "Hello from function_tracing example!"); + + /* Recording is host-driven: it starts when the SystemView host (OpenOCD + * "mon esp sysview_mcore start") begins the session. No explicit start call + * is needed because CONFIG_ESP_TRACE_FUNCTION_TRACE_AUTO_START is enabled. */ + + + for (int core = 0; core < CONFIG_FREERTOS_NUMBER_OF_CORES; core++) { + char name[configMAX_TASK_NAME_LEN]; + snprintf(name, sizeof(name), "ft_workload%d", core); + xTaskCreatePinnedToCore(example_task, name, 4096, NULL, 5, NULL, core); + } +} diff --git a/examples/system/function_tracing/main/idf_component.yml b/examples/system/function_tracing/main/idf_component.yml new file mode 100644 index 00000000000..ed17493ca93 --- /dev/null +++ b/examples/system/function_tracing/main/idf_component.yml @@ -0,0 +1,6 @@ +## IDF Component Manager Manifest File +dependencies: + ## Required IDF version + idf: + version: '>=6.0' + espressif/esp_sysview: ^1 diff --git a/examples/system/function_tracing/pytest_function_tracing.py b/examples/system/function_tracing/pytest_function_tracing.py new file mode 100644 index 00000000000..7e54bdcc38f --- /dev/null +++ b/examples/system/function_tracing/pytest_function_tracing.py @@ -0,0 +1,156 @@ +# SPDX-FileCopyrightText: 2026 Espressif Systems (Shanghai) CO LTD +# SPDX-License-Identifier: Unlicense OR CC0-1.0 +import json +import os.path +import re +import shutil +import subprocess +import sys +import time +import typing + +import pexpect +import pytest +from pytest_embedded_idf import IdfDut +from pytest_embedded_idf.utils import idf_parametrize +from pytest_embedded_idf.utils import soc_filtered_targets + +if typing.TYPE_CHECKING: + from conftest import OpenOCD + +# Function-trace events are a SystemView module. The first (only) registered module +# gets EventOffset 512, so enter uses ID 512 and exit uses ID 513. +FT_EVENT_ENTER = 512 +FT_EVENT_EXIT = 513 + +# Demo source compiled with instrumentation. Its functions must be traced. +INSTRUMENTED_SOURCE = 'ft_demo.c' +# Demo sources excluded by file. Their functions must never be traced. +EXCLUDED_SOURCES = ['ft_demo_hot.c', 'ft_demo_quiet.c'] + + +def _encode_event_id(event_id: int) -> bytes: + """Encode a SystemView event ID the way SEGGER_SYSVIEW does (base-128, LSB first).""" + out = bytearray() + while True: + b = event_id & 0x7F + event_id >>= 7 + out.append(b | 0x80 if event_id else b) + if not event_id: + return bytes(out) + + +def _toolchain_prefix(binary_path: str) -> str: + with open(os.path.join(binary_path, 'project_description.json')) as f: + return str(json.load(f)['monitor_toolprefix']) + + +def _validate_function_trace_manual(trace_log: str) -> None: + """Fallback validation when no toolchain is available to decode the capture. + + The module description string is not in a JTAG capture (it is recorded before + recording is enabled and never re-sent), so check for the enter/exit event IDs. + """ + with open(trace_log, 'rb') as f: + content = f.read() + enter = content.count(_encode_event_id(FT_EVENT_ENTER)) + exit_ = content.count(_encode_event_id(FT_EVENT_EXIT)) + assert enter > 0 and exit_ > 0, f'no function enter/exit events in {trace_log} (enter={enter}, exit={exit_})' + + +def _validate_function_trace(trace_log: str, idf_path: str, elf_file: str, binary_path: str) -> None: + """Decode function-trace events with sysviewtrace_proc.py and check instrumented + functions are traced while excluded sources are not. Fall back to counting + enter/exit packets when the target toolchain is not available.""" + toolchain = _toolchain_prefix(binary_path) + if shutil.which(f'{toolchain}addr2line') is None: + print(f'addr2line not found for {toolchain}, using manual validation') + _validate_function_trace_manual(trace_log) + return + + proc_script = os.path.join(idf_path, 'tools', 'esp_app_trace', 'sysviewtrace_proc.py') + result = subprocess.run( + [sys.executable, proc_script, '-b', elf_file, '-t', toolchain, '-i', 'func', f'file://{trace_log}'], + capture_output=True, + text=True, + ) + report = result.stdout + result.stderr + assert result.returncode == 0, f'sysviewtrace_proc.py failed:\n{report}' + + print(f'{report}') + + m = re.search(r'Processed (\d+) function trace events\.', report) + assert m and int(m.group(1)) > 0, f'no function trace events decoded:\n{report}' + assert INSTRUMENTED_SOURCE in report, f'instrumented functions ({INSTRUMENTED_SOURCE}) not traced:\n{report}' + for excluded in EXCLUDED_SOURCES: + assert excluded not in report, f'excluded source {excluded} was traced:\n{report}' + + +def _validate_trace_data(trace_log: str, target: str, dual_core: bool) -> None: + """Validate the multi-core capture contains SystemView trace data for each core.""" + with open(trace_log, 'rb') as f: + content = f.read() + for idx in range(2 if dual_core else 1): + 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}' + + +def _test_function_tracing_jtag(openocd_dut: 'OpenOCD', idf_path: str, dut: IdfDut) -> None: + # Single multi-core capture file (esp sysview_mcore). + trace_log = os.path.join(dut.logdir, 'function_tracing.svdat') + dual_core = not dut.app.sdkconfig.get('ESP_SYSTEM_SINGLE_CORE_MODE') or dut.target == 'esp32s3' + + # Prepare gdbinit file pointing at this run's capture 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) as f_r, open(gdbinit, 'w') as f_w: + for line in f_r: + if line.startswith('mon esp sysview_mcore start'): + f_w.write(f'mon esp sysview_mcore start file://{trace_log}\n') + else: + f_w.write(line) + + time.sleep(1) # Wait for the USJ port to be ready + dut.expect_exact('function-tracing: Hello from function_tracing example!', timeout=5) + with ( + openocd_dut.run() as openocd, + 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 has been restarted by gdb since the last dut.expect() + dut.expect(re.compile(rb'function-tracing: workload iteration \d+'), timeout=30) + + # Let function-trace samples accumulate while recording. + time.sleep(1) + openocd.write('esp sysview_mcore stop') + openocd.apptrace_wait_stop() + + _validate_trace_data(trace_log, dut.target, dual_core) + _validate_function_trace(trace_log, idf_path, dut.app.elf_file, dut.app.binary_path) + + +@pytest.mark.jtag +@idf_parametrize('config', ['jtag'], indirect=['config']) +@idf_parametrize('target', ['esp32', 'esp32c2', 'esp32s2'], indirect=['target']) +def test_function_tracing_jtag(openocd_dut: 'OpenOCD', idf_path: str, dut: IdfDut) -> None: + _test_function_tracing_jtag(openocd_dut, idf_path, dut) + + +@pytest.mark.usb_serial_jtag +@idf_parametrize('config', ['jtag'], indirect=['config']) +@idf_parametrize( + 'target', + soc_filtered_targets('SOC_USB_SERIAL_JTAG_SUPPORTED == 1'), + indirect=['target'], +) +@idf_parametrize('port', ['/dev/serial_ports/ttyUSB-esp32'], indirect=['port']) +def test_function_tracing_usj(openocd_dut: 'OpenOCD', idf_path: str, dut: IdfDut) -> None: + _test_function_tracing_jtag(openocd_dut, idf_path, dut) diff --git a/examples/system/function_tracing/sdkconfig.ci.jtag b/examples/system/function_tracing/sdkconfig.ci.jtag new file mode 100644 index 00000000000..cf4e0e84558 --- /dev/null +++ b/examples/system/function_tracing/sdkconfig.ci.jtag @@ -0,0 +1,3 @@ +CONFIG_ESP_TRACE_TRANSPORT_APPTRACE=y +CONFIG_APPTRACE_DEST_JTAG=y +CONFIG_APPTRACE_BUF_SIZE=32768 diff --git a/examples/system/function_tracing/sdkconfig.defaults b/examples/system/function_tracing/sdkconfig.defaults new file mode 100644 index 00000000000..66634289b3a --- /dev/null +++ b/examples/system/function_tracing/sdkconfig.defaults @@ -0,0 +1,12 @@ +# 1ms tick period +CONFIG_FREERTOS_HZ=1000 +# Enable SystemView tracing by default +CONFIG_ESP_TRACE_ENABLE=y +CONFIG_ESP_TRACE_LIB_EXTERNAL=y +CONFIG_ESP_TRACE_TS_SOURCE_ESP_TIMER=y +CONFIG_SEGGER_SYSVIEW_EVT_TASK_START_EXEC_ENABLE=y +CONFIG_SEGGER_SYSVIEW_EVT_TASK_STOP_EXEC_ENABLE=y +CONFIG_SEGGER_SYSVIEW_EVT_TASK_CREATE_ENABLE=y + +# Compiler-instrumented function tracing +CONFIG_ESP_TRACE_FUNCTION_TRACE=y diff --git a/tools/esp_app_trace/espytrace/apptrace.py b/tools/esp_app_trace/espytrace/apptrace.py index 95d55b6b712..7500d20f373 100644 --- a/tools/esp_app_trace/espytrace/apptrace.py +++ b/tools/esp_app_trace/espytrace/apptrace.py @@ -1,9 +1,7 @@ -# SPDX-FileCopyrightText: 2022-2023 Espressif Systems (Shanghai) CO LTD +# SPDX-FileCopyrightText: 2022-2026 Espressif Systems (Shanghai) CO LTD # SPDX-License-Identifier: Apache-2.0 -from __future__ import print_function import os -import sys try: from urlparse import urlparse @@ -22,156 +20,190 @@ import elftools.elf.elffile as elffile def clock(): - if sys.version_info >= (3, 3): - return time.process_time() - else: - return time.clock() + return time.process_time() def addr2line(toolchain, elf_path, addr): """ - Creates trace reader. + Creates trace reader. - Parameters - ---------- - toolchain : string - toolchain prefix to retrieve source line locations using addresses - elf_path : string - path to ELF file to use - addr : int - address to retrieve source line location + Parameters + ---------- + toolchain : string + toolchain prefix to retrieve source line locations using addresses + elf_path : string + path to ELF file to use + addr : int + address to retrieve source line location - Returns - ------- - string - source line location string + Returns + ------- + string + source line location string """ try: - return subprocess.check_output(['%saddr2line' % toolchain, '-e', elf_path, '0x%x' % addr]).decode('utf-8') + return subprocess.check_output([f'{toolchain}addr2line', '-e', elf_path, f'0x{addr:x}']).decode('utf-8') except subprocess.CalledProcessError: return '' +def addr2symbol(toolchain, elf_path, addr): + """ + Resolves an address to its function name and source line location. + + Parameters + ---------- + toolchain : string + toolchain prefix to retrieve symbol info using addresses + elf_path : string + path to ELF file to use + addr : int + address to resolve + + Returns + ------- + tuple + (function name, source line location) strings, empty on failure + """ + try: + out = ( + subprocess.check_output([f'{toolchain}addr2line', '-f', '-e', elf_path, f'0x{addr:x}']) + .decode('utf-8') + .splitlines() + ) + except subprocess.CalledProcessError: + return '', '' + func = out[0].strip() if len(out) > 0 else '' + line = out[1].strip() if len(out) > 1 else '' + return func, line + + class ParseError(RuntimeError): """ - Parse error exception + Parse error exception """ + def __init__(self, message): RuntimeError.__init__(self, message) class ReaderError(RuntimeError): """ - Trace reader error exception + Trace reader error exception """ + def __init__(self, message): RuntimeError.__init__(self, message) class ReaderTimeoutError(ReaderError): """ - Trace reader timeout error + Trace reader timeout error """ + def __init__(self, tmo, sz): - ReaderError.__init__(self, 'Timeout %f sec while reading %d bytes!' % (tmo, sz)) + ReaderError.__init__(self, f'Timeout {tmo:f} sec while reading {sz:d} bytes!') class ReaderShutdownRequest(ReaderError): """ - Trace reader shutdown request error - Raised when user presses CTRL+C (SIGINT). + Trace reader shutdown request error + Raised when user presses CTRL+C (SIGINT). """ + def __init__(self): ReaderError.__init__(self, 'Shutdown request!') class Reader: """ - Base abstract reader class + Base abstract reader class """ + def __init__(self, tmo): """ - Constructor + Constructor - Parameters - ---------- - tmo : int - read timeout + Parameters + ---------- + tmo : int + read timeout """ self.timeout = tmo self.need_stop = False def read(self, sz): """ - Reads a number of bytes + Reads a number of bytes - Parameters - ---------- - sz : int - number of bytes to read + Parameters + ---------- + sz : int + number of bytes to read - Returns - ------- - bytes object - read bytes + Returns + ------- + bytes object + read bytes - Returns - ------- - ReaderTimeoutError - if timeout expires - ReaderShutdownRequest - if SIGINT was received during reading + Returns + ------- + ReaderTimeoutError + if timeout expires + ReaderShutdownRequest + if SIGINT was received during reading """ pass def readline(self): """ - Reads line + Reads line - Parameters - ---------- - sz : int - number of bytes to read + Parameters + ---------- + sz : int + number of bytes to read - Returns - ------- - string - read line + Returns + ------- + string + read line """ pass def forward(self, sz): """ - Moves read pointer to a number of bytes + Moves read pointer to a number of bytes - Parameters - ---------- - sz : int - number of bytes to read + Parameters + ---------- + sz : int + number of bytes to read """ pass def cleanup(self): """ - Cleans up reader + Cleans up reader """ self.need_stop = True class FileReader(Reader): """ - File reader class + File reader class """ + def __init__(self, path, tmo): """ - Constructor + Constructor - Parameters - ---------- - path : string - path to file to read - tmo : int - see Reader.__init__() + Parameters + ---------- + path : string + path to file to read + tmo : int + see Reader.__init__() """ Reader.__init__(self, tmo) self.trace_file_path = path @@ -179,7 +211,7 @@ class FileReader(Reader): def read(self, sz): """ - see Reader.read() + see Reader.read() """ data = b'' start_tm = clock() @@ -195,18 +227,18 @@ class FileReader(Reader): def get_pos(self): """ - Retrieves current file read position + Retrieves current file read position - Returns - ------- - int - read position + Returns + ------- + int + read position """ return self.trace_file.tell() def readline(self, linesep=os.linesep): """ - see Reader.read() + see Reader.read() """ line = '' start_tm = clock() @@ -222,7 +254,7 @@ class FileReader(Reader): def forward(self, sz): """ - see Reader.read() + see Reader.read() """ cur_pos = self.trace_file.tell() start_tm = clock() @@ -239,8 +271,9 @@ class FileReader(Reader): class NetRequestHandler: """ - Handler for incoming network requests (connections, datagrams) + Handler for incoming network requests (connections, datagrams) """ + def handle(self): while not self.server.need_stop: data = self.rfile.read(1024) @@ -252,13 +285,14 @@ class NetRequestHandler: class NetReader(FileReader): """ - Base netwoek socket reader class + Base netwoek socket reader class """ + def __init__(self, tmo): """ - see Reader.__init__() + see Reader.__init__() """ - fhnd,fname = tempfile.mkstemp() + fhnd, fname = tempfile.mkstemp() FileReader.__init__(self, fname, tmo) self.wtrace = os.fdopen(fhnd, 'wb') self.server_thread = threading.Thread(target=self.serve_forever) @@ -266,7 +300,7 @@ class NetReader(FileReader): def cleanup(self): """ - see Reader.cleanup() + see Reader.cleanup() """ FileReader.cleanup(self) self.shutdown() @@ -279,27 +313,29 @@ class NetReader(FileReader): class TCPRequestHandler(NetRequestHandler, SocketServer.StreamRequestHandler): """ - Handler for incoming TCP connections + Handler for incoming TCP connections """ + pass class TCPReader(NetReader, SocketServer.TCPServer): """ - TCP socket reader class + TCP socket reader class """ + def __init__(self, host, port, tmo, handler=TCPRequestHandler): """ - Constructor + Constructor - Parameters - ---------- - host : string - see SocketServer.BaseServer.__init__() - port : int - see SocketServer.BaseServer.__init__() - tmo : int - see Reader.__init__() + Parameters + ---------- + host : string + see SocketServer.BaseServer.__init__() + port : int + see SocketServer.BaseServer.__init__() + tmo : int + see Reader.__init__() """ SocketServer.TCPServer.__init__(self, (host, port), handler) NetReader.__init__(self, tmo) @@ -307,27 +343,29 @@ class TCPReader(NetReader, SocketServer.TCPServer): class UDPRequestHandler(NetRequestHandler, SocketServer.DatagramRequestHandler): """ - Handler for incoming UDP datagrams + Handler for incoming UDP datagrams """ + pass class UDPReader(NetReader, SocketServer.UDPServer): """ - UDP socket reader class + UDP socket reader class """ + def __init__(self, host, port, tmo, handler=UDPRequestHandler): """ - Constructor + Constructor - Parameters - ---------- - host : string - see SocketServer.BaseServer.__init__() - port : int - see SocketServer.BaseServer.__init__() - tmo : int - see Reader.__init__() + Parameters + ---------- + host : string + see SocketServer.BaseServer.__init__() + port : int + see SocketServer.BaseServer.__init__() + tmo : int + see Reader.__init__() """ SocketServer.UDPServer.__init__(self, (host, port), handler) NetReader.__init__(self, tmo) @@ -335,19 +373,19 @@ class UDPReader(NetReader, SocketServer.UDPServer): def reader_create(trc_src, tmo, handler=None): """ - Creates trace reader. + Creates trace reader. - Parameters - ---------- - trc_src : string - trace source URL. Supports 'file:///path/to/file' or (tcp|udp)://host:port - tmo : int - read timeout + Parameters + ---------- + trc_src : string + trace source URL. Supports 'file:///path/to/file' or (tcp|udp)://host:port + tmo : int + read timeout - Returns - ------- - Reader - reader object or None if URL scheme is not supported + Returns + ------- + Reader + reader object or None if URL scheme is not supported """ url = urlparse(trc_src) if len(url.scheme) == 0 or url.scheme == 'file': @@ -369,8 +407,9 @@ def reader_create(trc_src, tmo, handler=None): class TraceEvent: """ - Base class for all trace events. + Base class for all trace events. """ + def __init__(self, name, core_id, evt_id): self.name = name self.ctx_name = 'None' @@ -383,8 +422,8 @@ class TraceEvent: @property def ctx_desc(self): if self.in_irq: - return 'IRQ "%s"' % self.ctx_name - return 'task "%s"' % self.ctx_name + return f'IRQ "{self.ctx_name}"' + return f'task "{self.ctx_name}"' def to_jsonable(self): res = self.__dict__ @@ -397,54 +436,55 @@ class TraceEvent: class TraceDataProcessor: """ - Base abstract class for all trace data processors. + Base abstract class for all trace data processors. """ + def __init__(self, print_events, keep_all_events=False): """ - Constructor. + Constructor. - Parameters - ---------- - print_events : bool - if True every event will be printed as they arrive - keep_all_events : bool - if True all events will be kept in self.events in the order they arrive + Parameters + ---------- + print_events : bool + if True every event will be printed as they arrive + keep_all_events : bool + if True all events will be kept in self.events in the order they arrive """ self.print_events = print_events self.keep_all_events = keep_all_events self.total_events = 0 self.events = [] - # This can be changed by the root procesor that includes several sub-processors. + # This can be changed by the root processor that includes several sub-processors. # It is used access some method of root processor which can contain methods/data common for all sub-processors. # Common info could be current execution context, info about running tasks, available IRQs etc. self.root_proc = self def _print_event(self, event): """ - Base method to print an event. + Base method to print an event. - Parameters - ---------- - event : object - Event object + Parameters + ---------- + event : object + Event object """ - print('EVENT[{:d}]: {}'.format(self.total_events, event)) + print(f'EVENT[{self.total_events:d}]: {event}') def print_report(self): """ - Base method to print report. + Base method to print report. """ - print('Processed {:d} events'.format(self.total_events)) + print(f'Processed {self.total_events:d} events') def cleanup(self): """ - Base method to make cleanups. + Base method to make cleanups. """ pass def on_new_event(self, event): """ - Base method to process event. + Base method to process event. """ if self.print_events: self._print_event(event) @@ -455,26 +495,27 @@ class TraceDataProcessor: class LogTraceParseError(ParseError): """ - Log trace parse error exception. + Log trace parse error exception. """ + pass def get_str_from_elf(felf, str_addr): """ - Retrieves string from ELF file. + Retrieves string from ELF file. - Parameters - ---------- - felf : elffile.ELFFile - open ELF file handle to retrive format string from - str_addr : int - address of the string + Parameters + ---------- + felf : elffile.ELFFile + open ELF file handle to retrieve format string from + str_addr : int + address of the string - Returns - ------- - string - string or None if it was not found + Returns + ------- + string + string or None if it was not found """ tgt_str = '' for sect in felf.iter_sections(): @@ -498,44 +539,45 @@ def get_str_from_elf(felf, str_addr): class LogTraceEvent: """ - Log trace event. + Log trace event. """ + def __init__(self, fmt_addr, log_args): """ - Constructor. + Constructor. - Parameters - ---------- - fmt_addr : int - address of the format string - log_args : list - list of log message arguments + Parameters + ---------- + fmt_addr : int + address of the format string + log_args : list + list of log message arguments """ self.fmt_addr = fmt_addr self.args = log_args def get_message(self, felf): """ - Retrieves log message. + Retrieves log message. - Parameters - ---------- - felf : elffile.ELFFile - open ELF file handle to retrive format string from + Parameters + ---------- + felf : elffile.ELFFile + open ELF file handle to retrieve format string from - Returns - ------- - string - formatted log message + Returns + ------- + string + formatted log message - Raises - ------ - LogTraceParseError - if format string has not been found in ELF file + Raises + ------ + LogTraceParseError + if format string has not been found in ELF file """ fmt_str = get_str_from_elf(felf, self.fmt_addr) if not fmt_str: - raise LogTraceParseError('Failed to find format string for 0x%x' % self.fmt_addr) + raise LogTraceParseError(f'Failed to find format string for 0x{self.fmt_addr:x}') prcnt_idx = 0 for i, arg in enumerate(self.args): prcnt_idx = fmt_str.find('%', prcnt_idx, -2) # TODO: check str ending with % @@ -555,18 +597,19 @@ class LogTraceEvent: class BaseLogTraceDataProcessorImpl: """ - Base implementation for log data processors. + Base implementation for log data processors. """ + def __init__(self, print_log_events=False, elf_path=''): """ - Constructor. + Constructor. - Parameters - ---------- - print_log_events : bool - if True every log event will be printed as they arrive - elf_path : string - path to ELF file to retrieve format strings for log messages + Parameters + ---------- + print_log_events : bool + if True every log event will be printed as they arrive + elf_path : string + path to ELF file to retrieve format strings for log messages """ if len(elf_path): self.felf = elffile.ELFFile(open(elf_path, 'rb')) @@ -577,26 +620,26 @@ class BaseLogTraceDataProcessorImpl: def cleanup(self): """ - Cleanup + Cleanup """ if self.felf: self.felf.stream.close() def print_report(self): """ - Prints log report + Prints log report """ print('=============== LOG TRACE REPORT ===============') - print('Processed {:d} log messages.'.format(len(self.messages))) + print(f'Processed {len(self.messages):d} log messages.') def on_new_event(self, event): """ - Processes log events. + Processes log events. - Parameters - ---------- - event : LogTraceEvent - Event object. + Parameters + ---------- + event : LogTraceEvent + Event object. """ msg = event.get_message(self.felf) self.messages.append(msg) @@ -606,51 +649,57 @@ class BaseLogTraceDataProcessorImpl: class HeapTraceParseError(ParseError): """ - Heap trace parse error exception. + Heap trace parse error exception. """ + pass class HeapTraceDuplicateAllocError(HeapTraceParseError): """ - Heap trace duplicate allocation error exception. + Heap trace duplicate allocation error exception. """ + def __init__(self, addr, new_size, prev_size): """ - Constructor. + Constructor. - Parameters - ---------- - addr : int - memory block address - new_size : int - size of the new allocation - prev_size : int - size of the previous allocation + Parameters + ---------- + addr : int + memory block address + new_size : int + size of the new allocation + prev_size : int + size of the previous allocation """ - HeapTraceParseError.__init__(self, """Duplicate alloc @ 0x{:x}! - New alloc is {:d} bytes, - previous is {:d} bytes.""".format(addr, new_size, prev_size)) + HeapTraceParseError.__init__( + self, + f"""Duplicate alloc @ 0x{addr:x}! + New alloc is {new_size:d} bytes, + previous is {prev_size:d} bytes.""", + ) class HeapTraceEvent: """ - Heap trace event. + Heap trace event. """ + def __init__(self, trace_event, alloc, toolchain='', elf_path=''): """ - Constructor. + Constructor. - Parameters - ---------- - sys_view_event : TraceEvent - trace event object related to this heap event - alloc : bool - True for allocation event, otherwise False - toolchain_pref : string - toolchain prefix to retrieve source line locations using addresses - elf_path : string - path to ELF file to retrieve format strings for log messages + Parameters + ---------- + sys_view_event : TraceEvent + trace event object related to this heap event + alloc : bool + True for allocation event, otherwise False + toolchain_pref : string + toolchain prefix to retrieve source line locations using addresses + elf_path : string + path to ELF file to retrieve format strings for log messages """ self.trace_event = trace_event self.alloc = alloc @@ -675,7 +724,7 @@ class HeapTraceEvent: for addr in self.trace_event.params['callers'].value: if addr == 0: break - callers += '{}'.format(addr2line(self.toolchain, self.elf_path, addr)) + callers += f'{addr2line(self.toolchain, self.elf_path, addr)}' else: callers = '' for addr in self.trace_event.params['callers'].value: @@ -683,31 +732,32 @@ class HeapTraceEvent: break if len(callers): callers += ':' - callers += '0x{:x}'.format(addr) + callers += f'0x{addr:x}' if self.alloc: - return '[{:.9f}] HEAP: Allocated {:d} bytes @ 0x{:x} from {} on core {:d} by: {}'.format(self.trace_event.ts, - self.size, self.addr, - self.trace_event.ctx_desc, - self.trace_event.core_id, - callers) + return ( + f'[{self.trace_event.ts:.9f}] HEAP: Allocated {self.size:d} bytes @ 0x{self.addr:x} ' + f'from {self.trace_event.ctx_desc} on core {self.trace_event.core_id:d} by: {callers}' + ) else: - return '[{:.9f}] HEAP: Freed bytes @ 0x{:x} from {} on core {:d} by: {}'.format(self.trace_event.ts, - self.addr, self.trace_event.ctx_desc, - self.trace_event.core_id, callers) + return ( + f'[{self.trace_event.ts:.9f}] HEAP: Freed bytes @ 0x{self.addr:x} ' + f'from {self.trace_event.ctx_desc} on core {self.trace_event.core_id:d} by: {callers}' + ) class BaseHeapTraceDataProcessorImpl: """ - Base implementation for heap data processors. + Base implementation for heap data processors. """ + def __init__(self, print_heap_events=False): """ - Constructor. + Constructor. - Parameters - ---------- - print_heap_events : bool - if True every heap event will be printed as they arrive + Parameters + ---------- + print_heap_events : bool + if True every heap event will be printed as they arrive """ self._alloc_addrs = {} self.allocs = [] @@ -717,12 +767,12 @@ class BaseHeapTraceDataProcessorImpl: def on_new_event(self, event): """ - Processes heap events. Keeps track of active allocations list. + Processes heap events. Keeps track of active allocations list. - Parameters - ---------- - event : HeapTraceEvent - Event object. + Parameters + ---------- + event : HeapTraceEvent + Event object. """ self.heap_events_count += 1 if self.print_heap_events: @@ -733,7 +783,8 @@ class BaseHeapTraceDataProcessorImpl: self.allocs.append(event) self._alloc_addrs[event.addr] = event else: - # do not treat free on unknown addresses as errors, because these blocks coould be allocated when tracing was disabled + # do not treat free on unknown addresses as errors, because these blocks + # coould be allocated when tracing was disabled if event.addr in self._alloc_addrs: event.size = self._alloc_addrs[event.addr].size self.allocs.remove(self._alloc_addrs[event.addr]) @@ -743,10 +794,10 @@ class BaseHeapTraceDataProcessorImpl: def print_report(self): """ - Prints heap report + Prints heap report """ print('=============== HEAP TRACE REPORT ===============') - print('Processed {:d} heap events.'.format(self.heap_events_count)) + print(f'Processed {self.heap_events_count:d} heap events.') if len(self.allocs) == 0: print('OK - Heap errors was not found.') return @@ -758,4 +809,4 @@ class BaseHeapTraceDataProcessorImpl: if free.addr > alloc.addr and free.addr <= alloc.addr + alloc.size: print('Possible wrong free operation found') print(free) - print('Found {:d} leaked bytes in {:d} blocks.'.format(leaked_bytes, len(self.allocs))) + print(f'Found {leaked_bytes:d} leaked bytes in {len(self.allocs):d} blocks.') diff --git a/tools/esp_app_trace/espytrace/sysview.py b/tools/esp_app_trace/espytrace/sysview.py index 234bc90cd29..fe7eb22027e 100644 --- a/tools/esp_app_trace/espytrace/sysview.py +++ b/tools/esp_app_trace/espytrace/sysview.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: Apache-2.0 import copy import json @@ -175,7 +175,7 @@ def _read_init_seq(reader): SysViewTraceParseError If sync sequence is broken. """ - SYNC_SEQ_FMT = '<%dB' % SYSVIEW_SYNC_LEN + SYNC_SEQ_FMT = f'<{SYSVIEW_SYNC_LEN}B' sync_bytes = struct.unpack(SYNC_SEQ_FMT, reader.read(struct.calcsize(SYNC_SEQ_FMT))) for b in sync_bytes: if b != 0: @@ -266,7 +266,7 @@ def _decode_str(reader): if sz == 0xFF: buf = struct.unpack('<2B', reader.read(2)) sz = (buf[0] << 8) | buf[1] - (val,) = struct.unpack('<%ds' % sz, reader.read(sz)) + (val,) = struct.unpack(f'<{sz}s', reader.read(sz)) val = val.decode('utf-8') if sz < 0xFF: return (sz + 1, val) # one extra byte for length @@ -353,7 +353,7 @@ class SysViewEvent(apptrace.TraceEvent): if event has unknown or invalid format. """ if self.id not in events_fmt_map: - raise SysViewTraceParseError('Unknown event ID %d!' % self.id) + raise SysViewTraceParseError(f'Unknown event ID {self.id}!') self.name = events_fmt_map[self.id][0] evt_params_templates = events_fmt_map[self.id][1] params_len = 0 @@ -364,9 +364,7 @@ class SysViewEvent(apptrace.TraceEvent): sz, param_val = event_param.decode(reader, self.plen - params_len) except Exception as e: raise SysViewTraceParseError( - 'Failed to decode event {}({:d}) {:d} param @ 0x{:x}! {}'.format( - self.name, self.id, self.plen, cur_pos, e - ) + f'Failed to decode event {self.name}({self.id:d}) {self.plen:d} param @ 0x{cur_pos:x}! {e}' ) event_param.idx = i event_param.value = param_val @@ -374,20 +372,16 @@ class SysViewEvent(apptrace.TraceEvent): params_len += sz if self.id >= SYSVIEW_EVENT_ID_PREDEF_LEN_MAX and self.plen != params_len: raise SysViewTraceParseError( - 'Invalid event {}({:d}) payload len {:d}! Must be {:d}.'.format( - self.name, self.id, self.plen, params_len - ) + f'Invalid event {self.name}({self.id:d}) payload len {self.plen:d}! Must be {params_len:d}.' ) def __str__(self): params = '' for param in sorted(self.params.values(), key=lambda x: x.idx): - params += '{}, '.format(param) + params += f'{param}, ' if len(params): params = params[:-2] # remove trailing ', ' - return '{:.9f} - core[{:d}].{}({:d}), plen {:d}: [{}]'.format( - self.ts, self.core_id, self.name, self.id, self.plen, params - ) + return f'{self.ts:.9f} - core[{self.core_id:d}].{self.name}({self.id:d}), plen {self.plen:d}: [{params}]' class SysViewEventParam: @@ -431,7 +425,7 @@ class SysViewEventParam: pass def __str__(self): - return '{}: {}'.format(self.name, self.value) + return f'{self.name}: {self.value}' def to_jsonable(self): return {self.name: self.value} @@ -634,6 +628,49 @@ class SysViewHeapEvent(SysViewEvent): # self.name = 'SysViewHeapEvent' +class SysViewFunctionEvent(SysViewEvent): + """ + Function tracing related SystemView events class. + + Attributes + ---------- + events_fmt : dict + see return value of _read_events_map() + """ + + events_fmt = { + 0: ( + 'esp_sysview_function_enter', + [SysViewEventParamSimple('func', _decode_u32), SysViewEventParamSimple('call_site', _decode_u32)], + ), + 1: ( + 'esp_sysview_function_exit', + [SysViewEventParamSimple('func', _decode_u32), SysViewEventParamSimple('call_site', _decode_u32)], + ), + } + + def __init__(self, evt_id, core_id, events_off, reader): + """ + Constructor. Reads and optionally decodes event. + + Parameters + ---------- + evt_id : int + see SysViewEvent.__init__() + events_off : int + Offset for function events IDs. Greater or equal to SYSVIEW_MODULE_EVENT_OFFSET. + reader : apptrace.Reader + see SysViewEvent.__init__() + core_id : int + see SysViewEvent.__init__() + """ + cur_events_map = {} + for _id in self.events_fmt: + cur_events_map[events_off + _id] = self.events_fmt[_id] + SysViewEvent.__init__(self, evt_id, core_id, reader, cur_events_map) + # self.name = 'SysViewFunctionEvent' + + class SysViewTraceDataParser(apptrace.TraceDataProcessor): """ Base SystemView trace data parser class. @@ -646,11 +683,14 @@ class SysViewTraceDataParser(apptrace.TraceDataProcessor): log events stream ID. STREAMID_HEAP : int heap events stream ID. + STREAMID_FUNC : int + function tracing events stream ID. """ STREAMID_SYS = -1 STREAMID_LOG = 0 STREAMID_HEAP = 1 + STREAMID_FUNC = 2 def __init__(self, print_events=False, core_id=0): """ @@ -984,7 +1024,7 @@ class SysViewTraceDataProcessor(apptrace.TraceDataProcessor): if len(self.root_proc.ctx_stack[core_id]): return self.root_proc.ctx_stack[core_id][-1] if self._get_prev_context(core_id): - return SysViewEventContext(None, False, 'IDLE%d' % core_id) + return SysViewEventContext(None, False, f'IDLE{core_id}') return None def _get_prev_context(self, core_id): @@ -1059,18 +1099,18 @@ class SysViewTraceDataProcessor(apptrace.TraceDataProcessor): if SYSVIEW_EVTID_TASK_START_EXEC or SYSVIEW_EVTID_TASK_STOP_READY is received for unknown task. """ if event.core_id not in self.traces: - raise SysViewTraceParseError('Event for unknown core %d' % event.core_id) + raise SysViewTraceParseError(f'Event for unknown core {event.core_id}') else: trace = self.traces[event.core_id] if event.id == SYSVIEW_EVTID_ISR_ENTER: if event.params['irq_num'].value not in trace.irqs_info: - raise SysViewTraceParseError('Enter unknown ISR %d' % event.params['irq_num'].value) + raise SysViewTraceParseError(f'Enter unknown ISR {event.params["irq_num"].value}') if len(self.ctx_stack[event.core_id]): self.prev_ctx[event.core_id] = self.ctx_stack[event.core_id][-1] else: # the 1st context switching event after trace start is SYSVIEW_EVTID_ISR_ENTER, # so we have been in IDLE context - self.prev_ctx[event.core_id] = SysViewEventContext(None, False, 'IDLE%d' % event.core_id) + self.prev_ctx[event.core_id] = SysViewEventContext(None, False, f'IDLE{event.core_id}') # put new ISR context on top of the stack (the last in the list) self.ctx_stack[event.core_id].append( SysViewEventContext(event.params['irq_num'].value, True, trace.irqs_info[event.params['irq_num'].value]) @@ -1083,17 +1123,17 @@ class SysViewTraceDataProcessor(apptrace.TraceDataProcessor): # the 1st context switching event after trace start is SYSVIEW_EVTID_ISR_EXIT, # so we have been in ISR context, # but we do not know which one because SYSVIEW_EVTID_ISR_EXIT do not include the IRQ number - self.prev_ctx[event.core_id] = SysViewEventContext(None, True, 'IRQ_oncore%d' % event.core_id) + self.prev_ctx[event.core_id] = SysViewEventContext(None, True, f'IRQ_oncore{event.core_id}') elif event.id == SYSVIEW_EVTID_TASK_START_EXEC: if event.params['tid'].value not in trace.tasks_info: - raise SysViewTraceParseError('Start exec unknown task 0x%x' % event.params['tid'].value) + raise SysViewTraceParseError(f'Start exec unknown task 0x{event.params["tid"].value:x}') if len(self.ctx_stack[event.core_id]): # return to the previous context (the last in the list) self.prev_ctx[event.core_id] = self.ctx_stack[event.core_id][-1] else: # the 1st context switching event after trace start is SYSVIEW_EVTID_TASK_START_EXEC, # so we have been in IDLE context - self.prev_ctx[event.core_id] = SysViewEventContext(None, False, 'IDLE%d' % event.core_id) + self.prev_ctx[event.core_id] = SysViewEventContext(None, False, f'IDLE{event.core_id}') # only one task at a time in context stack (can be interrupted by a bunch of ISRs) self.ctx_stack[event.core_id] = [ SysViewEventContext(event.params['tid'].value, False, trace.tasks_info[event.params['tid'].value]) @@ -1109,7 +1149,7 @@ class SysViewTraceDataProcessor(apptrace.TraceDataProcessor): break elif event.id == SYSVIEW_EVTID_TASK_STOP_READY: if event.params['tid'].value not in trace.tasks_info: - raise SysViewTraceParseError('Stop ready unknown task 0x%x' % event.params['tid'].value) + raise SysViewTraceParseError(f'Stop ready unknown task 0x{event.params["tid"].value:x}') if len(self.ctx_stack[event.core_id]): if ( not self.ctx_stack[event.core_id][-1].irq @@ -1282,7 +1322,7 @@ class SysViewTraceDataJsonEncoder(json.JSONEncoder): blk_addr = '0x{:x}'.format(obj.params['addr'].value) callers = [] for addr in obj.params['callers'].value: - callers.append('0x{:x}'.format(addr)) + callers.append(f'0x{addr:x}') return { 'ctx_name': obj.ctx_name, 'in_irq': obj.in_irq, @@ -1355,6 +1395,43 @@ class SysViewHeapTraceDataParser(SysViewTraceDataExtEventParser): self.events_off = event.params['evt_off'].value +class SysViewFunctionTraceDataParser(SysViewTraceDataExtEventParser): + """ + SystemView trace data parser supporting function tracing events. + """ + + def __init__(self, print_events=False, core_id=0): + """ + SystemView trace data parser supporting multiple event streams. + see SysViewTraceDataExtEventParser.__init__() + """ + SysViewTraceDataExtEventParser.__init__( + self, events_num=len(SysViewFunctionEvent.events_fmt.keys()), core_id=core_id, print_events=print_events + ) + + def read_extension_event(self, evt_id, core_id, reader): + """ + Reads function tracing event. + see SysViewTraceDataParser.read_extension_event() + """ + if ( + self.events_off >= SYSVIEW_MODULE_EVENT_OFFSET + and evt_id >= self.events_off + and evt_id < self.events_off + self.events_num + ): + return SysViewFunctionEvent(evt_id, core_id, self.events_off, reader) + return SysViewTraceDataParser.read_extension_event(self, evt_id, core_id, reader) + + def on_new_event(self, event): + """ + Keeps track of function tracing module descriptions, when present. + """ + if self.root_proc == self: + SysViewTraceDataParser.on_new_event(self, event) + if event.id == SYSVIEW_EVTID_MODULEDESC and event.params['desc'].value.startswith('M=ESP_FunctionTrace'): + self.events_off = event.params['evt_off'].value + + class SysViewHeapTraceDataProcessor(SysViewTraceDataProcessor, apptrace.BaseHeapTraceDataProcessorImpl): """ SystemView trace data processor supporting heap events. @@ -1398,6 +1475,120 @@ class SysViewHeapTraceDataProcessor(SysViewTraceDataProcessor, apptrace.BaseHeap apptrace.BaseHeapTraceDataProcessorImpl.print_report(self) +class SysViewFunctionTraceEvent: + """ + Function tracing event (enter or exit). + """ + + def __init__(self, trace_event, enter, toolchain='', elf_path=''): + """ + Constructor. + + Parameters + ---------- + trace_event : SysViewEvent + trace event object related to this function event + enter : bool + True for function enter event, otherwise False + toolchain : string + toolchain prefix to resolve addresses to source line locations + elf_path : string + path to ELF file to resolve addresses + """ + self.trace_event = trace_event + self.enter = enter + self.toolchain = toolchain + self.elf_path = elf_path + + @property + def func(self): + return self.trace_event.params['func'].value + + @property + def call_site(self): + return self.trace_event.params['call_site'].value + + def __repr__(self): + if len(self.toolchain) and len(self.elf_path): + name, location = apptrace.addr2symbol(self.toolchain, self.elf_path, self.func) + func = f'{name} ({location})' if name else f'0x{self.func:x}' + call_site = apptrace.addr2line(self.toolchain, self.elf_path, self.call_site).strip() + else: + func = f'0x{self.func:x}' + call_site = f'0x{self.call_site:x}' + return '[{:.9f}] FUNC: {} {} from {} on core {:d} (called at {})'.format( + self.trace_event.ts, + 'enter' if self.enter else 'exit', + func, + self.trace_event.ctx_desc, + self.trace_event.core_id, + call_site, + ) + + +class SysViewFunctionTraceDataProcessor(SysViewTraceDataProcessor): + """ + SystemView trace data processor supporting function tracing events. + """ + + def __init__( + self, toolchain_pref, elf_path, root_proc=None, traces=[], print_events=False, print_func_events=False + ): + """ + Constructor. + see SysViewTraceDataProcessor.__init__() + """ + SysViewTraceDataProcessor.__init__(self, traces, root_proc=root_proc, print_events=print_events) + self.toolchain = toolchain_pref + self.elf_path = elf_path + self.name = 'func' + self.print_func_events = print_func_events + self.func_events_count = 0 + # per-function [enter, exit] counts keyed by function address + self.func_stats = {} + stream = self.root_proc.get_trace_stream(0, SysViewTraceDataParser.STREAMID_FUNC) + self.event_ids = {'enter': stream.events_off, 'exit': stream.events_off + 1} + + def event_supported(self, event): + func_stream = self.root_proc.get_trace_stream(event.core_id, SysViewTraceDataParser.STREAMID_FUNC) + return func_stream.event_supported(event) + + def handle_event(self, event): + func_stream = self.root_proc.get_trace_stream(event.core_id, SysViewTraceDataParser.STREAMID_FUNC) + enter = (event.id - func_stream.events_off) == 0 + func_event = SysViewFunctionTraceEvent(event, enter, toolchain=self.toolchain, elf_path=self.elf_path) + self.func_events_count += 1 + if self.print_func_events: + print(func_event) + stats = self.func_stats.setdefault(func_event.func, [0, 0]) + stats[0 if enter else 1] += 1 + + def print_report(self): + """ + see apptrace.TraceDataProcessor.print_report() + """ + if self.root_proc == self: + SysViewTraceDataProcessor.print_report(self) + print('=============== FUNCTION TRACE REPORT ===============') + print(f'Processed {self.func_events_count:d} function trace events.') + # sort by enter count to show the most frequently called functions first + rows = [] + for func in sorted(self.func_stats, key=lambda a: self.func_stats[a][0], reverse=True): + enter_cnt, exit_cnt = self.func_stats[func] + if len(self.toolchain) and len(self.elf_path): + name, location = apptrace.addr2symbol(self.toolchain, self.elf_path, func) + else: + name, location = '', '' + rows.append((name, func, enter_cnt, exit_cnt, location)) + name_w = max((len(r[0]) for r in rows), default=0) + for name, func, enter_cnt, exit_cnt, location in rows: + print( + '{:<{nw}} 0x{:08x} enter={:<6d} exit={:<6d} {}'.format( + name, func, enter_cnt, exit_cnt, location, nw=name_w + ) + ) + + class SysViewLogTraceEvent(apptrace.LogTraceEvent): """ SystemView log event. @@ -1424,7 +1615,7 @@ class SysViewLogTraceEvent(apptrace.LogTraceEvent): string formatted log message """ - return '[{:.9f}] LOG: {}'.format(self.ts, self.msg) + return f'[{self.ts:.9f}] LOG: {self.msg}' class SysViewLogTraceDataParser(SysViewTraceDataParser): diff --git a/tools/esp_app_trace/sysviewtrace_proc.py b/tools/esp_app_trace/sysviewtrace_proc.py index 58e7f10dd0e..ec0a60baf1c 100755 --- a/tools/esp_app_trace/sysviewtrace_proc.py +++ b/tools/esp_app_trace/sysviewtrace_proc.py @@ -1,6 +1,6 @@ #!/usr/bin/env python # -# SPDX-FileCopyrightText: 2019-2025 Espressif Systems (Shanghai) CO LTD +# SPDX-FileCopyrightText: 2019-2026 Espressif Systems (Shanghai) CO LTD # SPDX-License-Identifier: Apache-2.0 # # This is python script to process various types trace data streams in SystemView format. @@ -125,7 +125,7 @@ def main(): '-i', help='Events types to be included into report.', type=str, - choices=['heap', 'log', 'all'], + choices=['heap', 'log', 'func', 'all'], default='all', ) parser.add_argument('--toolchain', '-t', help='Toolchain prefix.', type=str, default='xtensa-esp32-elf-') @@ -152,7 +152,7 @@ def main(): signal.signal(signal.SIGINT, sig_int_handler) - include_events = {'heap': False, 'log': False} + include_events = {'heap': False, 'log': False, 'func': False} if args.include_events == 'all': for k in include_events: include_events[k] = True @@ -160,6 +160,8 @@ def main(): include_events['heap'] = True elif args.include_events == 'log': include_events['log'] = True + elif args.include_events == 'func': + include_events['func'] = True logging.basicConfig(level=verbosity_levels[args.verbose], format='[%(levelname)s] %(message)s') @@ -190,6 +192,11 @@ def main(): sysview.SysViewTraceDataParser.STREAMID_LOG, sysview.SysViewLogTraceDataParser(print_events=False, core_id=i), ) + if include_events['func']: + parser.add_stream_parser( + sysview.SysViewTraceDataParser.STREAMID_FUNC, + sysview.SysViewFunctionTraceDataParser(print_events=False, core_id=i), + ) parsers.append(parser) except Exception as e: logging.error('Failed to create data parser (%s)!', e) @@ -231,6 +238,13 @@ def main(): sysview.SysViewTraceDataParser.STREAMID_LOG, sysview.SysViewLogTraceDataProcessor(root_proc=proc, print_log_events=args.print_events), ) + if include_events['func']: + proc.add_stream_processor( + sysview.SysViewTraceDataParser.STREAMID_FUNC, + sysview.SysViewFunctionTraceDataProcessor( + args.toolchain, args.elf_file, root_proc=proc, print_func_events=args.print_events + ), + ) except Exception as e: logging.error('Failed to create data processor (%s)!', e) traceback.print_exc() diff --git a/tools/esp_app_trace/test/sysview/expected_output b/tools/esp_app_trace/test/sysview/expected_output index 7d5de4e83b9..132f5ad7a23 100644 --- a/tools/esp_app_trace/test/sysview/expected_output +++ b/tools/esp_app_trace/test/sysview/expected_output @@ -3737,3 +3737,5 @@ Processed 99 heap events. /Users/erhan/dev/esp-idf/components/freertos/FreeRTOS-Kernel/portable/xtensa/port.c:141 Found 17706 leaked bytes in 45 blocks. +=============== FUNCTION TRACE REPORT =============== +Processed 0 function trace events. diff --git a/tools/esp_app_trace/test/sysview/expected_output.json b/tools/esp_app_trace/test/sysview/expected_output.json index 581d0337dfc..9f05bddfe04 100644 --- a/tools/esp_app_trace/test/sysview/expected_output.json +++ b/tools/esp_app_trace/test/sysview/expected_output.json @@ -26180,6 +26180,10 @@ } ], "streams": { + "func": { + "enter": 0, + "exit": 1 + }, "heap": { "alloc": 512, "free": 513 diff --git a/tools/esp_app_trace/test/sysview/expected_output_mcore b/tools/esp_app_trace/test/sysview/expected_output_mcore index aade7f94cc1..f5a5d8b5223 100644 --- a/tools/esp_app_trace/test/sysview/expected_output_mcore +++ b/tools/esp_app_trace/test/sysview/expected_output_mcore @@ -3748,3 +3748,5 @@ Processed 99 heap events. /Users/erhan/dev/esp-idf/components/freertos/FreeRTOS-Kernel/portable/xtensa/port.c:141 Found 17706 leaked bytes in 45 blocks. +=============== FUNCTION TRACE REPORT =============== +Processed 0 function trace events. diff --git a/tools/esp_app_trace/test/sysview/expected_output_mcore.json b/tools/esp_app_trace/test/sysview/expected_output_mcore.json index c3e5325b94b..cac85b1c664 100644 --- a/tools/esp_app_trace/test/sysview/expected_output_mcore.json +++ b/tools/esp_app_trace/test/sysview/expected_output_mcore.json @@ -26268,6 +26268,10 @@ } ], "streams": { + "func": { + "enter": 0, + "exit": 1 + }, "heap": { "alloc": 512, "free": 513