feat(esp_trace): add compiler-instrumented function tracing support

(cherry picked from commit 39d6aaaecb)
This commit is contained in:
Erhan Kurubas
2026-09-09 12:11:14 +02:00
parent 16cd970a43
commit baa4ad4362
36 changed files with 1562 additions and 274 deletions
+5 -1
View File
@@ -18,6 +18,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
@@ -30,7 +34,7 @@ set(priv_requires
"esp_driver_usb_serial_jtag"
"esp_timer"
)
set(priv_includes "")
set(priv_includes "private_include")
set(requires "app_trace")
idf_component_register(SRCS ${srcs}
+51
View File
@@ -86,6 +86,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/tracing/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"
+52 -1
View File
@@ -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 $<TARGET_NAME_IF_EXISTS:${COMPO
**Note:** External trace libraries should use `CONFIG_ESP_TRACE_LIB_EXTERNAL=y` instead of defining their own Kconfig option in the esp_trace menu. This keeps the external component independent from the esp_trace component.
## Function Tracing
`esp_trace` can record function entry/exit using the compiler's `-finstrument-functions` feature. The runtime and hooks live in `esp_trace`. The active encoder (e.g. SystemView) formats the events.
### Enable
```
CONFIG_ESP_TRACE_FUNCTION_TRACE=y
```
### Instrument selected code
Add the flag only to the components or files you want traced:
```cmake
# instrument the whole component
target_compile_options(${COMPONENT_LIB} PRIVATE -finstrument-functions)
```
To narrow it down, exclude files or functions:
```cmake
target_compile_options(${COMPONENT_LIB} PRIVATE
-finstrument-functions
-finstrument-functions-exclude-file-list=foo.c,bar.c
-finstrument-functions-exclude-function-list=hot_fn,isr_handler)
```
Individual functions can also be excluded in source with `__attribute__((no_instrument_function))`.
### Control from the application
```c
#include "esp_trace_function_trace.h"
esp_trace_function_trace_start();
// ...
esp_trace_function_trace_stop();
```
Recording is active only while function tracing is started and the encoder reports it is recording (for SystemView this follows the host connecting and starting a recording over JTAG/UART).
> 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:
@@ -0,0 +1,35 @@
/*
* SPDX-FileCopyrightText: 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
@@ -11,6 +11,7 @@ extern "C" {
#endif
#include <stddef.h>
#include <stdbool.h>
#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
@@ -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.
@@ -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 <stdbool.h>
#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);
+25 -2
View File
@@ -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"
static const char *TAG = "esp_trace_core";
@@ -162,7 +163,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)
@@ -176,7 +181,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)
@@ -216,6 +225,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;
+143
View File
@@ -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 <stdbool.h>
#include <stdint.h>
#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();
}
@@ -0,0 +1,42 @@
.. _app_trace-function-tracing:
Compiler-Instrumented Function Tracing
======================================
:link_to_translation:`zh_CN:[中文]`
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 :doc:`esp_trace <index>` 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).
Enabling Function Tracing
-------------------------
Enable :ref:`CONFIG_ESP_TRACE_FUNCTION_TRACE`. 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, no events are emitted 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).
Decoding Function-Trace Events
------------------------------
After collecting a SystemView capture (see :doc:`sysview`), decode the function-trace events with the processing script:
.. code-block:: bash
$IDF_PATH/tools/esp_app_trace/sysviewtrace_proc.py -i func -b </path/to/program.elf> -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 Example
-------------------
- :example:`system/tracing/function_tracing` demonstrates compiler-instrumented function entry/exit tracing and how to control which code is instrumented.
+4
View File
@@ -35,6 +35,8 @@ Choosing Your Path
- :doc:`Application Level Tracing transport <transports>`
* - Collect source code coverage
- :doc:`Gcov <gcov>`
* - Trace every function entry and exit automatically
- :doc:`Function tracing <function-tracing>`
* - Integrate a third-party trace recorder
- :doc:`Custom trace library <custom-trace-library>`
@@ -87,6 +89,7 @@ Detailed Guides
transports
sysview
gcov
function-tracing
custom-trace-library
Related Documentation
@@ -105,4 +108,5 @@ Examples
- :example:`system/tracing/sysview_tracing`: SystemView tracing example
- :example:`system/tracing/sysview_tracing_heap_log`: Heap tracing with SystemView
- :example:`system/tracing/gcov`: Source code coverage over JTAG
- :example:`system/tracing/function_tracing`: Compiler-instrumented function entry/exit tracing
- :example:`system/tracing/esp_trace_custom_library`: External trace library integration template
@@ -0,0 +1,42 @@
.. _app_trace-function-tracing:
编译器插桩的函数跟踪
====================
:link_to_translation:`en:[English]`
函数跟踪可自动记录每次函数进入和退出,无需手动插入跟踪点。当源文件使用 GCC 标志 ``-finstrument-functions`` 编译时,编译器会在每个函数的开始和结束处插入调用。这些调用进入由 :doc:`esp_trace <index>` 组件提供的钩子,钩子再将事件转发给当前活动的跟踪编码器(例如 SystemView)。事件携带原始的函数地址和调用点地址,SystemView 将其记录为原始地址。将地址解析为函数名的工作单独针对 ELF 文件完成(例如使用 ``addr2line`` 或自定义工具)。
启用函数跟踪
------------
启用 :ref:`CONFIG_ESP_TRACE_FUNCTION_TRACE`。以下选项控制函数跟踪:
- :ref:`CONFIG_ESP_TRACE_FUNCTION_TRACE` - 构建函数跟踪钩子和运行时。
- :ref:`CONFIG_ESP_TRACE_FUNCTION_TRACE_AUTO_START` - 启用时(默认),记录跟随编码器的状态,并在主机启动会话后立即开始。禁用时,在应用程序调用 :cpp:func:`esp_trace_function_trace_start` 之前不会发出任何事件;仅有活动的主机会话是不够的。
启用该选项会将钩子和运行时编译进构建,但不会为任何代码添加 ``-finstrument-functions``,因此单独启用不会产生任何事件。要跟踪某个组件或文件,请在其自身的 ``CMakeLists.txt`` 中为需要跟踪的源文件添加该标志:
.. code-block:: cmake
if(CONFIG_ESP_TRACE_FUNCTION_TRACE)
target_compile_options(${COMPONENT_LIB} PRIVATE -finstrument-functions)
endif()
使用 GCC 的 ``-finstrument-functions-exclude-file-list`` 和 ``-finstrument-functions-exclude-function-list`` 标志可跳过特定文件或函数。请将插桩范围限定在你自己的组件内,且不要对在关闭 flash 缓存的情况下运行的代码(IRAM 中断服务程序、SPI flash 操作)进行插桩。
解码函数跟踪事件
----------------
在采集到 SystemView 捕获数据后(参见 :doc:`sysview`),使用处理脚本解码函数跟踪事件:
.. code-block:: bash
$IDF_PATH/tools/esp_app_trace/sysviewtrace_proc.py -i func -b </path/to/program.elf> -t {IDF_TARGET_TOOLCHAIN_PREFIX}- file:///path/to/trace.svdat
``-i func`` 选项用于选择函数跟踪事件流。脚本使用 ELF 文件和工具链前缀解析地址,然后打印按函数分类的报告,列出每个被跟踪函数的地址、进入和退出次数以及源代码位置。
应用示例
--------
- :example:`system/tracing/function_tracing` 演示编译器插桩的函数进入或退出跟踪,以及如何控制对哪些代码进行插桩。
+4
View File
@@ -35,6 +35,8 @@ ESP-IDF 提供了一套跟踪系统,用于程序行为分析和调试。以较
- :doc:`应用层跟踪传输 <transports>`
* - 收集源代码覆盖率
- :doc:`Gcov <gcov>`
* - 自动跟踪每次函数进入和退出
- :doc:`函数跟踪 <function-tracing>`
* - 集成第三方跟踪记录器
- :doc:`自定义跟踪库 <custom-trace-library>`
@@ -87,6 +89,7 @@ ESP-IDF 提供了一套跟踪系统,用于程序行为分析和调试。以较
transports
sysview
gcov
function-tracing
custom-trace-library
相关文档
@@ -105,4 +108,5 @@ ESP-IDF 提供了一套跟踪系统,用于程序行为分析和调试。以较
- :example:`system/tracing/sysview_tracing`:SystemView 跟踪示例
- :example:`system/tracing/sysview_tracing_heap_log`:基于 SystemView 的堆跟踪
- :example:`system/tracing/gcov`:通过 JTAG 获取源代码覆盖率
- :example:`system/tracing/function_tracing`:编译器插桩的函数进入/退出跟踪
- :example:`system/tracing/esp_trace_custom_library`:外部跟踪库集成模板
@@ -27,6 +27,18 @@ examples/system/tracing/esp_trace_custom_library:
- esp_trace
- freertos
examples/system/tracing/function_tracing:
disable_test:
- if: IDF_TARGET == "esp32h21"
temporary: true
reason: lack of runners
- if: IDF_TARGET == "esp32h4"
temporary: true
reason: lack of runners
depends_components:
- esp_trace
- app_trace
examples/system/tracing/gcov:
disable_test:
- if: IDF_TARGET == "esp32h21"
@@ -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)
@@ -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 |
| ----------------- | ----- | -------- | -------- | -------- | -------- | --------- | -------- | --------- | -------- | -------- | -------- | -------- |
# 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 <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 <core0_file> [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 guide](https://docs.espressif.com/projects/esp-idf/en/latest/api-guides/tracing/function-tracing.html).
## 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.
@@ -0,0 +1,2 @@
512 function_enter func=%p call_site=%p
513 function_exit func=%p call_site=%p
@@ -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()
@@ -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("");
}
@@ -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;
}
@@ -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;
}
@@ -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 <stdint.h>
#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
@@ -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
@@ -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()
@@ -0,0 +1,72 @@
/*
* SPDX-FileCopyrightText: 2026 Espressif Systems (Shanghai) CO LTD
*
* SPDX-License-Identifier: Apache-2.0
*
* Function Tracing Example
*/
#include <inttypes.h>
#include <stdio.h>
#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);
}
}
@@ -0,0 +1,6 @@
## IDF Component Manager Manifest File
dependencies:
## Required IDF version
idf:
version: '>=6.0'
espressif/esp_sysview: ^1
@@ -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)
@@ -0,0 +1,3 @@
CONFIG_ESP_TRACE_TRANSPORT_APPTRACE=y
CONFIG_APPTRACE_DEST_JTAG=y
CONFIG_APPTRACE_BUF_SIZE=32768
@@ -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
+291 -240
View File
@@ -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.')
+216 -25
View File
@@ -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):
+17 -3
View File
@@ -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()
@@ -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.
@@ -26180,6 +26180,10 @@
}
],
"streams": {
"func": {
"enter": 0,
"exit": 1
},
"heap": {
"alloc": 512,
"free": 513
@@ -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.
@@ -26268,6 +26268,10 @@
}
],
"streams": {
"func": {
"enter": 0,
"exit": 1
},
"heap": {
"alloc": 512,
"free": 513