Merge branch 'refactor/ble-log-lbm-overhaul' into 'master'

refactor: BLE Log LBM Overhaul

See merge request espressif/esp-idf!52299
This commit is contained in:
Island
2026-09-11 20:09:53 +08:00
43 changed files with 6139 additions and 2492 deletions
+3 -6
View File
@@ -170,8 +170,10 @@ list(APPEND bt_common_priv_include_dirs
if(CONFIG_BLE_LOG_ENABLED)
list(APPEND bt_common_srcs
"${CMAKE_CURRENT_LIST_DIR}/ble_log/src/ble_log.c"
"${CMAKE_CURRENT_LIST_DIR}/ble_log/src/ble_log_lbm.c"
"${CMAKE_CURRENT_LIST_DIR}/ble_log/src/ble_log_lbm_v2.c"
"${CMAKE_CURRENT_LIST_DIR}/ble_log/src/ble_log_redir.c"
"${CMAKE_CURRENT_LIST_DIR}/ble_log/src/ble_log_rt.c"
"${CMAKE_CURRENT_LIST_DIR}/ble_log/src/ble_log_task_registry.c"
"${CMAKE_CURRENT_LIST_DIR}/ble_log/src/ble_log_util.c"
)
@@ -184,11 +186,6 @@ if(CONFIG_BLE_LOG_ENABLED)
"${CMAKE_CURRENT_LIST_DIR}/ble_log/src/internal_include/prph"
)
# Timestamp synchronization extension
if(CONFIG_BLE_LOG_TS_ENABLED)
list(APPEND bt_common_srcs "${CMAKE_CURRENT_LIST_DIR}/ble_log/src/ble_log_ts.c")
endif()
# Peripheral interface implementation
if(CONFIG_BLE_LOG_PRPH_DUMMY)
list(APPEND bt_common_srcs
+101 -95
View File
@@ -1,55 +1,57 @@
config BLE_LOG_ENABLED
bool "Enable BT Log Async Output (Dev Only)"
select BLE_COMPRESSED_LOG_ENABLE
select BLE_HOST_COMPRESSED_LOG_ENABLE if BT_BLUEDROID_ENABLED
select BLE_HOST_COMPRESSED_LOG_ENABLE if BT_BLUEDROID_ENABLED || BT_NIMBLE_ENABLED
select ESP_TIMER_IN_IRAM
default n
help
Enable BT Log Async Output
if BLE_LOG_ENABLED
config BLE_LOG_LBM_AUTO_FLUSH
bool "Enable automatic BLE Log LBM buffer flush"
default n
config BLE_LOG_POOL_TRANS_CNT
int "Number of transport buffers in the unified pool"
range 2 32
default 8
help
Periodically flush partially-filled BLE Log LBM transport buffers
that remain pending, reducing latency for low-volume or
intermittent logging.
Total number of transports shared by ordinary, Link Layer, ISR,
and critical-section log writers. Availability is represented by
32-bit bitmaps, so the maximum is 32.
config BLE_LOG_LBM_TRANS_BUF_SIZE
int "Total buffer memory per common LBM (bytes)"
default 2048
help
Total buffer memory allocated for each common pool log buffer
manager (LBM). This memory is divided equally among internal
transport buffers. Must be a multiple of BLE_LOG_TRANS_BUF_CNT
(currently 4).
The common pool contains:
- BLE_LOG_LBM_ATOMIC_LOCK_TASK_CNT atomic LBMs (task context)
- BLE_LOG_LBM_ATOMIC_LOCK_ISR_CNT atomic LBMs (ISR context)
- 2 spinlock-protected LBMs (one for task, one for ISR fallback)
Total common pool memory:
(ATOMIC_TASK_CNT + ATOMIC_ISR_CNT + 2) * BLE_LOG_LBM_TRANS_BUF_SIZE
config BLE_LOG_LBM_ATOMIC_LOCK_TASK_CNT
int "Count of log buffer managers with atomic lock protection for task context"
default 2
help
BLE Log module will search for an LBM with atomic lock protection first; if
all LBMs with atomic lock protection are unavailable, BLE Log module will
try to use the LBM with spin lock protection. So the more LBMs with atomic
lock protection are created, the better the logging performance will be.
config BLE_LOG_LBM_ATOMIC_LOCK_ISR_CNT
int "Count of log buffer managers with atomic lock protection for ISR context"
config BLE_LOG_POOL_NON_YIELD_RESERVE_CNT
int "Transport buffers reserved for non-yieldable contexts"
range 1 31
default 1
help
BLE Log module will search for an LBM with atomic lock protection first; if
all LBMs with atomic lock protection are unavailable, BLE Log module will
try to use the LBM with spin lock protection. So the more LBMs with atomic
lock protection are created, the more ISRs can nest.
Buffers that ordinary task writers cannot consume. ISR and
critical-section writers try the shared region first, then this
reserve. The value must remain below BLE_LOG_POOL_TRANS_CNT.
config BLE_LOG_POOL_TRANS_SIZE
int "Per-transport buffer size (bytes)"
range 640 10240
default 640
help
Size of every unified-pool transport. One complete frame must fit
in one transport. SPI builds require a multiple of four so they
can append peripheral-only zero padding to each logical frame.
config BLE_LOG_TASK_ID_MAX
int "Maximum number of distinct logging tasks"
range 2 32
default 16
help
Size of the task-id registry (protocol v8). Every ENCODE record
carries the one-byte id of the task that formatted it; the
registry maps task names to those stable ids. One binding record
per registered entry is broadcast as an INTERNAL frame on every
periodic snapshot window, so a receiver that missed or lost a
binding converges on the next window. A task that starts logging
after the registry is full falls back to the unknown id (0xFF)
and its records are still emitted.
RAM cost is 16 bytes per entry (256 bytes at the default 16)
plus one dedicated binding transport (320 bytes at 16 entries,
624 at 32; the broadcast frame must fit in one transport).
config BLE_LOG_IS_ESP_CONTROLLER
bool "Current BLE Controller is ESP BLE Controller"
@@ -77,44 +79,9 @@ if BLE_LOG_ENABLED
help
Enable BLE Log for Link Layer
if BLE_LOG_LL_ENABLED
config BLE_LOG_LBM_LL_TRANS_BUF_SIZE
int "Total buffer memory per Link Layer LBM (bytes)"
default 2048
help
Total buffer memory allocated for each Link Layer dedicated
log buffer manager (LBM). This memory is divided equally among
internal transport buffers. Must be a multiple of
BLE_LOG_TRANS_BUF_CNT (currently 4).
There are 2 Link Layer LBMs without lock protection (each is
accessed from a single context only):
- LL task LBM (Link Layer task context logs)
- LL HCI LBM (Link Layer HCI context logs)
Total LL pool memory: 2 * BLE_LOG_LBM_LL_TRANS_BUF_SIZE
config BLE_LOG_LL_HCI_LOG_PAYLOAD_LEN_LIMIT_ENABLED
bool "Enable LL HCI Log Payload Length Limit"
default n
help
Enable length limit for LL HCI Log payload (addr_append).
When enabled, if len_append exceeds the configured limit,
it will be truncated to the maximum length.
config BLE_LOG_LL_HCI_LOG_PAYLOAD_LEN_LIMIT
int "LL HCI Log Payload Length Limit (bytes)"
depends on BLE_LOG_LL_HCI_LOG_PAYLOAD_LEN_LIMIT_ENABLED
default 32
help
Maximum length for LL HCI Log payload (len_append).
When the feature is enabled and len_append exceeds this value,
it will be truncated.
endif
config BLE_LOG_HOST_LOG
bool "Enable BLE Log for Host"
depends on BT_BLUEDROID_ENABLED
depends on BT_BLUEDROID_ENABLED || BT_NIMBLE_ENABLED
default y
help
Enable BLE Log for the Host stack (Bluedroid or NimBLE).
@@ -124,26 +91,30 @@ if BLE_LOG_ENABLED
the standard UART logging path. Disable this option to keep
BLE Log enabled for the controller/link layer only.
config BLE_LOG_HOST_SIDE_HCI_LOG_ENABLED
bool "Enable BLE Host side HCI Logging"
default y if BLE_LOG_IS_ESP_LEGACY_CONTROLLER
config BLE_LOG_HCI_LOG_ENABLED
bool "Enable BLE HCI Logging"
default y
help
Enable HCI packet logging captured on the Host side
(Bluedroid / NimBLE HCI HAL). Useful for correlating
host events with controller-side HCI traces.
Enable HCI packet logging. Bluedroid and legacy VHCI NimBLE
capture on the Host side and suppress duplicate Controller
HCI records. Other configurations, including non-legacy
NimBLE, retain Controller HCI records through the LL callback
and require BLE_LOG_LL_ENABLED. Disabling this option
suppresses HCI records from both capture paths.
config BLE_LOG_TS_ENABLED
bool "Enable BLE Log Timestamp Synchronization (TS)"
config BLE_LOG_TS_SYNC_TOGGLE_IO_ENABLED
bool "Toggle a GPIO on every BLE Log TS sync sample"
default n
help
Enable BLE Log TS with external logging module. Synchronization is
triggered periodically by an ESP Timer using task dispatch. The
timer does not wake the system from light sleep.
Every periodic Internal Snapshot samples the link-layer, ESP and
OS clocks regardless of this option. Enable this option to build
the GPIO toggle used by external logic analyzers. It starts
disabled and low; ble_log_ts_sync_io_toggle_enable controls its
edges without stopping periodic snapshots.
if BLE_LOG_TS_ENABLED
if BLE_LOG_TS_SYNC_TOGGLE_IO_ENABLED
config BLE_LOG_SYNC_IO_NUM
int "GPIO number for Timestamp Synchronization (TS) toggle output"
depends on BLE_LOG_TS_ENABLED
default 0
help
GPIO number for TS toggle output
@@ -165,8 +136,11 @@ if BLE_LOG_ENABLED
bool "Test only transport"
help
Test transport that models DMA ownership and optional
link-rate backpressure. Selected by BLE Log test apps
only; not shown in menuconfig.
link-rate backpressure. Intended for the BLE Log test apps
only: outside them nothing drains the transmitted buffers,
so selecting this transport in a production build stalls
log output. The BLE Log test apps select it through their
sdkconfig.defaults.
config BLE_LOG_PRPH_SPI_MASTER_DMA
bool "Utilize SPI master DMA driver as transport"
@@ -240,6 +214,35 @@ if BLE_LOG_ENABLED
int
default 512
config BLE_LOG_LBM_TRANS_BUF_SIZE
int
default 2048
config BLE_LOG_LBM_ATOMIC_LOCK_TASK_CNT
int
default 2
config BLE_LOG_LBM_ATOMIC_LOCK_ISR_CNT
int
default 1
config BLE_LOG_LBM_LL_TRANS_BUF_SIZE
int
default 2048
config BLE_LOG_LL_HCI_LOG_PAYLOAD_LEN_LIMIT_ENABLED
bool
default n
config BLE_LOG_LL_HCI_LOG_PAYLOAD_LEN_LIMIT
int
depends on BLE_LOG_LL_HCI_LOG_PAYLOAD_LEN_LIMIT_ENABLED
default 32
config BLE_LOG_LBM_AUTO_FLUSH
bool
default n
config BLE_LOG_ENH_STAT_ENABLED
bool
default y
@@ -260,28 +263,31 @@ if BLE_LOG_ENABLED
config BLE_LOG_TS_TRIGGER_TIMEOUT_MS
int
depends on BLE_LOG_TS_ENABLED
default 1000
config BLE_LOG_TS_TRIGGER_CHOICE
bool
depends on BLE_LOG_TS_ENABLED
default y
config BLE_LOG_TS_TRIGGER_ESP_TIMER
bool
depends on BLE_LOG_TS_ENABLED
default y
config BLE_LOG_TS_TRIGGER_TASK_EVENT
bool
depends on BLE_LOG_TS_ENABLED
default n
config BLE_LOG_TS_TRIGGER_ESP_TIMER_ISR_DISPATCH_METHOD
bool
depends on BLE_LOG_TS_ENABLED
default n
# Deprecated: renamed to BLE_LOG_HCI_LOG_ENABLED. No prompt, so it
# never appears in menuconfig; kept so sdkconfig files pinning the old
# name keep Host side HCI logging enabled.
config BLE_LOG_HOST_SIDE_HCI_LOG_ENABLED
bool
default n
select BLE_LOG_HCI_LOG_ENABLED
endif
menu "Legacy SPI Log Output (Deprecated - use BT Log Async Output instead)"
+295 -480
View File
@@ -1,495 +1,310 @@
# BLE Log Module
# BLE Log
A high-performance, modular Bluetooth logging system that provides real-time log capture and asynchronous transmission capabilities for the ESP-IDF Bluetooth stack.
BLE Log is an asynchronous binary logging transport for Bluetooth controller,
Host HCI, application, and compressed logs.
## Table of Contents
## Architecture
- [Overview](#overview)
- [Architecture Design](#architecture-design)
- [Features](#features)
- [Quick Start](#quick-start)
- [Configuration Options](#configuration-options)
- [API Reference](#api-reference)
- [Usage Examples](#usage-examples)
- [Performance & Memory Optimization](#performance--memory-optimization)
- [Troubleshooting](#troubleshooting)
- [Important Notes](#important-notes)
## Overview
The BLE Log module is an efficient logging system specifically designed for the ESP-IDF Bluetooth stack, supporting real-time log capture, multi-source log collection, and various transmission methods. This module has been refactored with a modular design, featuring high-concurrency processing capabilities and low-latency characteristics.
### Main Components
- **BLE Log Core** (`ble_log.c`): Module core responsible for initialization and coordination of sub-modules
- **Runtime Manager** (`ble_log_rt.c`): One-shot ESP Timer dispatch for log transmission scheduling
- **Log Buffer Manager** (`ble_log_lbm.c`): Log buffer management supporting multiple locking mechanisms
- **Peripheral Interface** (`ble_log_prph_*.c`): Peripheral interface abstraction layer supporting various transmission methods
- **Timestamp Sync** (`ble_log_ts.c`): Timestamp synchronization module
- **Utility** (`ble_log_util.c`): Common utility functions
## Features
### Core Functionality
- **Multi-source Log Collection**: Supports multiple log sources including Link Layer, Host, HCI, UART redirection, etc.
- **High Concurrency Processing**: Uses atomic and spin lock mechanisms for multi-task concurrent writing
- **Real-time Transmission**: Asynchronous transmission through ESP Timer task dispatch
- **Data Integrity**: Checksum mechanism ensures data integrity (always enabled)
- **Multi-buffer Transport**: Each LBM manages multiple transport buffers (default 4) for improved throughput over the legacy ping-pong design
- **Cross-pool Buffer Fallback**: LBM acquire attempts all atomic LBMs before falling back to spinlock LBMs, improving buffer availability under contention
### Advanced Features
- **UART Redirection**: When using UART DMA on PORT 0, UART output (including `esp_rom_printf`) is transparently redirected through the async log pipeline
- **Timestamp Synchronization**: Supports timestamp synchronization with external devices (optional)
- **Enhanced Statistics**: Detailed logging statistics including written/lost frame and byte counts (always enabled)
- **Buffer Utilization Reporting**: Per-LBM buffer utilization and inflight peak tracking for diagnostics
- **Link Layer Integration**: Deep integration with ESP-IDF Bluetooth Link Layer
- **Multiple Transmission Methods**: Supports SPI Master DMA, UART DMA, and Dummy transmission
### Performance Features
- **IRAM Optimization**: Critical path code runs in IRAM ensuring low latency
- **Lock-free Design**: Most operations use atomic operations reducing lock contention
- **Buffer Reuse**: Intelligent buffer management reduces memory allocation overhead
## Quick Start
### 1. Enable Module
Enable the BLE Log module in `menuconfig`:
```
Component config → Bluetooth → Enable BT Log Async Output (Dev Only)
```mermaid
flowchart TD
A[Public and LL writers] --> P[Unified bitmap pool]
C[Compression encoder] --> P
S[Internal snapshot] --> I[Fixed internal transport]
R[UART0 redirection] --> D[Redirection transports]
P --> Q[ESP Timer runtime queue]
I --> Q
D --> Q
Q --> X[Peripheral DMA]
```
### 2. Basic Configuration
The shared pool contains `CONFIG_BLE_LOG_POOL_TRANS_CNT` transports. The last
`CONFIG_BLE_LOG_POOL_NON_YIELD_RESERVE_CNT` transports are reserved for ISR and
other contexts that cannot yield. Ordinary yieldable task writers, from the
public API and claims to the controller LL task, wait for a shared transport
unless a claim explicitly opts out. Writers on the shared ESP Timer task never
wait for a transport: its callbacks must return so dispatch can progress.
While yieldable, they use shared transports only; ISR and critical-section
writers retain reserve access and fail-fast behavior.
The Internal Snapshot and UART0 redirection transports are not members of the
bitmap pool.
Periodic flushing scans the whole bounded pool, not just OPEN bitmap hints:
writers temporarily remove their hints while writing or holding a claim. A
failed try-lock leaves `pending_seal`; the next claim seals the old buffer
before appending, or a later periodic scan seals it when unlocked. This is a
deferred request, not a snapshot barrier. Seal and recycle clear the flag,
but a delayed flusher can set it afterwards; an extra early partial seal is
allowed. Full flush/deinit retain OPEN-only scans after writers drain.
FREE acquisition requires the lock, FREE state, and atomically removing an
actually published FREE bit. A cached candidate alone cannot bypass the
recycler's state-to-bitmap publication window. UART0 periodic flushing is
independent of producer enable: disable stops new writes, not cached output.
## Runtime dispatch
Sealed transports enter one bounded queue. The first submission anchors a
one-shot ESP Timer deadline at 1 ms; later submissions do not move it. Each
callback drains the queue depth captured at entry and schedules another fixed
defer only for arrivals left behind, so it does not continuously monopolize
the shared ESP Timer task.
## Version 8 frame
All multi-byte fields use the target's little-endian representation.
```text
offset size field
0 2 payload length
2 4 frame_meta
6 N payload
6 + N 4 checksum
```
`frame_meta` is:
```text
bits 0..7 source
bits 8..31 sequence number, low 24 bits
```
The checksum is `ble_log_fast_checksum()` over the six-byte header and exactly
`payload length` bytes. It excludes the checksum field and peripheral-only DMA
padding.
Core frame payloads follow the writer entry point, not a single rule:
- Public write / claim path (`write_hex`, compressed encoder): the API
prepends a `[4-byte low32 esp_timer_get_time() microseconds]` before
the source payload. The timestamp is captured at API entry before any
pool mutex wait. It wraps approximately every 71.6 minutes and must be
unwrapped modulo 2^32 by the receiver.
- LL callback path (`write_hex_ll`, covering the LL_TASK / LL_HCI /
LL_ISR sources): controller payloads are forwarded raw, with no ESP
timestamp prefix — the on-wire layout is exactly what the controller
handed over.
UART0 redirection payload is likewise the raw console stream with no
timestamp prefix: the redirection stream keeps its own frame sequence, and
its receiver-side arrival time (aggregation delay bounded by the periodic
redirection flush) is the alignment reference against the core timeline.
### Sources
The public `ble_log_src_t` ABI is frozen and its values are the on-wire
source IDs of protocol v8 frames:
```text
0 INTERNAL
1 CUSTOM
2 LL_TASK
3 LL_HCI
4 LL_ISR
5 HOST
6 HCI
7 ENCODE
8 REDIR extension
```
Core log sources (`CUSTOM` through `ENCODE`) and Internal Snapshots share one
24-bit Global SN. Core logs consume it after entry validation and gate acceptance,
before buffer contention; lost log attempts leave gaps accounted for by
`lost_frame_cnt`. Snapshots consume it only after acquiring their dedicated
transport, when assembling the frame. Busy/skipped snapshots do not consume a
Global SN and are not included in `lost_frame_cnt`.
Snapshots also carry a separate 24-bit `anchor_count` in their payload:
only snapshot attempts advance this counter, including skipped snapshots.
The periodic task-binding broadcast and REDIR console stream retain their
own separate header sequences (gaps count skipped binding windows or dropped
console batches). `ble_log_init()` resets all sequences and the anchor counter,
and its required `INIT` snapshot starts a new
receiver epoch. They remain continuous through `FLUSH` within that epoch.
Callers must not write until `ble_log_init()` returns, so the `INIT`
snapshot is submitted first.
`CONFIG_BLE_LOG_HCI_LOG_ENABLED` controls HCI logging. Bluedroid and legacy
VHCI NimBLE retain Host-side capture and suppress duplicate Controller HCI
records. Other configurations, including non-legacy NimBLE, retain Controller
HCI records through the LL callback (requires `CONFIG_BLE_LOG_LL_ENABLED`).
Controller flags preserve their source mapping: `HCI` to `LL_HCI` and
`HCI_UPSTREAM` to `HCI`, with ISR precedence. Controller payloads are forwarded
unchanged. Host-side capture retains its direction bit in HCI payload byte 0
bit 7. Disabling HCI logging suppresses records from both capture paths.
## Internal Snapshot
All BLE Log-owned internal information is emitted as fixed-layout frames
from dedicated transports: the snapshot frame is 179 logical bytes on its
180-byte aligned transport, and the periodic task-binding broadcast has its own
transport sized to the registry (one full binding frame per window;
`CONFIG_BLE_LOG_TASK_ID_MAX` entries of 19 bytes plus a timestamp).
The snapshot contains:
- reason flags (`INIT`, `PERIODIC`, `FLUSH`, `TS_VALID`);
- a 24-bit little-endian `anchor_count` (three bytes), immediately after the reason flags;
- the complete 58-byte build, library, chip, and protocol version block;
- the LC clock, ESP Timer, and FreeRTOS tick samples captured together with
the GPIO sync level;
- pool count, reserve count, current inflight count, and inflight peak;
- compact statistics for `CUSTOM` through `ENCODE` (one slot per public
source in that range, `HOST` included).
The periodic snapshot is an always-on system behavior from initialization
until deinitialization. It cannot be stopped by the TS sync IO control API.
A skipped periodic snapshot advances only the anchor count, not the Global SN.
Anchor counts start at zero for INIT, also advance for FLUSH, and wrap modulo
2^24 on the wire (the atomic runtime counter remains uint32_t).
A gap between anchor counts identifies missed snapshot attempts without
mistaking intervening ordinary logs for missed snapshots.
Each source statistic contains only:
```c
#include "ble_log.h"
uint32_t written_frame_cnt;
uint32_t lost_frame_cnt;
uint32_t written_bytes_cnt;
```
void app_main() {
// Initialize BLE Log module
if (!ble_log_init()) {
ESP_LOGE(TAG, "Failed to initialize BLE Log");
return;
}
// Write log data
uint8_t data[] = {0x01, 0x02, 0x03, 0x04};
ble_log_write_hex(BLE_LOG_SRC_CUSTOM, data, sizeof(data));
// End session and flush buffers
ble_log_flush();
// Cleanup resources
ble_log_deinit();
Successful counts are incremented only after a complete frame is committed to
a transport; they do not imply confirmed physical TX. `written_bytes_cnt`
counts the full logical frame (six-byte header, payload including any timestamp
prefix, and four-byte checksum), excluding peripheral DMA padding. Rejected or
aborted writes do not add bytes; there is no lost-byte counter. Internal and
REDIR frames are not included in these per-core-source byte counters. All three
counters are uint32 values and wrap modulo 2^32.
Core counts and the pool peak restart after a completed FLUSH; the Global SN
and anchor count remain continuous. A busy periodic Internal
transport is never overwritten; that snapshot is skipped and counted. Required
INIT and FLUSH snapshots use a bounded task-context wait.
The protocol version remains v8 despite the changed snapshot payload layout and
header sequence semantics. Receivers must be updated together with the producer;
the version byte alone cannot distinguish the old and new layouts.
The snapshot remains a sampling point,
not a confirmed TX boundary: periodic OPEN flushing is best-effort, statistics
are sampled individually while writers can run, and Global SN allocation order
is not submission order. Neither deferred sealing nor the anchor count makes
snapshot differences an exact SN-interval accounting boundary.
## Public API
```c
bool ble_log_init(void);
void ble_log_deinit(void);
bool ble_log_enable(bool enable);
void ble_log_flush(void);
bool ble_log_write_hex(ble_log_src_t source, const uint8_t *data, size_t len);
uint8_t *ble_log_claim(ble_log_src_t source, size_t maximum,
uint32_t *handle, bool wait_for_transport);
void ble_log_commit(uint32_t handle, size_t actual_len);
void ble_log_write_hex_ll(uint32_t len, const uint8_t *data,
uint32_t append_len, const uint8_t *append,
uint32_t flags);
bool ble_log_ts_sync_io_toggle_enable(bool enable);
bool ble_log_sync_enable(bool enable); /* compatibility shim */
```
`ble_log_enable()` gates public producers only. Periodic system output remains
active while that gate is closed.
`ble_log_ts_sync_io_toggle_enable()` controls only the optional external
analyzer GPIO, which starts disabled and low. Disabling it leaves the IO low
after a final falling edge;
periodic clock sampling, OPEN transport flushing, and Internal Snapshots
continue. When the GPIO feature is not built, the call remains a
lifecycle-checked no-op. `ble_log_sync_enable()` is the backward-compatible
name for the same behavior.
`ble_log_flush()` is an ordinary FreeRTOS task API. Do not call it from an ISR,
critical section, or the shared ESP Timer task.
A public or LL record that cannot fit completely in one pool transport is
rejected and counted as lost; BLE Log never emits a truncated record.
## Compression direct write
Compression encoders write directly into shared-pool storage:
```c
uint32_t handle;
uint8_t *payload = ble_log_claim(BLE_LOG_SRC_ENCODE, maximum,
&handle, true);
if (payload) {
size_t encoded = encode(payload, maximum);
ble_log_commit(handle, encoded);
}
```
### 3. Link Layer Integration
`ble_log_claim()` reserves the hidden frame header, ESP Timer timestamp, and
checksum. It waits for a shared transport in ordinary yieldable tasks when
`wait_for_transport` is true (writer backpressure); pass false to opt out.
The shared ESP Timer task and non-yieldable contexts fail fast either way.
A busy-pool rejection leaves a Global SN gap and increments the source's loss
counter, just like other pool acquisition failures.
Every successful claim must be committed exactly once before
`ble_log_deinit()`; `ble_log_commit(handle, 0)` cancels it. Handles include a
transport generation so a stale handle cannot commit a later claim in the same
lifecycle.
When `CONFIG_BLE_LOG_LL_ENABLED` is enabled, Link Layer logs are automatically integrated:
Mesh, ISO, Bluedroid, and NimBLE compression no longer allocate three static
payload buffers per channel. Every ENCODE record names its writer: the byte
after the source is a task id from a name-keyed registry. The registry is a
self-contained module (`ble_log_task_registry.c/h`, structured like the
UART redirection writer: a small append-only table shared by every ENCODE
writer; RAM cost 16 bytes per entry, sized by `CONFIG_BLE_LOG_TASK_ID_MAX`).
```c
// Link Layer logs will automatically call this function
void ble_log_write_hex_ll(uint32_t len, const uint8_t *addr,
uint32_t len_append, const uint8_t *addr_append,
uint32_t flag);
The registry broadcast is module-owned system output: every periodic snapshot
window, one INTERNAL frame (`BLE_LOG_INT_SRC_TASK_BINDING`) packs one
fixed-layout record per registered entry, binding each id to its task name.
It rides the registry's own dedicated transport with a sequence of its own
(a window skipped despite a non-empty registry leaves a gap in the binding
sequence, never in the Global SN or snapshot anchor count), is never counted in the
per-source written/lost stats, and never contends with the snapshot
transport or with user records for pool transports. A receiver that joined
late or lost a frame converges on the next window; a record of a new task
keeps its id and is bound by name at the next window. Announcements are
idempotent on the wire and best effort (a busy binding transport — the
previous broadcast still in DMA — skips a window).
Attribution is a property of the record, so concurrent writers to one source
need no serialization and never drop a record on contention. When the registry
is full, a new task degrades to the unknown id (`0xFF`) and its records are
still emitted.
## Configuration
| Option | Default | Meaning |
| --- | ---: | --- |
| `CONFIG_BLE_LOG_ENABLED` | n | Enable BLE Log |
| `CONFIG_BLE_LOG_POOL_TRANS_CNT` | 8 | Unified pool transport count, range 2..32 |
| `CONFIG_BLE_LOG_POOL_NON_YIELD_RESERVE_CNT` | 1 | ISR/critical reserve count |
| `CONFIG_BLE_LOG_POOL_TRANS_SIZE` | 640 | Bytes per shared transport; SPI builds require a multiple of four |
| `CONFIG_BLE_LOG_LL_ENABLED` | target dependent | Controller LL logging |
| `CONFIG_BLE_LOG_HCI_LOG_ENABLED` | y | HCI capture from Host or Controller, selected by transport |
| `CONFIG_BLE_LOG_TASK_ID_MAX` | 16 | Task-id registry size, range 2..32; 16 bytes of RAM per entry |
| `CONFIG_BLE_LOG_TS_SYNC_TOGGLE_IO_ENABLED` | n | Build the optional analyzer GPIO toggle |
| `CONFIG_BLE_LOG_TS_ENABLED` | n | Deprecated compatibility entry selecting the GPIO toggle |
Old multi-LBM sizing options remain hidden only so existing sdkconfig files can
be parsed; they no longer control allocation.
## Validation apps
```bash
. ./export.sh
cd components/bt/common/ble_log/test_apps/ble_log_test
idf.py build
cd ../ble_log_rt_test
idf.py build
cd ../ble_log_perf_test
idf.py build
```
## Configuration Options
### Basic Configuration
| Configuration | Default | Description |
|---------------|---------|-------------|
| `CONFIG_BLE_LOG_ENABLED` | n | Enable BT Log Async Output |
| `CONFIG_BLE_LOG_LBM_TRANS_BUF_SIZE` | 2048 | Total buffer memory per common LBM (bytes). Divided equally among `BLE_LOG_TRANS_BUF_CNT` (4) internal transport buffers. |
| `CONFIG_BLE_LOG_LBM_ATOMIC_LOCK_TASK_CNT` | 2 | Number of atomic lock LBMs for task context |
| `CONFIG_BLE_LOG_LBM_ATOMIC_LOCK_ISR_CNT` | 1 | Number of atomic lock LBMs for ISR context |
### Link Layer Configuration
| Configuration | Default | Description |
|---------------|---------|-------------|
| `CONFIG_BLE_LOG_LL_ENABLED` | y | Enable Link Layer logging |
| `CONFIG_BLE_LOG_LBM_LL_TRANS_BUF_SIZE` | 2048 | Total buffer memory per Link Layer LBM (bytes). Divided equally among `BLE_LOG_TRANS_BUF_CNT` (4) internal transport buffers. |
### Other Features
| Configuration | Default | Description |
|---------------|---------|-------------|
| `CONFIG_BLE_LOG_TS_ENABLED` | n | Enable timestamp synchronization |
| `CONFIG_BLE_LOG_HOST_HCI_LOG_ENABLED` | n | Enable BLE Host side HCI logging |
> **Note**: Payload checksum and enhanced statistics are now always enabled and no longer have separate Kconfig options.
### Transport Method Configuration
| Transport | Configuration | Description |
|-----------|---------------|-------------|
| Dummy | `CONFIG_BLE_LOG_PRPH_DUMMY` | Debug dummy transport (default unless `SOC_UHCI_SUPPORTED`) |
| SPI Master DMA | `CONFIG_BLE_LOG_PRPH_SPI_MASTER_DMA` | SPI DMA transport |
| UART DMA | `CONFIG_BLE_LOG_PRPH_UART_DMA` | UART DMA transport (default when `SOC_UHCI_SUPPORTED`). Default baud rate: 3000000. |
### Deprecated / Removed
| Module | Status | Notes |
|--------|--------|-------|
| Legacy SPI Log Output | Deprecated | Moved to `deprecated/` directory. Use BT Log Async Output instead. A separate Kconfig menu "Legacy SPI Log Output" is available for backward compatibility. |
| UHCI Out | Removed | The standalone UHCI Out module (`ble_log_uhci_out.c`) has been removed. UART DMA transport under the main BLE Log peripheral interface replaces it. |
## API Reference
### Core API
#### `bool ble_log_init(void)`
Initialize the BLE Log module.
**Return Value**:
- `true`: Initialization successful
- `false`: Initialization failed
**Note**: Must be called before using any other APIs.
#### `void ble_log_deinit(void)`
Cleanup the BLE Log module and release all resources.
**Note**:
- All pending logs will be lost after calling this function
- Peripheral interface will be cleaned up first to avoid DMA transmission issues during memory release
- This function may run concurrently with BLE Log write APIs. New writes are
rejected after shutdown begins, and deinit waits for in-progress writers
before releasing their buffers.
#### `bool ble_log_write_hex(ble_log_src_t src_code, const uint8_t *addr, size_t len)`
Write hexadecimal log data.
**Parameters**:
- `src_code`: Log source code
- `addr`: Data pointer
- `len`: Data length
**Return Value**:
- `true`: Write successful
- `false`: Write failed (module not initialized or insufficient buffer)
#### `void ble_log_flush(void)`
End the current logging session and flush pending logs immediately.
This API temporarily suspends ordinary log writes, waits for in-progress
writers to exit, emits a final statistics internal frame, flushes pending
transport buffers, resets statistics, and then restores the enable state that
was in effect before the call.
**Note**: This operation is blocking and must run in an ordinary caller-owned
FreeRTOS task. Do not call it from an ISR or a system callback such as an ESP
Timer callback. If BLE Log was enabled before the call, it remains enabled
after the flush completes.
#### `void ble_log_dump_to_console(void)`
Output all buffer contents to console in hexadecimal format for debugging.
### Log Source Types
```c
typedef enum {
BLE_LOG_SRC_INTERNAL = 0, // Internal system logs
BLE_LOG_SRC_CUSTOM, // User-defined logs
BLE_LOG_SRC_LL_TASK, // Link Layer task logs
BLE_LOG_SRC_LL_HCI, // Link Layer HCI logs
BLE_LOG_SRC_LL_ISR, // Link Layer interrupt logs
BLE_LOG_SRC_HOST, // Host layer logs
BLE_LOG_SRC_HCI, // HCI layer logs
BLE_LOG_SRC_ENCODE, // Encoding layer logs
BLE_LOG_SRC_REDIR, // UART redirection (PORT 0 only)
BLE_LOG_SRC_MAX,
} ble_log_src_t;
```
### HCI Log Macro
```c
#define ble_log_write_hci(direction, data, len)
```
Writes an HCI packet with direction encoding. `direction` is `BLE_LOG_HCI_DOWNSTREAM` (0) or `BLE_LOG_HCI_UPSTREAM` (1). Direction is encoded in the MSB of the first byte (HCI type).
### Link Layer API (Conditional Compilation)
#### `void ble_log_write_hex_ll(uint32_t len, const uint8_t *addr, uint32_t len_append, const uint8_t *addr_append, uint32_t flag)`
Link Layer dedicated log writing interface.
**Parameters**:
- `len`: Main data length
- `addr`: Main data pointer
- `len_append`: Append data length
- `addr_append`: Append data pointer
- `flag`: Log flag bits
**Flag Definitions**:
```c
enum {
BLE_LOG_LL_FLAG_CONTINUE = 0,
BLE_LOG_LL_FLAG_END,
BLE_LOG_LL_FLAG_TASK,
BLE_LOG_LL_FLAG_ISR,
BLE_LOG_LL_FLAG_HCI,
BLE_LOG_LL_FLAG_RAW,
BLE_LOG_LL_FLAG_OMDATA,
BLE_LOG_LL_FLAG_HCI_UPSTREAM,
};
```
### Timestamp Synchronization API (Conditional Compilation)
#### `bool ble_log_sync_enable(bool enable)`
Enable or disable timestamp synchronization functionality.
**Parameters**:
- `enable`: true to enable, false to disable
**Return Value**:
- `true`: Operation successful
- `false`: Operation failed (module not initialized)
## Usage Examples
### Example 1: Basic Logging
```c
#include "ble_log.h"
void example_basic_logging() {
// Initialize
if (!ble_log_init()) {
printf("BLE Log init failed\n");
return;
}
// Log some example data
uint8_t hci_cmd[] = {0x01, 0x03, 0x0C, 0x00}; // HCI Reset Command
ble_log_write_hex(BLE_LOG_SRC_HCI, hci_cmd, sizeof(hci_cmd));
uint8_t host_data[] = {0x02, 0x00, 0x20, 0x0B, 0x00, 0x07, 0x00, 0x04, 0x00, 0x10, 0x01, 0x00, 0xFF, 0xFF, 0x00, 0x28};
ble_log_write_hex(BLE_LOG_SRC_HOST, host_data, sizeof(host_data));
// End session and flush buffers
ble_log_flush();
// Cleanup
ble_log_deinit();
}
```
### Example 2: ISR Context Logging
```c
void IRAM_ATTR some_isr_handler() {
uint8_t isr_data[] = {0xDE, 0xAD, 0xBE, 0xEF};
// Safe to write logs in ISR context
ble_log_write_hex(BLE_LOG_SRC_LL_ISR, isr_data, sizeof(isr_data));
}
```
### Example 3: Logging with Timestamp Synchronization
```c
void example_with_timestamp_sync() {
if (!ble_log_init()) {
return;
}
#if CONFIG_BLE_LOG_TS_ENABLED
// Enable timestamp synchronization
ble_log_sync_enable(true);
#endif
// Log data...
uint8_t data[] = {0x01, 0x02, 0x03};
ble_log_write_hex(BLE_LOG_SRC_CUSTOM, data, sizeof(data));
// Timestamp information will be automatically included in logs
ble_log_deinit();
}
```
### Example 4: Performance Testing
```c
void example_performance_test() {
if (!ble_log_init()) {
return;
}
uint8_t test_data[100];
for (int i = 0; i < 100; i++) {
test_data[i] = i;
}
uint32_t start_time = esp_timer_get_time();
// Send 1000 logs
for (int i = 0; i < 1000; i++) {
ble_log_write_hex(BLE_LOG_SRC_CUSTOM, test_data, sizeof(test_data));
}
// End session and flush buffers
ble_log_flush();
uint32_t end_time = esp_timer_get_time();
printf("Time to write 1000 logs: %lu us\n", end_time - start_time);
ble_log_deinit();
}
```
## Performance & Memory Optimization
### Memory Usage Estimation
Each LBM's total buffer memory is configured directly via Kconfig. The configured value is divided equally among `BLE_LOG_TRANS_BUF_CNT` (currently 4) internal transport buffers.
Memory usage under default configuration:
```
Common Pool:
LBM count = Atomic Task (2) + Atomic ISR (1) + Spinlock (2) = 5
Total = 5 × BLE_LOG_LBM_TRANS_BUF_SIZE = 5 × 2048 = 10240 bytes
Link Layer Pool (when CONFIG_BLE_LOG_LL_ENABLED):
LBM count = 2 (LL task + LL HCI)
Total = 2 × BLE_LOG_LBM_LL_TRANS_BUF_SIZE = 2 × 2048 = 4096 bytes
Statistics (always enabled):
Total = BLE_LOG_SRC_MAX × sizeof(ble_log_stat_mgr_t) = 9 × 20 = 180 bytes
UART Redirect (when UART DMA on PORT 0):
Additional BLE_LOG_TRANS_BUF_CNT (4) transport buffers
```
### Performance Optimization Recommendations
1. **Adjust LBM Count**: Adjust atomic lock LBM count based on concurrency requirements
2. **Buffer Size**: Adjust total buffer memory per LBM based on log volume; must be a multiple of `BLE_LOG_TRANS_BUF_CNT` (4)
3. **Transport Method**: Choose optimal transport method based on hardware (UART DMA is default on supported SoCs)
### Real-time Considerations
- Critical code paths are marked with `BLE_LOG_IRAM_ATTR` and run in IRAM
- Atomic operations avoid lock contention
- Multi-buffer transport ensures continuous writing even when some buffers are in-flight
## Troubleshooting
### Common Issues
#### 1. Initialization Failure
**Symptoms**: `ble_log_init()` returns `false`
**Possible Causes**:
- Insufficient memory
- Peripheral configuration error
- Duplicate initialization
**Solutions**:
```c
// Check available memory
printf("Free heap: %d bytes\n", esp_get_free_heap_size());
// Ensure initialization only happens once
static bool initialized = false;
if (!initialized) {
initialized = ble_log_init();
}
```
#### 2. Log Loss
**Symptoms**: Some logs don't appear in output
**Possible Causes**:
- Buffer overflow
- Transmission speed can't keep up with write speed
- Module not properly initialized
**Solutions**:
```c
// Enhanced statistics are always enabled — check written/lost frame
// and byte counts in the log stream output
// Increase total buffer memory per LBM
// CONFIG_BLE_LOG_LBM_TRANS_BUF_SIZE=4096
// Increase atomic lock LBM count
// CONFIG_BLE_LOG_LBM_ATOMIC_LOCK_TASK_CNT=4
```
#### 3. Performance Issues
**Symptoms**: System response becomes slow
**Possible Causes**:
- Transmission bottleneck
- Lock contention
**Solutions**:
```c
// Use faster transmission method
// CONFIG_BLE_LOG_PRPH_UART_DMA=y (default on SOC_UHCI_SUPPORTED targets)
// Increase baud rate (default is now 3000000)
// CONFIG_BLE_LOG_PRPH_UART_DMA_BAUD_RATE=3000000
```
### Debugging Techniques
#### 1. Use Dummy Transport for Debugging
```c
// Select Dummy transport in menuconfig
// Then use dump function to view buffer contents
ble_log_dump_to_console();
```
#### 2. Check Enhanced Statistics
```c
// Enhanced statistics are always enabled
// Written/lost frame and byte counts are automatically output to logs
```
#### 3. Monitor Memory Usage
```c
void monitor_memory() {
printf("Free heap before init: %d\n", esp_get_free_heap_size());
ble_log_init();
printf("Free heap after init: %d\n", esp_get_free_heap_size());
}
```
## Important Notes
### Buffer Size Constraints
- `CONFIG_BLE_LOG_LBM_TRANS_BUF_SIZE` and `CONFIG_BLE_LOG_LBM_LL_TRANS_BUF_SIZE` must be multiples of `BLE_LOG_TRANS_BUF_CNT` (currently 4)
- The per-buffer size (total ÷ 4) must be at least large enough to hold one frame overhead (`BLE_LOG_FRAME_OVERHEAD`)
- `BLE_LOG_TRANS_BUF_CNT` must be a power of 2
### Migration from Legacy Modules
- **UHCI Out**: The standalone `ble_log_uhci_out` module has been removed. Use the UART DMA peripheral transport (`CONFIG_BLE_LOG_PRPH_UART_DMA`) instead.
- **SPI Out**: The legacy SPI log output has been moved to `deprecated/`. A separate Kconfig menu "Legacy SPI Log Output (Deprecated)" is available for backward compatibility, but new projects should use BT Log Async Output with the SPI Master DMA peripheral transport.
`ble_log_test` validates golden v8 bytes, the consolidated Internal Snapshot,
source/HCI metadata and capture selection, pool exhaustion and reserve use,
snapshot busy loss, stale claims, and enable/disable/deinit races.
`ble_log_rt_test` covers batched dispatch, timer behavior, inflight statistics,
and repeated deinit races.
@@ -15,6 +15,7 @@ config BLE_COMPRESSED_LOG_ENABLE
for installation instructions.
if BLE_COMPRESSED_LOG_ENABLE
source "$IDF_PATH/components/bt/common/ble_log/extension/log_compression/profile/mesh/Kconfig.mesh.in"
source "$IDF_PATH/components/bt/common/ble_log/extension/log_compression/iso/audio/Kconfig.iso.in"
source "$IDF_PATH/components/bt/common/ble_log/extension/log_compression/host/Kconfig.host.in"
@@ -9,14 +9,29 @@
// Private includes
#include "freertos/FreeRTOS.h"
#include "freertos/task.h"
#include "sdkconfig.h"
#include "ble_log_lbm_v2.h"
#include "ble_log_task_registry.h"
#include "ble_log_util.h"
#include "log_compression/utils.h"
#if CONFIG_BLE_COMPRESSED_LOG_ENABLE
#define BLE_CP_DROP_LOG_PERIOD 256U
#if CONFIG_BLE_MESH_COMPRESSED_LOG_ENABLE
_Static_assert(CONFIG_BLE_MESH_COMPRESSED_LOG_BUFFER_LEN <=
BLE_LOG_MAX_PAYLOAD_LEN - sizeof(uint32_t),
"Mesh compressed log record exceeds one BLE Log transport");
#endif
#if CONFIG_BLE_ISO_COMPRESSED_LOG_ENABLE
_Static_assert(CONFIG_BLE_ISO_COMPRESSED_LOG_BUFFER_LEN <=
BLE_LOG_MAX_PAYLOAD_LEN - sizeof(uint32_t),
"ISO compressed log record exceeds one BLE Log transport");
#endif
#if CONFIG_BLE_HOST_COMPRESSED_LOG_ENABLE
_Static_assert(CONFIG_BLE_HOST_COMPRESSED_LOG_BUFFER_LEN <=
BLE_LOG_MAX_PAYLOAD_LEN - sizeof(uint32_t),
"Host compressed log record exceeds one BLE Log transport");
#endif
#define BLE_CP_TRY_PUSH(expr) do { \
if ((expr) != 0) { \
@@ -24,88 +39,30 @@
} \
} while (0)
#define BUF_NAME(name, idx) name##_buffer##idx
#define BUF_MGMT_NAME(name) name##_log_buffer_mgmt
#define DECL_BUF_OP(name, len, idx) \
static uint8_t BUF_NAME(name, idx)[len];
#define INIT_MAP_OP(name, _, buffer_idx) \
{.busy = 0, \
.idx = 0, \
.buffer = BUF_NAME(name, buffer_idx), \
.len = sizeof(BUF_NAME(name, buffer_idx))},
#define DECLARE_BUFFERS(NAME, BUF_LEN, BUF_CNT) \
FOR_EACH_IDX(DECL_BUF_OP, NAME, BUF_LEN, GEN_INDEX(BUF_CNT));
#define INIT_BUFFER_MGMT(NAME, BUF_CNT) \
ble_cp_log_buffer_mgmt_t BUF_MGMT_NAME(NAME)[BUF_CNT] = { \
FOR_EACH_IDX(INIT_MAP_OP, NAME, 0, GEN_INDEX(BUF_CNT)) \
};
#if CONFIG_BLE_MESH_COMPRESSED_LOG_ENABLE
DECLARE_BUFFERS(mesh, CONFIG_BLE_MESH_COMPRESSED_LOG_BUFFER_LEN, LOG_CP_MAX_LOG_BUFFER_USED_SIMU);
INIT_BUFFER_MGMT(mesh, LOG_CP_MAX_LOG_BUFFER_USED_SIMU);
char * mesh_last_task_handle = NULL;
#endif
#if CONFIG_BLE_ISO_COMPRESSED_LOG_ENABLE
/* The BLE_ISO buffer is shared by every source compiled into the unified
* ISO channel: esp_ble_iso, esp_ble_audio (and future ISO consumers, e.g.
* HID-over-ISO), as well as the AUDIO_LIB runtime callback (prebuilt
* libble_audio.a, source code 5) — they all funnel here. */
DECLARE_BUFFERS(iso, CONFIG_BLE_ISO_COMPRESSED_LOG_BUFFER_LEN, LOG_CP_MAX_LOG_BUFFER_USED_SIMU);
INIT_BUFFER_MGMT(iso, LOG_CP_MAX_LOG_BUFFER_USED_SIMU);
char * iso_last_task_handle = NULL;
#endif
#if CONFIG_BLE_HOST_COMPRESSED_LOG_ENABLE && CONFIG_BT_BLUEDROID_ENABLED
DECLARE_BUFFERS(host, CONFIG_BLE_HOST_COMPRESSED_LOG_BUFFER_LEN, LOG_CP_MAX_LOG_BUFFER_USED_SIMU);
INIT_BUFFER_MGMT(host, LOG_CP_MAX_LOG_BUFFER_USED_SIMU);
char * host_last_task_handle = NULL;
#endif
#if CONFIG_BLE_HOST_COMPRESSED_LOG_ENABLE && CONFIG_BT_NIMBLE_ENABLED
DECLARE_BUFFERS(nimble, CONFIG_BLE_HOST_COMPRESSED_LOG_BUFFER_LEN, LOG_CP_MAX_LOG_BUFFER_USED_SIMU);
INIT_BUFFER_MGMT(nimble, LOG_CP_MAX_LOG_BUFFER_USED_SIMU);
char * nimble_last_task_handle = NULL;
#endif
/* The maximum number of supported parameters is 64 */
#define LOG_HEADER(log_type, info) ((log_type << 6) | (info & 0x3f))
int ble_compressed_log_cb_get(uint8_t source, ble_cp_log_buffer_mgmt_t **mgmt)
int ble_compressed_log_cb_get(uint8_t source, ble_cp_log_buffer_mgmt_t *mgmt)
{
ble_cp_log_buffer_mgmt_t *buffer_mgmt = NULL;
char ** last_handle = NULL;
char * cur_handle = pcTaskGetName(NULL);
uint16_t claim_len = 0;
switch (source)
{
#if CONFIG_BLE_MESH_COMPRESSED_LOG_ENABLE
case BLE_COMPRESSED_LOG_OUT_SOURCE_MESH:
case BLE_COMPRESSED_LOG_OUT_SOURCE_MESH_LIB:
buffer_mgmt = BUF_MGMT_NAME(mesh);
last_handle = &mesh_last_task_handle;
claim_len = CONFIG_BLE_MESH_COMPRESSED_LOG_BUFFER_LEN;
break;
#endif
#if CONFIG_BLE_ISO_COMPRESSED_LOG_ENABLE
case BLE_COMPRESSED_LOG_OUT_SOURCE_ISO:
case BLE_COMPRESSED_LOG_OUT_SOURCE_AUDIO_LIB:
buffer_mgmt = BUF_MGMT_NAME(iso);
last_handle = &iso_last_task_handle;
claim_len = CONFIG_BLE_ISO_COMPRESSED_LOG_BUFFER_LEN;
break;
#endif
#if CONFIG_BLE_HOST_COMPRESSED_LOG_ENABLE && (CONFIG_BT_BLUEDROID_ENABLED || CONFIG_BT_NIMBLE_ENABLED)
case BLE_COMPRESSED_LOG_OUT_SOURCE_HOST:
#if CONFIG_BT_BLUEDROID_ENABLED
buffer_mgmt = BUF_MGMT_NAME(host);
last_handle = &host_last_task_handle;
#elif CONFIG_BT_NIMBLE_ENABLED
buffer_mgmt = BUF_MGMT_NAME(nimble);
last_handle = &nimble_last_task_handle;
#endif
claim_len = CONFIG_BLE_HOST_COMPRESSED_LOG_BUFFER_LEN;
break;
#endif
default:
@@ -113,37 +70,36 @@ int ble_compressed_log_cb_get(uint8_t source, ble_cp_log_buffer_mgmt_t **mgmt)
return -1;
}
for (int i = 0; i < LOG_CP_MAX_LOG_BUFFER_USED_SIMU; i++) {
if (ble_log_cas_acquire(&(buffer_mgmt[i].busy))) {
*mgmt = &buffer_mgmt[i];
if (ble_log_cp_push_u8(*mgmt, source) != 0) {
(*mgmt)->idx = 0;
ble_log_cas_release(&((*mgmt)->busy));
return -1;
}
if (*last_handle == NULL ||
*last_handle != cur_handle) {
if (ble_log_cp_push_u8(*mgmt, LOG_HEADER(LOG_TYPE_INFO, LOG_TYPE_INFO_TASK_SWITCH)) != 0) {
(*mgmt)->idx = 0;
ble_log_cas_release(&((*mgmt)->busy));
return -1;
}
*last_handle = cur_handle;
}
return 0;
}
mgmt->len = claim_len;
mgmt->idx = 0;
mgmt->buffer = ble_log_claim(BLE_LOG_SRC_ENCODE, claim_len,
&mgmt->handle, true);
if (!mgmt->buffer) {
return -1;
}
return -1;
/* Resolve the task id only after the claim succeeded: the claim's
* lifetime reference pins the current registry epoch, so the id
* cannot cross an init/deinit boundary (which reassigns ids from 0).
* Resolving before the claim instead left a window where a full
* deinit/reinit completed and the stale id named a different task. */
uint8_t task_id = ble_log_task_id_current();
if (ble_log_cp_push_u8(mgmt, source) != 0 ||
ble_log_cp_push_u8(mgmt, task_id) != 0) {
ble_log_commit(mgmt->handle, 0);
return -1;
}
return 0;
}
static inline int ble_compressed_log_buffer_free(ble_cp_log_buffer_mgmt_t *mgmt)
static inline int ble_compressed_log_commit(ble_cp_log_buffer_mgmt_t *mgmt)
{
#if BLE_LOG_CP_CONTENT_CHECK_ENABLE
memset(mgmt->buffer, BLE_LOG_CP_CONTENT_CHECK_VAL, mgmt->idx);
#endif
mgmt->idx = 0;
ble_log_cas_release(&mgmt->busy);
ble_log_commit(mgmt->handle, mgmt->idx);
return 0;
}
static inline int ble_compressed_log_abort(ble_cp_log_buffer_mgmt_t *mgmt)
{
ble_log_commit(mgmt->handle, 0);
return 0;
}
@@ -287,76 +243,75 @@ int ble_log_compressed_hex_print_internal(ble_cp_log_buffer_mgmt_t *mgmt, uint32
int ble_log_compressed_hex_printv(uint8_t source, uint32_t log_index, size_t args_cnt, va_list args)
{
ble_cp_log_buffer_mgmt_t *mgmt = NULL;
ble_cp_log_buffer_mgmt_t mgmt;
if (ble_compressed_log_cb_get(source, &mgmt)) {
return 0;
}
if (ble_log_compressed_hex_print_internal(mgmt, log_index, args_cnt, args) != 0) {
ble_compressed_log_buffer_free(mgmt);
if (ble_log_compressed_hex_print_internal(&mgmt, log_index, args_cnt, args) != 0) {
ble_compressed_log_abort(&mgmt);
return 0;
}
ble_compressed_log_output(source, mgmt->buffer, mgmt->idx);
ble_compressed_log_buffer_free(mgmt);
ble_compressed_log_commit(&mgmt);
return 0;
}
int ble_log_compressed_hex_print(uint8_t source, uint32_t log_index, size_t args_cnt, ...)
{
ble_cp_log_buffer_mgmt_t *mgmt = NULL;
ble_cp_log_buffer_mgmt_t mgmt;
if (ble_compressed_log_cb_get(source, &mgmt)) {
return 0;
}
if (args_cnt == 0) {
if (ble_log_cp_push_u8(mgmt, LOG_HEADER(LOG_TYPE_HEX_ARGS, 0)) != 0 ||
ble_log_cp_push_u16(mgmt, log_index) != 0) {
ble_compressed_log_buffer_free(mgmt);
if (ble_log_cp_push_u8(&mgmt, LOG_HEADER(LOG_TYPE_HEX_ARGS, 0)) != 0 ||
ble_log_cp_push_u16(&mgmt, log_index) != 0) {
ble_compressed_log_abort(&mgmt);
return 0;
}
} else {
va_list args;
va_start(args, args_cnt);
if (ble_log_compressed_hex_print_internal(mgmt, log_index, args_cnt, args) != 0) {
if (ble_log_compressed_hex_print_internal(&mgmt, log_index, args_cnt, args) != 0) {
va_end(args);
ble_compressed_log_buffer_free(mgmt);
ble_compressed_log_abort(&mgmt);
return 0;
}
va_end(args);
}
ble_compressed_log_output(source, mgmt->buffer, mgmt->idx);
ble_compressed_log_buffer_free(mgmt);
ble_compressed_log_commit(&mgmt);
return 0;
}
int ble_log_compressed_hex_print_buf(uint8_t source, uint32_t log_index, uint8_t buf_idx, const uint8_t *buf, size_t len)
{
ble_cp_log_buffer_mgmt_t *mgmt = NULL;
ble_cp_log_buffer_mgmt_t mgmt;
if (ble_compressed_log_cb_get(source, &mgmt)) {
return 0;
}
if (buf == NULL) {
ble_log_cp_push_u8(mgmt, LOG_HEADER(LOG_TYPE_INFO, LOG_TYPE_INFO_NULL_BUF));
ble_log_cp_push_u16(mgmt, log_index);
ble_compressed_log_output(source, mgmt->buffer, mgmt->idx);
ble_compressed_log_buffer_free(mgmt);
if (ble_log_cp_push_u8(&mgmt, LOG_HEADER(LOG_TYPE_INFO, LOG_TYPE_INFO_NULL_BUF)) != 0 ||
ble_log_cp_push_u16(&mgmt, log_index) != 0) {
ble_compressed_log_abort(&mgmt);
return 0;
}
ble_compressed_log_commit(&mgmt);
return 0;
}
if (ble_log_cp_push_u8(mgmt, LOG_HEADER(LOG_TYPE_HEX_BUF, buf_idx)) != 0 ||
ble_log_cp_push_u16(mgmt, log_index) != 0 ||
ble_log_cp_push_u16(mgmt, (uint16_t)len) != 0 ||
ble_log_cp_push_buf(mgmt, buf, (uint16_t)len) != 0) {
ble_compressed_log_buffer_free(mgmt);
if (ble_log_cp_push_u8(&mgmt, LOG_HEADER(LOG_TYPE_HEX_BUF, buf_idx)) != 0 ||
ble_log_cp_push_u16(&mgmt, log_index) != 0 ||
ble_log_cp_push_u16(&mgmt, (uint16_t)len) != 0 ||
ble_log_cp_push_buf(&mgmt, buf, (uint16_t)len) != 0) {
ble_compressed_log_abort(&mgmt);
return 0;
}
ble_compressed_log_output(source, mgmt->buffer, mgmt->idx);
ble_compressed_log_buffer_free(mgmt);
ble_compressed_log_commit(&mgmt);
return 0;
}
#endif /* CONFIG_BLE_COMPRESSED_LOG_ENABLE */
@@ -10,49 +10,6 @@
#include <stdio.h>
#include <string.h>
#ifndef CONCAT
#define CONCAT(a, b) a##b
#endif
#ifndef _CONCAT
#define _CONCAT(a, b) CONCAT(a, b)
#endif
#define _0 0
#define _1 1
#define _2 2
#define _3 3
#define _4 4
#define _5 5
#define _6 6
#define _7 7
#define _8 8
#define _9 9
#define __COUNT_ARGS(_0, _1, _2, _3, _4, _5, _6, _7, _8, _9, _10, _11, _12, _n, X...) _n
#define COUNT_ARGS(X...) __COUNT_ARGS(, ##X, 12, 11, 10, 9, 8, 7, 6, 5, 4, 3, 2, 1, 0)
#ifndef FOR_EACH_IDX
#define FOR_EACH_IDX(macro, name, len, ...) \
_CONCAT(_FOR_EACH_, COUNT_ARGS(__VA_ARGS__))(macro, name, len, __VA_ARGS__)
#endif
#define _FOR_EACH_0(m, n, l, ...)
#define _FOR_EACH_1(m, n, l, i1, ...) m(n, l, i1)
#define _FOR_EACH_2(m, n, l, i1, ...) m(n, l, i1) _FOR_EACH_1(m, n, l, __VA_ARGS__)
#define _FOR_EACH_3(m, n, l, i1, ...) m(n, l, i1) _FOR_EACH_2(m, n, l, __VA_ARGS__)
#define _FOR_EACH_4(m, n, l, i1, ...) m(n, l, i1) _FOR_EACH_3(m, n, l, __VA_ARGS__)
#define _FOR_EACH_5(m, n, l, i1, ...) m(n, l, i1) _FOR_EACH_4(m, n, l, __VA_ARGS__)
#define _GEN_INDEX_0()
#define _GEN_INDEX_1() _0
#define _GEN_INDEX_2() _0, _1
#define _GEN_INDEX_3() _0, _1, _2
#define _GEN_INDEX_4() _0, _1, _2, _3
#define _GEN_INDEX_5() _0, _1, _2, _3, _4
#define GEN_INDEX(n) _CONCAT(_GEN_INDEX_, n)()
enum {
BLE_COMPRESSED_LOG_OUT_SOURCE_HOST,
BLE_COMPRESSED_LOG_OUT_SOURCE_MESH,
@@ -72,47 +29,30 @@ enum {
ARG_SIZE_TYPE_MAX,
};
/* The maximum number of buffers used simultaneously */
#define LOG_CP_MAX_LOG_BUFFER_USED_SIMU 3
#define LOG_TYPE_ZERO_ARGS 0
#define LOG_TYPE_HEX_ARGS 1
#define LOG_TYPE_HEX_BUF 2
/* This type of message is used to update log information,
* such as there is currently a new task log */
/* Informational in-band records (protocol v8). Task-id bindings used to
* be one of these; they are broadcast as INTERNAL frames on the periodic
* snapshot window now (see ble_log_task_registry.h), keeping the ENCODE
* stream user records only. */
#define LOG_TYPE_INFO 3
#define LOG_TYPE_INFO_TASK_ID_UPDATE 0
#define LOG_TYPE_INFO_NULL_BUF 1
#define LOG_TYPE_INFO_TASK_SWITCH 2
typedef struct {
volatile bool busy;
uint8_t *buffer;
uint16_t idx;
uint16_t len;
uint8_t *buffer; /* claim() payload pointer */
uint16_t idx; /* bytes written so far */
uint16_t len; /* claimed capacity (max_len) */
uint32_t handle; /* claim handle for commit/abort */
} ble_cp_log_buffer_mgmt_t;
#define CONTENT_CHECK(idx, buf, except_val, len)
#define LENGTH_CHECK(idx, pbuffer_mgmt) do ( if(unlikely((idx) > (pbuffer_mgmt->len))) assert(0 && "Maximum log buffer length exceeded");) while(0)
#define BLE_LOG_CP_CONTENT_CHECK_ENABLE 0
#define BLE_LOG_CP_CONTENT_CHECK_VAL 0x00
static inline int ble_log_cp_buffer_safe_check(ble_cp_log_buffer_mgmt_t *pbuf_mgmt, uint16_t write_len)
{
if ((pbuf_mgmt->idx + write_len) > pbuf_mgmt->len) {
printf("Maximum length of buffer(%p) idx %d write_len %d exceed\n", pbuf_mgmt, pbuf_mgmt->idx, write_len);
return -1;
}
#if BLE_LOG_CP_CONTENT_CHECK_ENABLE
for (int i = pbuf_mgmt->idx; i < pbuf_mgmt->idx + write_len; i++) {
if (pbuf_mgmt->buffer[i] != BLE_LOG_CP_CONTENT_CHECK_VAL) {
printf("The value(%02x) in the buffer does not match the expected(%02x)\n", pbuf_mgmt->buffer[i], BLE_LOG_CP_CONTENT_CHECK_VAL);
return -1;
}
}
#endif
return 0;
}
@@ -182,17 +122,4 @@ static inline int ble_log_cp_update_half_byte(ble_cp_log_buffer_mgmt_t *pbuf_mgm
return 0;
}
static inline int ble_log_cp_buffer_print(ble_cp_log_buffer_mgmt_t *pbuf_mgmt)
{
for (size_t i = 0; i < pbuf_mgmt->idx; i++) {
printf("%02x ", pbuf_mgmt->buffer[i]);
}
printf("\n");
return 0;
}
static inline int ble_compressed_log_output(uint8_t source, uint8_t *data, uint16_t len)
{
return ble_log_write_hex(BLE_LOG_SRC_ENCODE, data, len);
}
#endif /* _BLE_LOG_COMPRESSION_UTILS_H */
+27 -10
View File
@@ -20,6 +20,8 @@
* The number of BLE Log source code will directly determine the number of statistic manager
* memory requirements, keep it as less as possible; it's recommended to use subcode for more
* log data structure decoding */
/* CRITICAL: this enum is a public ABI and must not be reordered or renamed.
* Its values are the base on-wire source IDs of protocol v8 frames. */
typedef enum {
/* Internal */
BLE_LOG_SRC_INTERNAL = 0,
@@ -45,30 +47,45 @@ typedef enum {
#define BLE_LOG_HCI_DOWNSTREAM 0
#define BLE_LOG_HCI_UPSTREAM 1
/* HCI Log Write Macro
* Encodes direction in MSB of data[0] (HCI type byte) before writing.
* Safe because ble_log_write_hex -> ble_log_lbm_write_trans does synchronous memcpy.
* Parser reads MSB to determine direction; old firmware with MSB=0 defaults to "sent". */
#define ble_log_write_hci(direction, data, len) do { \
(data)[0] |= ((direction) << 7); \
ble_log_write_hex(BLE_LOG_SRC_HCI, (data), (len)); \
(data)[0] &= 0x7F; \
/* Encodes HCI direction in payload byte 0 bit 7 for the synchronous copy,
* then restores the complete original HCI type byte. The caller guarantees a
* non-NULL buffer with len > 0. */
#define ble_log_write_hci(direction, data, len) do { \
uint8_t *const ble_log_hci_data__ = (data); \
const uint8_t ble_log_hci_type__ = ble_log_hci_data__[0]; \
ble_log_hci_data__[0] = (ble_log_hci_type__ & 0x7fU) | \
((direction) ? 0x80U : 0U); \
(void)ble_log_write_hex(BLE_LOG_SRC_HCI, ble_log_hci_data__, \
(len)); \
ble_log_hci_data__[0] = ble_log_hci_type__; \
} while (0)
/* INTERFACE */
bool ble_log_init(void);
void ble_log_deinit(void);
/* Controls public producers only; periodic system output remains active. */
bool ble_log_enable(bool enable);
/* Blocking; call only from a caller-owned task, not an ISR or system callback. */
void ble_log_flush(void);
/* Waits for a shared transport in ordinary yieldable tasks. The shared ESP
* Timer task, ISR and critical-section callers fail fast when none is available. */
bool ble_log_write_hex(ble_log_src_t src_code, const uint8_t *addr, size_t len);
/* Same backpressure as ble_log_write_hex(): ordinary yieldable tasks wait
* when wait_for_transport is true; false opts out. The shared ESP Timer
* task and non-yieldable contexts fail fast regardless of this flag. */
uint8_t *ble_log_claim(ble_log_src_t src_code, size_t max_len,
uint32_t *handle, bool wait_for_transport);
void ble_log_commit(uint32_t handle, size_t actual_len);
void ble_log_dump_to_console(void);
#if CONFIG_BLE_LOG_LL_ENABLED
void ble_log_write_hex_ll(uint32_t len, const uint8_t *addr,
uint32_t len_append, const uint8_t *addr_append, uint32_t flag);
#endif /* CONFIG_BLE_LOG_LL_ENABLED */
#if CONFIG_BLE_LOG_TS_ENABLED
/* Task-context only. Controls the optional TS sync IO toggle, which starts
* disabled and low; this is a lifecycle-checked no-op when the toggle is not
* built. Periodic Internal Snapshots remain active in either state. */
bool ble_log_ts_sync_io_toggle_enable(bool enable);
/* Backward-compatible name for ble_log_ts_sync_io_toggle_enable(). */
bool ble_log_sync_enable(bool enable);
#endif /* CONFIG_BLE_LOG_TS_ENABLED */
#endif /* __BLE_LOG_H__ */
+30 -38
View File
@@ -10,14 +10,11 @@
/* INCLUDE */
#include "ble_log.h"
#include "ble_log_rt.h"
#include "ble_log_lbm.h"
#include "ble_log_lbm_v2.h"
#include "ble_log_prph.h"
#include "ble_log_util.h"
#include "esp_log.h"
#include "esp_system.h"
#if CONFIG_BLE_LOG_TS_ENABLED
#include "ble_log_ts.h"
#endif /* CONFIG_BLE_LOG_TS_ENABLED */
/* VARIABLE */
#define TAG "ble_log"
@@ -38,31 +35,29 @@ bool ble_log_init(void)
return true;
}
#if CONFIG_BLE_LOG_TS_ENABLED
/* Initialize BLE Log TS */
if (!ble_log_ts_init()) {
goto exit;
}
#endif /* CONFIG_BLE_LOG_TS_ENABLED */
/* Initialize BLE Log Runtime */
if (!ble_log_rt_init()) {
goto exit;
}
/* Initialize BLE Log LBM */
/* Allocate pool and dedicated Internal transport before runtime starts. */
if (!ble_log_lbm_init()) {
goto exit;
}
/* Initialize BLE Log peripheral interface */
if (!ble_log_prph_init(BLE_LOG_TRANS_TOTAL_CNT)) {
goto exit;
}
/* Initialization done */
if (!ble_log_rt_init()) {
goto exit;
}
ble_log_inited = true;
ble_log_enable(true);
/* Queue the required INIT snapshot before starting the periodic path or
* opening the public producer gate, so it starts the receiver epoch.
* INIT/FLUSH samples never toggle sync IO. */
ble_log_ts_info_t ts_info;
ble_log_rt_ts_sample(&ts_info, false);
if (!ble_log_internal_snapshot(BLE_LOG_SNAPSHOT_REASON_INIT, &ts_info, true) ||
!ble_log_rt_start_periodic() || !ble_log_enable(true)) {
goto exit;
}
esp_err_t ret = esp_register_shutdown_handler(ble_log_shutdown_handler);
if (ret == ESP_OK) {
shutdown_handler_registered = true;
@@ -70,12 +65,6 @@ bool ble_log_init(void)
ESP_LOGW(TAG, "Register shutdown handler failed, ret = 0x%x", ret);
}
/* Write initialization done log */
ble_log_info_t ble_log_info = {
.int_src_code = BLE_LOG_INT_SRC_INIT_DONE,
.version = BLE_LOG_VERSION,
};
ble_log_write_hex(BLE_LOG_SRC_INTERNAL, (const uint8_t *)&ble_log_info, sizeof(ble_log_info_t));
return true;
exit:
@@ -94,18 +83,26 @@ void ble_log_deinit(void)
}
}
ble_log_inited = false;
ble_log_lbm_close();
ble_log_lbm_begin_deinit();
/* CRITICAL — Deinit ordering rationale:
/* Seal and dispatch residual pool and UART0 REDIR data while the runtime
* queue is still alive. The peripheral waits below complete delivery. */
ble_log_lbm_drain_open_trans();
#if BLE_LOG_UART_REDIR_ENABLED
(void)ble_log_prph_flush();
#endif
/* CRITICAL - Deinit ordering rationale:
*
* 1. The LBM writer gate is closed before submodule teardown. Writers
* already inside the gate keep a reference until they finish; later
* writers are rejected.
* writers are rejected. With writers gone, the pool and REDIR drains
* seal and dispatch every residual frame while runtime is still live.
*
* 2. Runtime dispatch must be stopped FIRST to prevent it from sending
* 2. Runtime dispatch is stopped FIRST to prevent it from sending
* transports to an already-destroyed peripheral driver. Active
* submissions and callbacks finish before the timers are deleted;
* the queue is then drained and pending transports are discarded.
* submissions and callbacks finish before the timers and queue are
* deleted.
*
* 3. Peripheral interface is deinitialized SECOND. It waits for DMA
* operations started before runtime dispatch stopped, then destroys
@@ -113,13 +110,8 @@ void ble_log_deinit(void)
*
* 4. LBM is deinitialized LAST. At this point all DMA has completed
* (ensured by step 3) and all queued transports have been drained
* (ensured by step 2), so freeing the buffers is safe. */
* (ensured by steps 1 and 2), so freeing the buffers is safe. */
ble_log_rt_deinit();
ble_log_prph_deinit();
ble_log_lbm_deinit();
#if CONFIG_BLE_LOG_TS_ENABLED
/* Deinitialize BLE Log TS */
ble_log_ts_deinit();
#endif /* CONFIG_BLE_LOG_TS_ENABLED */
}
@@ -1,874 +0,0 @@
/*
* SPDX-FileCopyrightText: 2025-2026 Espressif Systems (Shanghai) CO LTD
*
* SPDX-License-Identifier: Apache-2.0
*/
/* ------------------------------- */
/* BLE Log - Log Buffer Management */
/* ------------------------------- */
/* INCLUDE */
#include "ble_log.h"
#include "ble_log_lbm.h"
#include "ble_log_rt.h"
#include "esp_log.h"
#if CONFIG_BLE_LOG_LL_ENABLED && CONFIG_SOC_ESP_NIMBLE_CONTROLLER
#if CONFIG_BT_DUAL_MODE_ARCH
#include "ble_mbuf.h"
#define BLE_MBUF_COPY(buf, off, len, dst) ble_mbuf_copydata((struct ble_mbuf *)(buf), off, len, dst)
#else
#include "os/os_mbuf.h"
#define BLE_MBUF_COPY(buf, off, len, dst) os_mbuf_copydata((struct os_mbuf *)(buf), off, len, dst)
#endif // CONFIG_BT_DUAL_MODE_ARCH
#endif /* CONFIG_BLE_LOG_LL_ENABLED && CONFIG_SOC_ESP_NIMBLE_CONTROLLER */
/* VARIABLE */
#define TAG "ble_log"
#define BLE_LOG_LBM_WAIT_TIMEOUT_MS (1000)
BLE_LOG_STATIC BLE_LOG_DRAM_ATTR volatile uint32_t lbm_ref_count = 0;
BLE_LOG_STATIC BLE_LOG_DRAM_ATTR uint32_t lbm_inited = 0;
BLE_LOG_STATIC BLE_LOG_DRAM_ATTR uint32_t lbm_enabled = 0;
BLE_LOG_STATIC volatile bool flush_in_progress = false;
BLE_LOG_STATIC BLE_LOG_DRAM_ATTR ble_log_lbm_ctx_t *lbm_ctx = NULL;
BLE_LOG_STATIC BLE_LOG_DRAM_ATTR ble_log_stat_mgr_t *stat_mgr_ctx[BLE_LOG_SRC_MAX] = {0};
/* PRIVATE FUNCTION DECLARATION */
BLE_LOG_STATIC
bool ble_log_lbm_acquire_trans(size_t log_len, ble_log_lbm_t **out_lbm,
ble_log_prph_trans_t ***out_trans);
BLE_LOG_STATIC void ble_log_lbm_release(ble_log_lbm_t *lbm);
BLE_LOG_STATIC void ble_log_lbm_submit_trans(ble_log_prph_trans_t **trans);
BLE_LOG_STATIC
ble_log_prph_trans_t **ble_log_lbm_get_trans(ble_log_lbm_t *lbm, size_t log_len);
BLE_LOG_STATIC bool ble_log_lbm_flush_all_trans(void);
BLE_LOG_STATIC void ble_log_lbm_reset_stats(void);
BLE_LOG_STATIC
void ble_log_lbm_write_trans(ble_log_prph_trans_t **trans, ble_log_src_t src_code,
const uint8_t *addr, uint16_t len,
const uint8_t *addr_append, uint16_t len_append, bool omdata);
BLE_LOG_STATIC
bool ble_log_write_hex_core(ble_log_src_t src_code, const uint8_t *addr, size_t len);
#if BLE_LOG_UART_REDIR_ENABLED
BLE_LOG_STATIC
void ble_log_lbm_stream_seal(ble_log_prph_trans_t **trans, ble_log_src_t src_code);
#endif /* BLE_LOG_UART_REDIR_ENABLED */
BLE_LOG_STATIC void ble_log_stat_mgr_update(ble_log_src_t src_code, uint32_t len, bool lost);
/* ------------------------- */
/* PRIVATE INTERFACE */
/* ------------------------- */
BLE_LOG_IRAM_ATTR BLE_LOG_STATIC
bool ble_log_lbm_ref_acquire(bool require_enabled)
{
if (!ble_log_ref_count_try_acquire(&lbm_ref_count, &lbm_inited)) {
return false;
}
if (require_enabled && !BLE_LOG_ATOMIC_LOAD_ACQUIRE(lbm_enabled)) {
BLE_LOG_REF_COUNT_RELEASE(&lbm_ref_count);
return false;
}
return true;
}
BLE_LOG_IRAM_ATTR BLE_LOG_STATIC
bool ble_log_lbm_acquire_trans(size_t log_len, ble_log_lbm_t **out_lbm,
ble_log_prph_trans_t ***out_trans)
{
*out_lbm = NULL;
*out_trans = NULL;
ble_log_lbm_t *lbm;
ble_log_prph_trans_t **trans;
ble_log_lbm_t *atomic_pool;
ble_log_lbm_t *spin_lbm;
int atomic_pool_size;
if (BLE_LOG_IN_ISR()) {
atomic_pool = lbm_ctx->atomic_pool_isr;
spin_lbm = &(lbm_ctx->spin_isr);
atomic_pool_size = BLE_LOG_LBM_ATOMIC_ISR_CNT;
} else {
atomic_pool = lbm_ctx->atomic_pool_task;
spin_lbm = &(lbm_ctx->spin_task);
atomic_pool_size = BLE_LOG_LBM_ATOMIC_TASK_CNT;
}
/* Try each atomic LBM: acquire lock, check buffer, fallback on failure */
for (int i = 0; i < atomic_pool_size; i++) {
lbm = &atomic_pool[i];
if (ble_log_cas_acquire(&(lbm->atomic_lock))) {
trans = ble_log_lbm_get_trans(lbm, log_len);
if (trans) {
*out_lbm = lbm;
*out_trans = trans;
return true;
}
ble_log_cas_release(&(lbm->atomic_lock));
}
}
/* Last resort: spinlock LBM */
lbm = spin_lbm;
BLE_LOG_ACQUIRE_SPIN_LOCK(&(lbm->spin_lock));
trans = ble_log_lbm_get_trans(lbm, log_len);
if (trans) {
*out_lbm = lbm;
*out_trans = trans;
return true;
}
BLE_LOG_RELEASE_SPIN_LOCK(&(lbm->spin_lock));
return false;
}
BLE_LOG_IRAM_ATTR BLE_LOG_STATIC
void ble_log_lbm_release(ble_log_lbm_t *lbm)
{
switch (lbm->lock_type) {
case BLE_LOG_LBM_LOCK_ATOMIC:
ble_log_cas_release(&(lbm->atomic_lock));
break;
case BLE_LOG_LBM_LOCK_SPIN:
BLE_LOG_RELEASE_SPIN_LOCK(&lbm->spin_lock);
break;
case BLE_LOG_LBM_LOCK_NONE:
default:
break;
}
}
BLE_LOG_IRAM_ATTR BLE_LOG_STATIC
void ble_log_lbm_submit_trans(ble_log_prph_trans_t **trans)
{
ble_log_prph_trans_t *submitted = *trans;
BLE_LOG_ATOMIC_STORE_RELAXED(submitted->prph_owned, true);
ble_log_lbm_t *lbm = (ble_log_lbm_t *)submitted->owner;
uint32_t inflight = __atomic_add_fetch(&lbm->trans_inflight, 1, __ATOMIC_RELAXED);
uint32_t peak = __atomic_load_n(&lbm->trans_inflight_peak, __ATOMIC_RELAXED);
while (inflight > peak &&
!__atomic_compare_exchange_n(&lbm->trans_inflight_peak, &peak, inflight,
false, __ATOMIC_RELAXED, __ATOMIC_RELAXED)) {
}
ble_log_rt_submit_trans(submitted);
}
BLE_LOG_STATIC bool ble_log_lbm_flush_all_trans(void)
{
ble_log_lbm_t *lbm;
ble_log_prph_trans_t **trans;
bool in_progress;
TickType_t start_tick = xTaskGetTickCount();
/* Queue transports with logs */
for (int i = 0; i < BLE_LOG_LBM_CNT; i++) {
lbm = &(lbm_ctx->lbm_pool[i]);
int trans_idx = lbm->trans_idx;
for (int j = 0; j < BLE_LOG_TRANS_BUF_CNT; j++) {
trans = &(lbm->trans[trans_idx]);
if (!BLE_LOG_ATOMIC_LOAD_ACQUIRE((*trans)->prph_owned) && (*trans)->pos) {
ble_log_lbm_submit_trans(trans);
}
trans_idx = (trans_idx + 1) & (BLE_LOG_TRANS_BUF_CNT - 1);
}
}
/* Dispatch anything still waiting on the defer alarm, then
* wait for transportation to finish */
if (!ble_log_rt_drain()) {
return false;
}
do {
in_progress = false;
for (int i = 0; i < BLE_LOG_LBM_CNT; i++) {
lbm = &(lbm_ctx->lbm_pool[i]);
for (int j = 0; j < BLE_LOG_TRANS_BUF_CNT; j++) {
trans = &(lbm->trans[j]);
in_progress |= BLE_LOG_ATOMIC_LOAD_ACQUIRE((*trans)->prph_owned);
}
}
if (in_progress) {
if ((xTaskGetTickCount() - start_tick) >=
pdMS_TO_TICKS(BLE_LOG_LBM_WAIT_TIMEOUT_MS)) {
ESP_LOGE(TAG, "Timed out waiting for BLE Log transports");
return false;
}
vTaskDelay(1);
}
} while (in_progress);
return true;
}
BLE_LOG_STATIC void ble_log_lbm_reset_stats(void)
{
ble_log_lbm_t *lbm;
for (int i = 0; i < BLE_LOG_SRC_MAX; i++) {
BLE_LOG_MEMSET(stat_mgr_ctx[i], 0, sizeof(ble_log_stat_mgr_t));
}
for (int i = 0; i < BLE_LOG_LBM_CNT; i++) {
lbm = &(lbm_ctx->lbm_pool[i]);
__atomic_store_n(&lbm->trans_inflight, 0, __ATOMIC_RELAXED);
__atomic_store_n(&lbm->trans_inflight_peak, 0, __ATOMIC_RELAXED);
}
#if CONFIG_BLE_LOG_PRPH_UART_DMA
ble_log_prph_reset_util_counters();
#endif
}
BLE_LOG_IRAM_ATTR BLE_LOG_STATIC
void ble_log_lbm_write_trans(ble_log_prph_trans_t **trans, ble_log_src_t src_code,
const uint8_t *addr, uint16_t len,
const uint8_t *addr_append, uint16_t len_append, bool omdata)
{
/* Preparation before writing */
uint8_t *buf = (*trans)->buf + (*trans)->pos;
uint16_t payload_len = len + len_append;
ble_log_stat_mgr_t *stat_mgr = stat_mgr_ctx[src_code];
uint32_t frame_sn = BLE_LOG_GET_FRAME_SN(&(stat_mgr->frame_sn));
ble_log_frame_head_t frame_head = {
.length = payload_len,
.frame_meta = BLE_LOG_MAKE_FRAME_META(src_code, frame_sn),
};
/* Memory operation */
BLE_LOG_MEMCPY(buf, &frame_head, BLE_LOG_FRAME_HEAD_LEN);
if (len) {
BLE_LOG_MEMCPY(buf + BLE_LOG_FRAME_HEAD_LEN, addr, len);
}
if (len_append) {
#if CONFIG_BLE_LOG_LL_ENABLED && CONFIG_SOC_ESP_NIMBLE_CONTROLLER
if (omdata) {
BLE_MBUF_COPY(addr_append, 0, len_append, buf + BLE_LOG_FRAME_HEAD_LEN + len);
}
else
#endif /* CONFIG_BLE_LOG_LL_ENABLED && CONFIG_SOC_ESP_NIMBLE_CONTROLLER */
{
BLE_LOG_MEMCPY(buf + BLE_LOG_FRAME_HEAD_LEN + len, addr_append, len_append);
}
}
/* Data integrity check */
uint32_t checksum = ble_log_fast_checksum((const uint8_t *)buf, BLE_LOG_FRAME_HEAD_LEN + payload_len);
BLE_LOG_MEMCPY(buf + BLE_LOG_FRAME_HEAD_LEN + payload_len, &checksum, BLE_LOG_FRAME_TAIL_LEN);
/* Update peripheral transport */
(*trans)->pos += payload_len + BLE_LOG_FRAME_OVERHEAD;
ble_log_stat_mgr_update(src_code, payload_len, false);
/* Queue trans if full */
if (BLE_LOG_TRANS_FREE_SPACE((*trans)) <= BLE_LOG_FRAME_OVERHEAD) {
ble_log_lbm_submit_trans(trans);
}
}
#if BLE_LOG_UART_REDIR_ENABLED
BLE_LOG_IRAM_ATTR BLE_LOG_STATIC
void ble_log_lbm_stream_seal(ble_log_prph_trans_t **trans, ble_log_src_t src_code)
{
if ((*trans)->pos <= BLE_LOG_FRAME_HEAD_LEN) {
return;
}
uint16_t payload_len = (*trans)->pos - BLE_LOG_FRAME_HEAD_LEN;
ble_log_stat_mgr_t *stat_mgr = stat_mgr_ctx[src_code];
uint32_t frame_sn = BLE_LOG_GET_FRAME_SN(&(stat_mgr->frame_sn));
ble_log_frame_head_t frame_head = {
.length = payload_len,
.frame_meta = BLE_LOG_MAKE_FRAME_META(src_code, frame_sn),
};
BLE_LOG_MEMCPY((*trans)->buf, &frame_head, BLE_LOG_FRAME_HEAD_LEN);
uint32_t checksum = ble_log_fast_checksum((*trans)->buf, (*trans)->pos);
BLE_LOG_MEMCPY((*trans)->buf + (*trans)->pos, &checksum, BLE_LOG_FRAME_TAIL_LEN);
(*trans)->pos += BLE_LOG_FRAME_TAIL_LEN;
ble_log_stat_mgr_update(src_code, payload_len, false);
ble_log_lbm_submit_trans(trans);
}
#endif /* BLE_LOG_UART_REDIR_ENABLED */
BLE_LOG_IRAM_ATTR BLE_LOG_STATIC
void ble_log_stat_mgr_update(ble_log_src_t src_code, uint32_t len, bool lost)
{
/* Get statistic manager by source code */
ble_log_stat_mgr_t *stat_mgr = stat_mgr_ctx[src_code];
/* Update aligned counters */
uint32_t bytes_cnt = len + BLE_LOG_FRAME_OVERHEAD;
if (lost) {
BLE_LOG_GET_FRAME_SN(&(stat_mgr->frame_sn)); /* consume SN for loss detection */
__atomic_fetch_add(&stat_mgr->lost_frame_cnt, 1, __ATOMIC_RELAXED);
__atomic_fetch_add(&stat_mgr->lost_bytes_cnt, bytes_cnt, __ATOMIC_RELAXED);
} else {
__atomic_fetch_add(&stat_mgr->written_frame_cnt, 1, __ATOMIC_RELAXED);
__atomic_fetch_add(&stat_mgr->written_bytes_cnt, bytes_cnt, __ATOMIC_RELAXED);
}
}
BLE_LOG_IRAM_ATTR BLE_LOG_STATIC
bool ble_log_write_hex_core(ble_log_src_t src_code, const uint8_t *addr, size_t len)
{
/* Get transport from the best available pool */
size_t payload_len = len + sizeof(uint32_t);
ble_log_lbm_t *lbm;
ble_log_prph_trans_t **trans;
if (!ble_log_lbm_acquire_trans(payload_len, &lbm, &trans)) {
goto failed;
}
/* Write transport */
uint32_t os_ts = pdTICKS_TO_MS(BLE_LOG_IN_ISR()?
xTaskGetTickCountFromISR():
xTaskGetTickCount());
ble_log_lbm_write_trans(trans, src_code, (const uint8_t *)&os_ts,
sizeof(uint32_t), addr, len, false);
/* Release */
ble_log_lbm_release(lbm);
return true;
failed:
if (BLE_LOG_ATOMIC_LOAD_RELAXED(lbm_inited)) {
ble_log_stat_mgr_update(src_code, payload_len, true);
}
return false;
}
/* -------------------------- */
/* INTERNAL INTERFACE */
/* -------------------------- */
/* CRITICAL:
* Recycle a transport back to its LBM pool after the send completes or fails.
* Leaves trans->pos untouched on purpose: a failed send keeps its buffered data
* so the next flush re-queues it (flush re-sends any trans with pos != 0) */
BLE_LOG_IRAM_ATTR void ble_log_lbm_recycle_trans(ble_log_prph_trans_t *trans)
{
ble_log_lbm_t *lbm = (ble_log_lbm_t *)trans->owner;
__atomic_fetch_sub(&lbm->trans_inflight, 1, __ATOMIC_RELAXED);
BLE_LOG_ATOMIC_STORE_RELEASE(trans->prph_owned, false);
}
bool ble_log_lbm_init(void)
{
/* Avoid double init */
if (BLE_LOG_ATOMIC_LOAD_ACQUIRE(lbm_inited)) {
return true;
}
/* Initialize LBM context */
lbm_ctx = (ble_log_lbm_ctx_t *)BLE_LOG_MALLOC(sizeof(ble_log_lbm_ctx_t));
if (!lbm_ctx) {
goto exit;
}
BLE_LOG_MEMSET(lbm_ctx, 0, sizeof(ble_log_lbm_ctx_t));
/* Initialize peripheral transport for common LBMs */
ble_log_lbm_t *lbm;
for (int i = 0; i < BLE_LOG_LBM_COMMON_CNT; i++) {
lbm = &(lbm_ctx->lbm_common_pool[i]);
for (int j = 0; j < BLE_LOG_TRANS_BUF_CNT; j++) {
if (!ble_log_prph_trans_init(&(lbm->trans[j]),
BLE_LOG_TRANS_SIZE)) {
goto exit;
}
lbm->trans[j]->owner = (void *)lbm;
}
}
/* Initialize lock types for atomic pool */
for (int i = 0; i < BLE_LOG_LBM_ATOMIC_CNT; i++) {
lbm_ctx->atomic_pool[i].lock_type = BLE_LOG_LBM_LOCK_ATOMIC;
}
/* Initialize lock types for spin pool */
for (int i = 0; i < BLE_LOG_LBM_SPIN_MAX; i++) {
lbm_ctx->spin_pool[i].lock_type = BLE_LOG_LBM_LOCK_SPIN;
portMUX_INITIALIZE(&(lbm_ctx->spin_pool[i].spin_lock));
}
#if CONFIG_BLE_LOG_LL_ENABLED
for (int i = 0; i < BLE_LOG_LBM_LL_MAX; i++) {
lbm = &(lbm_ctx->lbm_ll_pool[i]);
for (int j = 0; j < BLE_LOG_TRANS_BUF_CNT; j++) {
if (!ble_log_prph_trans_init(&(lbm->trans[j]),
BLE_LOG_TRANS_LL_SIZE)) {
goto exit;
}
lbm->trans[j]->owner = (void *)lbm;
}
}
/* Initialize lock types for LL pool */
for (int i = 0; i < BLE_LOG_LBM_LL_MAX; i++) {
lbm_ctx->lbm_ll_pool[i].lock_type = BLE_LOG_LBM_LOCK_NONE;
}
#endif /* CONFIG_BLE_LOG_LL_ENABLED */
/* Initialize statistic manager context */
for (int i = 0; i < BLE_LOG_SRC_MAX; i++) {
stat_mgr_ctx[i] = (ble_log_stat_mgr_t *)BLE_LOG_MALLOC(sizeof(ble_log_stat_mgr_t));
if (!stat_mgr_ctx[i]) {
goto exit;
}
BLE_LOG_MEMSET(stat_mgr_ctx[i], 0, sizeof(ble_log_stat_mgr_t));
}
/* Initialization done */
BLE_LOG_ATOMIC_STORE_RELAXED(lbm_enabled, false);
BLE_LOG_ATOMIC_STORE_RELEASE(lbm_inited, true);
return true;
exit:
ble_log_lbm_deinit();
return false;
}
void ble_log_lbm_close(void)
{
BLE_LOG_ATOMIC_STORE_SEQ_CST(lbm_inited, false);
BLE_LOG_ATOMIC_STORE_RELEASE(lbm_enabled, false);
}
void ble_log_lbm_deinit(void)
{
/* Close before waiting: every LBM entry increments the reference count
* before checking this seq_cst gate. */
ble_log_lbm_close();
/* Disable module and wait for all references to be released */
while (!ble_log_ref_count_wait(&lbm_ref_count, 0)) {
ESP_LOGE(TAG, "Timed out waiting for BLE Log references during deinit");
BLE_LOG_ASSERT(false);
}
/* Release statistic manager context */
for (int i = 0; i < BLE_LOG_SRC_MAX; i++) {
if (stat_mgr_ctx[i]) {
BLE_LOG_FREE(stat_mgr_ctx[i]);
stat_mgr_ctx[i] = NULL;
}
}
/* Release LBM */
if (lbm_ctx) {
/* Release peripheral transport for common pools */
ble_log_lbm_t *lbm;
for (int i = 0; i < BLE_LOG_LBM_CNT; i++) {
lbm = &(lbm_ctx->lbm_pool[i]);
for (int j = 0; j < BLE_LOG_TRANS_BUF_CNT; j++) {
ble_log_prph_trans_deinit(&(lbm->trans[j]));
}
}
/* Release LBM context */
BLE_LOG_FREE(lbm_ctx);
lbm_ctx = NULL;
}
}
BLE_LOG_IRAM_ATTR BLE_LOG_STATIC
ble_log_prph_trans_t **ble_log_lbm_get_trans(ble_log_lbm_t *lbm, size_t log_len)
{
/* Check if available buffer can contain incoming log */
ble_log_prph_trans_t **trans;
for (int i = 0; i < BLE_LOG_TRANS_BUF_CNT; i++) {
trans = &(lbm->trans[lbm->trans_idx]);
if (!BLE_LOG_ATOMIC_LOAD_ACQUIRE((*trans)->prph_owned)) {
/* Return if there's enough free space in current transport */
if (BLE_LOG_TRANS_FREE_SPACE((*trans)) >= (log_len + BLE_LOG_FRAME_OVERHEAD)) {
return trans;
}
/* Queue transport if there's insufficient free space */
if ((*trans)->pos) {
ble_log_lbm_submit_trans(trans);
}
}
/* Current transport unavailable, switch to the other */
lbm->trans_idx = (lbm->trans_idx + 1) & (BLE_LOG_TRANS_BUF_CNT - 1);
}
/* All buffers are unavailable */
return NULL;
}
void ble_log_write_enh_stat(void)
{
if (!ble_log_lbm_ref_acquire(true)) {
return;
}
/* Snapshot all sources under one critical section so the set of
* counters is mutually consistent, then write outside the lock. */
ble_log_enh_stat_t snapshots[BLE_LOG_SRC_MAX];
for (int i = 0; i < BLE_LOG_SRC_MAX; i++) {
snapshots[i].int_src_code = BLE_LOG_INT_SRC_ENH_STAT;
snapshots[i].src_code = i;
}
BLE_LOG_ENTER_CRITICAL();
for (int i = 0; i < BLE_LOG_SRC_MAX; i++) {
BLE_LOG_MEMCPY(&snapshots[i].written_frame_cnt,
&stat_mgr_ctx[i]->written_frame_cnt,
4 * sizeof(uint32_t));
}
BLE_LOG_EXIT_CRITICAL();
for (int i = 0; i < BLE_LOG_SRC_MAX; i++) {
ble_log_write_hex(BLE_LOG_SRC_INTERNAL, (const uint8_t *)&snapshots[i], sizeof(ble_log_enh_stat_t));
}
BLE_LOG_REF_COUNT_RELEASE(&lbm_ref_count);
}
#if BLE_LOG_UART_REDIR_ENABLED
/* ------------------------------------------------- */
/* STREAM WRITE INTERFACE */
/* */
/* Stream mode appends raw data into a transport */
/* buffer with deferred frame encapsulation: */
/* - Header space is reserved on first write */
/* - Data is memcpy'd after the reserved header */
/* - Header and checksum are filled in at seal */
/* */
/* get_trans(lbm, 0) reuse safety: */
/* */
/* get_trans auto-queues a buffer raw (no seal) when */
/* free_space < log_len + FRAME_OVERHEAD. With */
/* log_len = 0, this triggers at free_space < 10. */
/* */
/* To prevent unsealed stream data from being sent */
/* raw, stream_write auto-seals at free_space <= 10. */
/* This guarantees that any unsealed stream buffer */
/* seen by get_trans always has free_space > 10, */
/* so get_trans returns it directly without queuing. */
/* ------------------------------------------------- */
BLE_LOG_IRAM_ATTR
void ble_log_lbm_stream_write(ble_log_lbm_t *lbm, ble_log_src_t src_code,
const uint8_t *data, size_t len)
{
while (len > 0) {
ble_log_prph_trans_t **trans = ble_log_lbm_get_trans(lbm, 0);
if (!trans) {
ble_log_stat_mgr_update(src_code, len, true);
return;
}
if ((*trans)->pos == 0) {
(*trans)->pos = BLE_LOG_FRAME_HEAD_LEN;
}
uint16_t available = BLE_LOG_TRANS_FREE_SPACE((*trans));
if (available <= BLE_LOG_FRAME_TAIL_LEN) {
ble_log_lbm_stream_seal(trans, src_code);
continue;
}
available -= BLE_LOG_FRAME_TAIL_LEN;
size_t to_write = (len < available) ? len : available;
BLE_LOG_MEMCPY((*trans)->buf + (*trans)->pos, data, to_write);
(*trans)->pos += to_write;
data += to_write;
len -= to_write;
if (BLE_LOG_TRANS_FREE_SPACE((*trans)) <= BLE_LOG_FRAME_OVERHEAD) {
ble_log_lbm_stream_seal(trans, src_code);
}
}
}
BLE_LOG_IRAM_ATTR
void ble_log_lbm_stream_flush(ble_log_lbm_t *lbm, ble_log_src_t src_code)
{
int trans_idx = lbm->trans_idx;
for (int i = 0; i < BLE_LOG_TRANS_BUF_CNT; i++) {
ble_log_prph_trans_t **trans = &(lbm->trans[trans_idx]);
if (!BLE_LOG_ATOMIC_LOAD_ACQUIRE((*trans)->prph_owned) &&
(*trans)->pos > BLE_LOG_FRAME_HEAD_LEN) {
ble_log_lbm_stream_seal(trans, src_code);
}
trans_idx = (trans_idx + 1) & (BLE_LOG_TRANS_BUF_CNT - 1);
}
}
#endif /* BLE_LOG_UART_REDIR_ENABLED */
BLE_LOG_STATIC void ble_log_emit_buf_util(ble_log_lbm_t *lbm, uint8_t lbm_id)
{
ble_log_buf_util_t util = {
.int_src_code = BLE_LOG_INT_SRC_BUF_UTIL,
.lbm_id = lbm_id,
.trans_cnt = BLE_LOG_TRANS_BUF_CNT,
.inflight_peak = (uint8_t)__atomic_load_n(&lbm->trans_inflight_peak,
__ATOMIC_RELAXED),
};
ble_log_write_hex(BLE_LOG_SRC_INTERNAL,
(const uint8_t *)&util, sizeof(ble_log_buf_util_t));
}
void ble_log_write_buf_util(void)
{
if (!ble_log_lbm_ref_acquire(true)) {
return;
}
ble_log_emit_buf_util(&lbm_ctx->spin_task,
BLE_LOG_BUF_UTIL_MAKE_ID(BLE_LOG_BUF_UTIL_POOL_COMMON_TASK, 0));
for (int i = 0; i < BLE_LOG_LBM_ATOMIC_TASK_CNT; i++) {
ble_log_emit_buf_util(&lbm_ctx->atomic_pool_task[i],
BLE_LOG_BUF_UTIL_MAKE_ID(BLE_LOG_BUF_UTIL_POOL_COMMON_TASK, 1 + i));
}
ble_log_emit_buf_util(&lbm_ctx->spin_isr,
BLE_LOG_BUF_UTIL_MAKE_ID(BLE_LOG_BUF_UTIL_POOL_COMMON_ISR, 0));
for (int i = 0; i < BLE_LOG_LBM_ATOMIC_ISR_CNT; i++) {
ble_log_emit_buf_util(&lbm_ctx->atomic_pool_isr[i],
BLE_LOG_BUF_UTIL_MAKE_ID(BLE_LOG_BUF_UTIL_POOL_COMMON_ISR, 1 + i));
}
#if CONFIG_BLE_LOG_LL_ENABLED
ble_log_emit_buf_util(&lbm_ctx->lbm_ll_task,
BLE_LOG_BUF_UTIL_MAKE_ID(BLE_LOG_BUF_UTIL_POOL_LL, 0));
ble_log_emit_buf_util(&lbm_ctx->lbm_ll_hci,
BLE_LOG_BUF_UTIL_MAKE_ID(BLE_LOG_BUF_UTIL_POOL_LL, 1));
#endif
#if BLE_LOG_UART_REDIR_ENABLED
ble_log_lbm_t *redir_lbm = ble_log_prph_get_redir_lbm();
if (redir_lbm) {
ble_log_emit_buf_util(redir_lbm,
BLE_LOG_BUF_UTIL_MAKE_ID(BLE_LOG_BUF_UTIL_POOL_REDIR, 0));
}
#endif
BLE_LOG_REF_COUNT_RELEASE(&lbm_ref_count);
}
void ble_log_write_final_stat(void)
{
if (!ble_log_lbm_ref_acquire(false)) {
return;
}
ble_log_final_stat_t final_stat;
final_stat.int_src_code = BLE_LOG_INT_SRC_FINAL_STAT;
final_stat.src_cnt = BLE_LOG_SRC_MAX;
BLE_LOG_ENTER_CRITICAL();
for (int i = 0; i < BLE_LOG_SRC_MAX; i++) {
ble_log_final_stat_entry_t *entry = &final_stat.entries[i];
entry->src_code = i;
BLE_LOG_MEMCPY(&entry->written_frame_cnt,
&stat_mgr_ctx[i]->written_frame_cnt,
4 * sizeof(uint32_t));
}
BLE_LOG_EXIT_CRITICAL();
ble_log_write_internal((const uint8_t *)&final_stat, sizeof(final_stat));
BLE_LOG_REF_COUNT_RELEASE(&lbm_ref_count);
}
/* ------------------------ */
/* PUBLIC INTERFACE */
/* ------------------------ */
bool ble_log_enable(bool enable)
{
if (!BLE_LOG_ATOMIC_LOAD_ACQUIRE(lbm_inited)) {
return false;
}
BLE_LOG_ATOMIC_STORE_RELEASE(lbm_enabled, enable);
return true;
}
void ble_log_flush(void)
{
/* Prevent concurrent flush — two concurrent callers would deadlock on
* the ref_count spin-wait (both hold a ref, both wait for ref_count <= 1).
* Second caller returns immediately instead of deadlocking. */
if (__atomic_test_and_set(&flush_in_progress, __ATOMIC_ACQUIRE)) {
return;
}
if (!ble_log_lbm_ref_acquire(false)) {
goto clear;
}
ble_log_write_enh_stat();
ble_log_write_buf_util();
/* Write BLE Log flush log */
ble_log_info_t ble_log_info = {
.int_src_code = BLE_LOG_INT_SRC_FLUSH,
.version = BLE_LOG_VERSION,
};
ble_log_write_hex(BLE_LOG_SRC_INTERNAL, (const uint8_t *)&ble_log_info, sizeof(ble_log_info_t));
/* Disable module and wait for all other references to release */
bool lbm_enabled_copy = BLE_LOG_ATOMIC_LOAD_ACQUIRE(lbm_enabled);
BLE_LOG_ATOMIC_STORE_RELEASE(lbm_enabled, false);
if (!ble_log_ref_count_wait(&lbm_ref_count, 1)) {
ESP_LOGE(TAG, "Timed out waiting for BLE Log writers");
goto fail;
}
if (!ble_log_lbm_flush_all_trans()) {
goto fail;
}
ble_log_write_final_stat();
if (!ble_log_lbm_flush_all_trans()) {
goto fail;
}
ble_log_lbm_reset_stats();
fail:
/* Resume enable status after a completed or failed flush. */
BLE_LOG_ATOMIC_STORE_RELEASE(lbm_enabled, lbm_enabled_copy);
BLE_LOG_REF_COUNT_RELEASE(&lbm_ref_count);
clear:
__atomic_clear(&flush_in_progress, __ATOMIC_RELEASE);
}
BLE_LOG_IRAM_ATTR
bool ble_log_write_hex(ble_log_src_t src_code, const uint8_t *addr, size_t len)
{
bool ret = false;
if (!ble_log_lbm_ref_acquire(true)) {
return false;
}
ret = ble_log_write_hex_core(src_code, addr, len);
BLE_LOG_REF_COUNT_RELEASE(&lbm_ref_count);
return ret;
}
BLE_LOG_IRAM_ATTR
bool ble_log_write_internal(const uint8_t *addr, size_t len)
{
bool ret = false;
if (!ble_log_lbm_ref_acquire(false)) {
return false;
}
ret = ble_log_write_hex_core(BLE_LOG_SRC_INTERNAL, addr, len);
BLE_LOG_REF_COUNT_RELEASE(&lbm_ref_count);
return ret;
}
#if CONFIG_BLE_LOG_LL_ENABLED
BLE_LOG_IRAM_ATTR
void ble_log_write_hex_ll(uint32_t len, const uint8_t *addr,
uint32_t len_append, const uint8_t *addr_append, uint32_t flag)
{
if (!ble_log_lbm_ref_acquire(true)) {
return;
}
/* Source code shall be determined before LBM determination */
ble_log_src_t src_code = BLE_LOG_SRC_MAX;
bool use_ll_task = false;
if (flag & BIT(BLE_LOG_LL_FLAG_ISR)) {
src_code = BLE_LOG_SRC_LL_ISR;
} else if (flag & BIT(BLE_LOG_LL_FLAG_HCI)) {
src_code = BLE_LOG_SRC_LL_HCI;
} else if (flag & BIT(BLE_LOG_LL_FLAG_HCI_UPSTREAM)) {
src_code = BLE_LOG_SRC_HCI;
} else {
src_code = BLE_LOG_SRC_LL_TASK;
use_ll_task = true;
}
bool omdata = flag & BIT(BLE_LOG_LL_FLAG_OMDATA);
/* Determine LBM and get transport */
ble_log_lbm_t *lbm;
ble_log_prph_trans_t **trans;
size_t payload_len;
if (BLE_LOG_IN_ISR()) {
/* os_mbuf_copydata is in flash and not safe to call from ISR */
omdata = false;
payload_len = len + len_append;
if (!ble_log_lbm_acquire_trans(payload_len, &lbm, &trans)) {
goto failed;
}
} else {
if (use_ll_task) {
lbm = &(lbm_ctx->lbm_ll_task);
} else {
lbm = &(lbm_ctx->lbm_ll_hci);
#if CONFIG_BLE_LOG_LL_HCI_LOG_PAYLOAD_LEN_LIMIT_ENABLED
if (len_append > CONFIG_BLE_LOG_LL_HCI_LOG_PAYLOAD_LEN_LIMIT) {
len_append = CONFIG_BLE_LOG_LL_HCI_LOG_PAYLOAD_LEN_LIMIT;
}
#endif /* CONFIG_BLE_LOG_LL_HCI_LOG_PAYLOAD_LEN_LIMIT_ENABLED */
}
payload_len = len + len_append;
trans = ble_log_lbm_get_trans(lbm, payload_len);
if (!trans) {
/* LL pools use LOCK_NONE, release is no-op */
goto failed;
}
}
/* Write transport */
ble_log_lbm_write_trans(trans, src_code, addr, len, addr_append, len_append, omdata);
ble_log_lbm_release(lbm);
BLE_LOG_REF_COUNT_RELEASE(&lbm_ref_count);
return;
failed:
if (BLE_LOG_ATOMIC_LOAD_RELAXED(lbm_inited)) {
ble_log_stat_mgr_update(src_code, payload_len, true);
}
BLE_LOG_REF_COUNT_RELEASE(&lbm_ref_count);
return;
}
#endif /* CONFIG_BLE_LOG_LL_ENABLED */
void ble_log_dump_to_console(void)
{
if (!ble_log_lbm_ref_acquire(false)) {
return;
}
int trans_idx;
ble_log_lbm_t *lbm;
ble_log_prph_trans_t *trans;
BLE_LOG_ENTER_CRITICAL();
BLE_LOG_CONSOLE("[BLE_LOG_DUMP_START:\n");
for (int i = 0; i < BLE_LOG_LBM_CNT; i++) {
lbm = &(lbm_ctx->lbm_pool[i]);
trans_idx = lbm->trans_idx;
for (int j = 0; j < BLE_LOG_TRANS_BUF_CNT; j++) {
trans = lbm->trans[trans_idx];
BLE_LOG_FEED_WDT();
for (int k = 0; k < trans->size; k++) {
BLE_LOG_CONSOLE("%02x ", trans->buf[k]);
if (!(k & 0xFF)) {
BLE_LOG_FEED_WDT();
}
}
trans_idx = (trans_idx + 1) & (BLE_LOG_TRANS_BUF_CNT - 1);
}
}
BLE_LOG_CONSOLE("\n:BLE_LOG_DUMP_END]\n\n");
BLE_LOG_EXIT_CRITICAL();
BLE_LOG_REF_COUNT_RELEASE(&lbm_ref_count);
return;
}
File diff suppressed because it is too large Load Diff
@@ -0,0 +1,121 @@
/*
* SPDX-FileCopyrightText: 2025-2026 Espressif Systems (Shanghai) CO LTD
*
* SPDX-License-Identifier: Apache-2.0
*/
/* ------------------------------------------------- */
/* BLE Log - UART Redirection Stream Writer */
/* */
/* Stream mode appends raw data into a transport */
/* buffer with deferred frame encapsulation. */
/* Redirection transports are single-writer under */
/* redir->mutex; their only concurrent mutation is */
/* the UART tx-done recycle (state SENDING -> FREE), */
/* so state access uses atomics. */
/* ------------------------------------------------- */
/* INCLUDE */
#include "ble_log_redir.h"
#include "ble_log_rt.h"
#if BLE_LOG_UART_REDIR_ENABLED
BLE_LOG_STATIC void ble_log_redir_seal(ble_log_prph_trans_t *trans, ble_log_src_t src_code);
BLE_LOG_STATIC
ble_log_prph_trans_t *ble_log_redir_get_trans(ble_log_redir_t *redir,
ble_log_src_t src_code)
{
for (int i = 0; i < BLE_LOG_TRANS_BUF_CNT; i++) {
ble_log_prph_trans_t *trans = redir->trans[redir->trans_idx];
if (BLE_LOG_ATOMIC_LOAD_ACQUIRE(trans->state) != BLE_LOG_TRANS_STATE_SENDING) {
if (BLE_LOG_TRANS_FREE_SPACE(trans) >= BLE_LOG_FRAME_OVERHEAD) {
return trans;
}
if (trans->pos > BLE_LOG_FRAME_HEAD_LEN) {
ble_log_redir_seal(trans, src_code);
}
}
redir->trans_idx = (redir->trans_idx + 1) & (BLE_LOG_TRANS_BUF_CNT - 1);
}
return NULL;
}
BLE_LOG_STATIC
void ble_log_redir_seal(ble_log_prph_trans_t *trans, ble_log_src_t src_code)
{
if (trans->pos <= BLE_LOG_FRAME_HEAD_LEN) {
return;
}
uint16_t payload_len = trans->pos - BLE_LOG_FRAME_HEAD_LEN;
ble_log_redir_t *redir = ble_log_prph_get_redir_lbm();
/* REDIR keeps its own stream sequence: a raw console stream is not a
* log attempt, so it never eats Global SNs or fakes loss gaps. The
* stream has no core-stat slot. */
uint32_t frame_sn = BLE_LOG_GET_FRAME_SN(redir->frame_sn);
ble_log_frame_head_t frame_head = {
.length = payload_len,
.frame_meta = BLE_LOG_MAKE_FRAME_META(src_code, frame_sn),
};
BLE_LOG_MEMCPY(trans->buf, &frame_head, BLE_LOG_FRAME_HEAD_LEN);
uint32_t checksum = ble_log_fast_checksum(trans->buf, trans->pos);
BLE_LOG_MEMCPY(trans->buf + trans->pos, &checksum, BLE_LOG_FRAME_TAIL_LEN);
trans->pos += BLE_LOG_FRAME_TAIL_LEN;
uint32_t infl = __atomic_add_fetch(&redir->inflight, 1, __ATOMIC_RELAXED);
ble_log_atomic_update_peak(&redir->inflight_peak, infl);
BLE_LOG_ATOMIC_STORE_RELAXED(trans->state, BLE_LOG_TRANS_STATE_SENDING);
ble_log_rt_submit_trans(trans);
}
void ble_log_lbm_stream_write(ble_log_redir_t *redir, ble_log_src_t src_code,
const uint8_t *data, size_t len)
{
while (len > 0) {
ble_log_prph_trans_t *trans = ble_log_redir_get_trans(redir, src_code);
if (!trans) {
/* Burn one stream SN so the dropped console batch leaves a
* gap in the REDIR sequence. */
(void)BLE_LOG_GET_FRAME_SN(redir->frame_sn);
return;
}
if (trans->pos == 0) {
trans->pos = BLE_LOG_FRAME_HEAD_LEN;
}
uint16_t available = BLE_LOG_TRANS_FREE_SPACE(trans);
if (available <= BLE_LOG_FRAME_TAIL_LEN) {
ble_log_redir_seal(trans, src_code);
continue;
}
available -= BLE_LOG_FRAME_TAIL_LEN;
size_t to_write = (len < available) ? len : available;
BLE_LOG_MEMCPY(trans->buf + trans->pos, data, to_write);
trans->pos += to_write;
data += to_write;
len -= to_write;
if (BLE_LOG_TRANS_FREE_SPACE(trans) <= BLE_LOG_FRAME_OVERHEAD) {
ble_log_redir_seal(trans, src_code);
}
}
}
void ble_log_lbm_stream_flush(ble_log_redir_t *redir, ble_log_src_t src_code)
{
int trans_idx = redir->trans_idx;
for (int i = 0; i < BLE_LOG_TRANS_BUF_CNT; i++) {
ble_log_prph_trans_t *trans = redir->trans[trans_idx];
if (BLE_LOG_ATOMIC_LOAD_ACQUIRE(trans->state) != BLE_LOG_TRANS_STATE_SENDING &&
trans->pos > BLE_LOG_FRAME_HEAD_LEN) {
ble_log_redir_seal(trans, src_code);
}
trans_idx = (trans_idx + 1) & (BLE_LOG_TRANS_BUF_CNT - 1);
}
}
#endif /* BLE_LOG_UART_REDIR_ENABLED */
+187 -134
View File
@@ -11,172 +11,166 @@
/* INCLUDE */
#include "ble_log.h"
#include "ble_log_rt.h"
#include "ble_log_lbm.h"
#include "ble_log_lbm_v2.h"
#include "ble_log_task_registry.h"
#include "ble_log_util.h"
#include "esp_log.h"
#include "esp_timer.h"
#include "esp_chip_info.h"
#if CONFIG_BLE_LOG_LL_ENABLED
#include "esp_bt.h"
#endif
#include "driver/gpio.h"
/* MACRO */
#define TAG "ble_log_rt"
#define BLE_LOG_RT_DEFER_TIMEOUT_US (1000)
#if CONFIG_BT_CONTROLLER_ENABLED
#if CONFIG_IDF_TARGET_ESP32 || CONFIG_IDF_TARGET_ESP32C3 || CONFIG_IDF_TARGET_ESP32S3
extern const char *btdm_controller_get_compile_version(void);
#define BLE_LOG_CONTROLLER_GET_COMMIT() btdm_controller_get_compile_version()
#elif !CONFIG_BT_DUAL_MODE_ARCH || CONFIG_BT_CTRL_BLE_ENABLE
/* BR/EDR-only dual-mode builds do not link the BLE controller lib */
extern char *ble_controller_get_compile_version(void);
#define BLE_LOG_CONTROLLER_GET_COMMIT() ble_controller_get_compile_version()
#endif
/* Link-layer clock sample; 0 when the controller exports no accessor. */
#if CONFIG_BLE_LOG_LL_ENABLED
#if CONFIG_BT_DUAL_MODE_ARCH
/* BTDM common lib (dual-mode arch only) */
extern const char *r_btdm_get_compile_version(void);
#define BLE_LOG_BTDM_COMMON_GET_COMMIT() r_btdm_get_compile_version()
#endif
#endif
/* Temporary fallback until the dual-mode controller libraries export the
* link-layer timer accessor. A strong library definition overrides it. */
uint32_t r_sched_timer_getCurrentTimeU32(void) __attribute__((weak));
uint32_t r_sched_timer_getCurrentTimeU32(void)
{
return 0;
}
#define BLE_LOG_GET_LC_TS r_sched_timer_getCurrentTimeU32()
/* ESP BLE Controller Gen 2 */
#elif defined(CONFIG_IDF_TARGET_ESP32H2) || defined(CONFIG_IDF_TARGET_ESP32C6) || defined(CONFIG_IDF_TARGET_ESP32C5) ||\
defined(CONFIG_IDF_TARGET_ESP32C61) || defined(CONFIG_IDF_TARGET_ESP32H21)
extern uint32_t r_ble_lll_timer_current_tick_get(void);
#define BLE_LOG_GET_LC_TS r_ble_lll_timer_current_tick_get()
/* ESP BLE Controller Gen 1 */
#elif defined(CONFIG_IDF_TARGET_ESP32C2)
extern uint32_t r_os_cputime_get32(void);
#define BLE_LOG_GET_LC_TS r_os_cputime_get32()
/* Legacy BLE Controller */
#elif defined(CONFIG_IDF_TARGET_ESP32C3) || defined(CONFIG_IDF_TARGET_ESP32S3)
extern uint32_t lld_read_clock_us(void);
#define BLE_LOG_GET_LC_TS lld_read_clock_us()
#else /* Other targets */
#define BLE_LOG_GET_LC_TS 0
#endif /* BLE targets */
#else /* !CONFIG_BLE_LOG_LL_ENABLED */
#define BLE_LOG_GET_LC_TS 0
#endif /* CONFIG_BLE_LOG_LL_ENABLED */
#if CONFIG_BLE_MESH && CONFIG_BLE_MESH_V11_SUPPORT
/* "Bluetooth Mesh v1.1 commit: <hash>" */
extern const char bt_mesh_v11_commit_str[];
BLE_LOG_STATIC uint32_t ble_log_rt_lc_ts_get(void)
{
#if CONFIG_BLE_LOG_LL_ENABLED
/* Legacy accessors dereference controller state. INIT is emitted before
* controller initialization completes, and standalone users may keep the
* controller idle for the entire BLE Log epoch. */
if (esp_bt_controller_get_status() == ESP_BT_CONTROLLER_STATUS_IDLE) {
return 0;
}
#endif
#if CONFIG_BT_AUDIO && CONFIG_SOC_BLE_AUDIO_SUPPORTED
extern const char *lib_audio_commit_get(void);
#endif
_Static_assert(sizeof(ble_log_version_info_t) == 58,
"Unexpected BLE Log version info frame size");
return BLE_LOG_GET_LC_TS;
}
/* VARIABLE */
BLE_LOG_STATIC BLE_LOG_DRAM_ATTR uint32_t rt_inited = 0;
BLE_LOG_STATIC BLE_LOG_DRAM_ATTR volatile uint32_t rt_ref_count = 0;
BLE_LOG_STATIC BLE_LOG_DRAM_ATTR QueueHandle_t rt_queue_handle = NULL;
BLE_LOG_STATIC BLE_LOG_DRAM_ATTR esp_timer_handle_t rt_defer_timer = NULL;
BLE_LOG_STATIC uint32_t rt_last_hook_os_ts = 0;
#if CONFIG_BLE_LOG_TS_ENABLED
BLE_LOG_STATIC BLE_LOG_DRAM_ATTR uint32_t rt_ts_enabled = 0;
BLE_LOG_STATIC esp_timer_handle_t rt_ts_timer = NULL;
#endif /* CONFIG_BLE_LOG_TS_ENABLED */
BLE_LOG_STATIC BLE_LOG_DRAM_ATTR esp_timer_handle_t rt_ts_timer = NULL;
/* Toggle IO phase; stays false when the toggle IO is compiled out. */
BLE_LOG_STATIC BLE_LOG_DRAM_ATTR bool rt_ts_io_level = false;
#if CONFIG_BLE_LOG_TS_SYNC_TOGGLE_IO_ENABLED
/* Runtime IO control is independent from the always-on periodic snapshot. */
BLE_LOG_STATIC BLE_LOG_DRAM_ATTR bool rt_ts_io_toggle_enabled = false;
#endif
/* PRIVATE FUNCTION DECLARATION */
BLE_LOG_STATIC void ble_log_rt_defer_cb(void *arg);
BLE_LOG_STATIC bool ble_log_rt_dispatch(QueueHandle_t queue, UBaseType_t pending);
BLE_LOG_STATIC void ble_log_rt_run_hook(void);
#if CONFIG_BLE_LOG_TS_ENABLED
BLE_LOG_STATIC void ble_log_rt_dispatch(QueueHandle_t queue,
UBaseType_t pending);
BLE_LOG_STATIC void ble_log_rt_ts_trigger(void *arg);
#endif /* CONFIG_BLE_LOG_TS_ENABLED */
/* PRIVATE FUNCTION */
/* Copies a NUL-terminated commit string into a fixed-width zero-padded field */
BLE_LOG_STATIC void ble_log_commit_copy(uint8_t *dst, const char *src, size_t len)
/* Captures the link-layer, ESP and OS clocks at one instant. */
void ble_log_rt_ts_sample(ble_log_ts_info_t *info, bool toggle_io)
{
BLE_LOG_MEMCPY(dst, src, strnlen(src, len));
info->int_src_code = BLE_LOG_INT_SRC_TS;
BLE_LOG_ENTER_CRITICAL();
#if CONFIG_BLE_LOG_TS_SYNC_TOGGLE_IO_ENABLED
/* The critical section keeps the optional IO edge and clock samples
* adjacent, and serializes runtime IO control with the phase update. */
if (toggle_io && rt_ts_io_toggle_enabled) {
rt_ts_io_level = !rt_ts_io_level;
gpio_set_level(CONFIG_BLE_LOG_SYNC_IO_NUM, rt_ts_io_level);
}
#endif /* CONFIG_BLE_LOG_TS_SYNC_TOGGLE_IO_ENABLED */
info->io_level = rt_ts_io_level;
info->lc_ts = ble_log_rt_lc_ts_get();
info->esp_ts = esp_timer_get_time();
info->os_ts = pdTICKS_TO_MS(xTaskGetTickCountFromISR());
BLE_LOG_EXIT_CRITICAL();
}
BLE_LOG_STATIC void ble_log_rt_run_hook(void)
{
uint32_t now = pdTICKS_TO_MS(xTaskGetTickCount());
if ((uint32_t)(now - rt_last_hook_os_ts) < BLE_LOG_TS_TRIGGER_TIMEOUT_MS) {
return;
}
rt_last_hook_os_ts = now;
/* Write version info: BLE Log version, idf commit (build-time),
* linked-in BLE lib commits, chip model/revision (efuse, runtime-only).
* Libs absent from the build leave their fields zero. */
ble_log_version_info_t version_info = {
.int_src_code = BLE_LOG_INT_SRC_VERSION_INFO,
.version = BLE_LOG_VERSION,
};
#ifdef BLE_LOG_IDF_COMMIT
BLE_LOG_MEMCPY(version_info.idf_commit, BLE_LOG_IDF_COMMIT, BLE_LOG_IDF_COMMIT_LEN);
#endif
#if CONFIG_BT_CONTROLLER_ENABLED && defined(BLE_LOG_CONTROLLER_GET_COMMIT)
ble_log_commit_copy(version_info.controller_commit, BLE_LOG_CONTROLLER_GET_COMMIT(),
BLE_LOG_LIB_COMMIT_LEN);
#endif
#if CONFIG_BT_CONTROLLER_ENABLED && defined(BLE_LOG_BTDM_COMMON_GET_COMMIT)
ble_log_commit_copy(version_info.btdm_common_commit, BLE_LOG_BTDM_COMMON_GET_COMMIT(),
BLE_LOG_LIB_COMMIT_LEN);
#endif
#if CONFIG_BLE_MESH && CONFIG_BLE_MESH_V11_SUPPORT
/* The hash is the substring after the last space of the lib string */
const char *mesh_commit = strrchr(bt_mesh_v11_commit_str, ' ');
if (mesh_commit) {
ble_log_commit_copy(version_info.mesh_commit, mesh_commit + 1,
BLE_LOG_LIB_COMMIT_LEN);
}
#endif
#if CONFIG_BT_AUDIO && CONFIG_SOC_BLE_AUDIO_SUPPORTED
ble_log_commit_copy(version_info.audio_commit, lib_audio_commit_get(),
BLE_LOG_LIB_COMMIT_LEN);
#endif
esp_chip_info_t chip_info;
esp_chip_info(&chip_info);
version_info.chip_model = (uint16_t)chip_info.model;
version_info.chip_revision = chip_info.revision;
ble_log_write_hex(BLE_LOG_SRC_INTERNAL, (const uint8_t *)&version_info,
sizeof(version_info));
ble_log_write_enh_stat();
ble_log_write_buf_util();
}
BLE_LOG_STATIC bool ble_log_rt_dispatch(QueueHandle_t queue, UBaseType_t pending)
/* Dispatch only the queue depth observed at callback entry. A backend may
* recycle synchronously on queue-full while another core immediately refills
* the runtime queue; an unbounded loop here could starve every other callback
* on the shared ESP timer task. */
BLE_LOG_STATIC void ble_log_rt_dispatch(QueueHandle_t queue,
UBaseType_t pending)
{
ble_log_prph_trans_t *trans = NULL;
bool processed = false;
while (pending-- && xQueueReceive(queue, &trans, 0) == pdTRUE) {
ble_log_prph_send_trans(trans);
processed = true;
}
return processed;
}
BLE_LOG_STATIC void ble_log_rt_defer_cb(void *arg)
{
(void)arg;
/* Deinit clears the queue only after stop_blocking has waited for this
* callback, so a live gate implies a live queue. */
if (!BLE_LOG_ATOMIC_LOAD_ACQUIRE(rt_inited)) {
return;
}
QueueHandle_t queue = rt_queue_handle;
if (!queue) {
return;
}
ble_log_rt_dispatch(queue, uxQueueMessagesWaiting(queue));
UBaseType_t pending = uxQueueMessagesWaiting(queue);
if (ble_log_rt_dispatch(queue, pending)) {
ble_log_rt_run_hook();
}
pending = uxQueueMessagesWaiting(queue);
if (pending &&
/* A submit racing an active one-shot callback may fail to arm it. If the
* bounded batch left work behind, schedule another turn after yielding
* the shared timer task to callbacks that are already due. */
if (uxQueueMessagesWaiting(queue) &&
ble_log_ref_count_try_acquire(&rt_ref_count, &rt_inited)) {
(void)esp_timer_start_once(rt_defer_timer, BLE_LOG_RT_DEFER_TIMEOUT_US);
(void)esp_timer_start_once(rt_defer_timer,
BLE_LOG_RT_DEFER_TIMEOUT_US);
BLE_LOG_REF_COUNT_RELEASE(&rt_ref_count);
}
}
#if CONFIG_BLE_LOG_TS_ENABLED
BLE_LOG_STATIC void ble_log_rt_ts_trigger(void *arg)
{
(void)arg;
if (!BLE_LOG_ATOMIC_LOAD_ACQUIRE(rt_inited) ||
!BLE_LOG_ATOMIC_LOAD_ACQUIRE(rt_ts_enabled)) {
if (!BLE_LOG_ATOMIC_LOAD_ACQUIRE(rt_inited)) {
return;
}
ble_log_ts_info_t *ts_info = NULL;
ble_log_ts_info_update(&ts_info);
if (ts_info) {
ble_log_write_hex(BLE_LOG_SRC_INTERNAL, (const uint8_t *)ts_info, sizeof(ble_log_ts_info_t));
}
ble_log_ts_info_t ts_info;
ble_log_rt_ts_sample(&ts_info, true);
/* Unified periodic output: best-effort flush of partially-filled OPEN
* transports ahead of the periodic snapshot, so parked frames do not
* wait for the next capacity seal. The task-id binding broadcast
* rides the same window, ahead of the snapshot, on its own dedicated
* transport: a receiver that missed a binding converges on the next
* one, and the snapshot never waits behind it. */
ble_log_lbm_flush_open_trans();
ble_log_task_bindings_publish();
(void)ble_log_internal_snapshot(
BLE_LOG_SNAPSHOT_REASON_PERIODIC |
BLE_LOG_SNAPSHOT_REASON_TS_VALID,
&ts_info, false);
}
#endif /* CONFIG_BLE_LOG_TS_ENABLED */
/* INTERFACE */
bool ble_log_rt_init(void)
@@ -185,6 +179,21 @@ bool ble_log_rt_init(void)
return true;
}
/* Configure the analyzer toggle IO */
#if CONFIG_BLE_LOG_TS_SYNC_TOGGLE_IO_ENABLED
gpio_config_t sync_io_conf = {
.intr_type = GPIO_INTR_DISABLE,
.mode = GPIO_MODE_OUTPUT,
.pin_bit_mask = BIT64(CONFIG_BLE_LOG_SYNC_IO_NUM),
};
/* Program the output latch before enabling the driver to avoid a stale
* high level or a high glitch after deinit/reinit. */
if (gpio_set_level(CONFIG_BLE_LOG_SYNC_IO_NUM, 0) != ESP_OK ||
gpio_config(&sync_io_conf) != ESP_OK) {
goto exit;
}
#endif /* CONFIG_BLE_LOG_TS_SYNC_TOGGLE_IO_ENABLED */
rt_queue_handle = xQueueCreate(BLE_LOG_TRANS_TOTAL_CNT, sizeof(ble_log_prph_trans_t *));
if (!rt_queue_handle) {
goto exit;
@@ -201,8 +210,13 @@ bool ble_log_rt_init(void)
goto exit;
}
#if CONFIG_BLE_LOG_TS_ENABLED
BLE_LOG_ATOMIC_STORE_RELAXED(rt_ts_enabled, false);
/* Create the system-periodic path here; the top-level init starts it only
* after queuing INIT, then it runs through deinit. Runtime sync control
* affects only the optional analyzer IO toggle. */
rt_ts_io_level = false;
#if CONFIG_BLE_LOG_TS_SYNC_TOGGLE_IO_ENABLED
rt_ts_io_toggle_enabled = false;
#endif
esp_timer_create_args_t ts_timer_args = {
.callback = ble_log_rt_ts_trigger,
.arg = NULL,
@@ -211,13 +225,10 @@ bool ble_log_rt_init(void)
/* Do not wake light sleep or replay every missed periodic callback. */
.skip_unhandled_events = true,
};
if (esp_timer_create(&ts_timer_args, &rt_ts_timer) != ESP_OK ||
esp_timer_start_periodic(rt_ts_timer, BLE_LOG_TS_TRIGGER_TIMEOUT_US) != ESP_OK) {
if (esp_timer_create(&ts_timer_args, &rt_ts_timer) != ESP_OK) {
goto exit;
}
#endif /* CONFIG_BLE_LOG_TS_ENABLED */
rt_last_hook_os_ts = 0;
BLE_LOG_ATOMIC_STORE_RELEASE(rt_inited, true);
return true;
@@ -226,6 +237,21 @@ exit:
return false;
}
bool ble_log_rt_start_periodic(void)
{
bool started = false;
if (!ble_log_ref_count_try_acquire(&rt_ref_count, &rt_inited)) {
return false;
}
if (rt_ts_timer &&
esp_timer_start_periodic(rt_ts_timer,
BLE_LOG_TS_TRIGGER_TIMEOUT_US) == ESP_OK) {
started = true;
}
BLE_LOG_REF_COUNT_RELEASE(&rt_ref_count);
return started;
}
void ble_log_rt_deinit(void)
{
/* Closing gate: seq_cst on both sides (see also submit/drain) so a
@@ -236,14 +262,11 @@ void ble_log_rt_deinit(void)
ESP_LOGE(TAG, "Timed out waiting for BLE Log runtime references");
BLE_LOG_ASSERT(false);
}
#if CONFIG_BLE_LOG_TS_ENABLED
BLE_LOG_ATOMIC_STORE_RELEASE(rt_ts_enabled, false);
if (rt_ts_timer) {
esp_timer_stop_blocking(rt_ts_timer, portMAX_DELAY);
esp_timer_delete(rt_ts_timer);
rt_ts_timer = NULL;
}
#endif /* CONFIG_BLE_LOG_TS_ENABLED */
if (rt_defer_timer) {
esp_timer_stop_blocking(rt_defer_timer, portMAX_DELAY);
@@ -254,12 +277,18 @@ void ble_log_rt_deinit(void)
if (rt_queue_handle) {
ble_log_prph_trans_t *trans = NULL;
while (xQueueReceive(rt_queue_handle, &trans, 0) == pdTRUE) {
trans->pos = 0;
ble_log_lbm_recycle_trans(trans);
}
vQueueDelete(rt_queue_handle);
rt_queue_handle = NULL;
}
/* Release the toggle IO */
rt_ts_io_level = false;
#if CONFIG_BLE_LOG_TS_SYNC_TOGGLE_IO_ENABLED
rt_ts_io_toggle_enabled = false;
gpio_reset_pin(CONFIG_BLE_LOG_SYNC_IO_NUM);
#endif /* CONFIG_BLE_LOG_TS_SYNC_TOGGLE_IO_ENABLED */
}
bool ble_log_rt_drain(void)
@@ -276,7 +305,9 @@ bool ble_log_rt_drain(void)
goto exit;
}
QueueHandle_t queue = rt_queue_handle;
(void)ble_log_rt_dispatch(queue, uxQueueMessagesWaiting(queue));
while (uxQueueMessagesWaiting(queue)) {
ble_log_rt_dispatch(queue, uxQueueMessagesWaiting(queue));
}
drained = true;
exit:
@@ -287,13 +318,13 @@ exit:
BLE_LOG_IRAM_ATTR void ble_log_rt_submit_trans(ble_log_prph_trans_t *trans)
{
if (!ble_log_ref_count_try_acquire(&rt_ref_count, &rt_inited)) {
/* No reference was taken, so this path must not release; it stays
* separate from the held-reference failures below. */
ble_log_lbm_recycle_trans(trans);
return;
}
if (!rt_queue_handle) {
BLE_LOG_REF_COUNT_RELEASE(&rt_ref_count);
ble_log_lbm_recycle_trans(trans);
return;
goto fail;
}
bool in_isr = BLE_LOG_IN_ISR();
@@ -301,24 +332,46 @@ BLE_LOG_IRAM_ATTR void ble_log_rt_submit_trans(ble_log_prph_trans_t *trans)
? xQueueSendFromISR(rt_queue_handle, &trans, NULL)
: xQueueSend(rt_queue_handle, &trans, 0);
if (queued != pdTRUE) {
BLE_LOG_REF_COUNT_RELEASE(&rt_ref_count);
ble_log_lbm_recycle_trans(trans);
return;
goto fail;
}
/* An active timer keeps the deadline anchored to the first submission. */
(void)esp_timer_start_once(rt_defer_timer, BLE_LOG_RT_DEFER_TIMEOUT_US);
BLE_LOG_REF_COUNT_RELEASE(&rt_ref_count);
return;
fail:
BLE_LOG_REF_COUNT_RELEASE(&rt_ref_count);
ble_log_lbm_recycle_trans(trans);
}
#if CONFIG_BLE_LOG_TS_ENABLED
bool ble_log_sync_enable(bool enable)
bool ble_log_ts_sync_io_toggle_enable(bool enable)
{
if (!BLE_LOG_ATOMIC_LOAD_ACQUIRE(rt_inited)) {
if (!ble_log_ref_count_try_acquire(&rt_ref_count, &rt_inited)) {
return false;
}
BLE_LOG_ATOMIC_STORE_RELEASE(rt_ts_enabled, enable);
ble_log_ts_reset(enable);
#if CONFIG_BLE_LOG_TS_SYNC_TOGGLE_IO_ENABLED
/* Restart the analyzer phase from low. When disabling an already-low IO,
* drive it high first so the external analyzer still sees a final
* falling edge. The periodic snapshot remains active in either state. */
BLE_LOG_ENTER_CRITICAL();
rt_ts_io_toggle_enabled = enable;
if (!enable && !rt_ts_io_level) {
gpio_set_level(CONFIG_BLE_LOG_SYNC_IO_NUM, 1);
}
rt_ts_io_level = false;
gpio_set_level(CONFIG_BLE_LOG_SYNC_IO_NUM, 0);
BLE_LOG_EXIT_CRITICAL();
#else
(void)enable;
#endif /* CONFIG_BLE_LOG_TS_SYNC_TOGGLE_IO_ENABLED */
BLE_LOG_REF_COUNT_RELEASE(&rt_ref_count);
return true;
}
#endif /* CONFIG_BLE_LOG_TS_ENABLED */
bool ble_log_sync_enable(bool enable)
{
return ble_log_ts_sync_io_toggle_enable(enable);
}
@@ -0,0 +1,274 @@
/*
* SPDX-FileCopyrightText: 2026 Espressif Systems (Shanghai) CO LTD
*
* SPDX-License-Identifier: Apache-2.0
*/
/* ------------------------------------ */
/* BLE Log - Task-id Registry */
/* */
/* Owns the name-to-id registry, its */
/* broadcast sequence and its dedicated */
/* transport; a separate .c/.h pair */
/* like the UART redirection writer. */
/* ------------------------------------ */
/* INCLUDE */
#include "ble_log_task_registry.h"
#include "ble_log_rt.h"
#include "freertos/task.h"
#include "esp_timer.h"
/* MACRO */
/* Registry entries are word-compared on the record path. */
#define BLE_LOG_TASK_NAME_WORDS (BLE_LOG_TASK_NAME_LEN / sizeof(uint32_t))
/* ble_log_task_lookup() and ble_log_task_register() compare the four name
* words literally; a different name width must rework them. */
_Static_assert(BLE_LOG_TASK_NAME_WORDS == 4,
"Unexpected BLE Log task name word count");
/* VARIABLE */
/* Plain static variables (NOBITS .bss): the registry has no IRAM path, and zero
* page-image bytes beat DRAM_ATTR placement for a table this size. */
BLE_LOG_STATIC uint32_t s_task_names[CONFIG_BLE_LOG_TASK_ID_MAX][BLE_LOG_TASK_NAME_WORDS];
BLE_LOG_STATIC volatile uint8_t s_task_cnt;
BLE_LOG_STATIC ble_log_atomic_lock_t s_task_reg_lock;
/* The binding broadcast keeps its own 24-bit frame sequence, separate
* from the log/snapshot Global SN (see ble_log_lbm_v2.h): a gap counts a
* broadcast window skipped despite a non-empty registry, never a lost
* snapshot. ble_log_task_registry_init resets it. */
BLE_LOG_STATIC uint32_t g_task_binding_sn;
#define BLE_LOG_GET_TASK_BINDING_SN() BLE_LOG_GET_FRAME_SN(g_task_binding_sn)
/* Module lifetime gate, closed by begin_deinit (LBM teardown starts):
* publish is system output beyond the public producer gate, and only
* module teardown stops new broadcasts. The publish path never blocks,
* so the begin_deinit drain is immediate. */
BLE_LOG_STATIC volatile uint32_t s_registry_ref_count = 0;
BLE_LOG_STATIC uint32_t s_registry_inited = 0;
/* The dedicated single-frame transport. It shares the INTERNAL owner
* kind: recycled by the peripheral tx-done straight back to FREE, with
* no pool bookkeeping. */
BLE_LOG_STATIC ble_log_prph_trans_t *binding_trans;
/* ------------------------------- */
/* Registry Lookup/Insert */
/* ------------------------------- */
/* - Entries are append-only: an inserter (holding s_task_reg_lock)
* writes all name words first and publishes the entry by storing the
* new count with RELEASE; readers ACQUIRE-load the count and scan
* only the entries below it, so the read path is lock-free.
* - Names are matched by content, not by TCB pointer, so a recycled
* TCB cannot alias two different tasks onto one id.
* - Names longer than the storage are truncated; tasks sharing the
* truncated prefix share an id (identical names are indistinguishable
* in the decoded log anyway).
* - A full registry, or a contended registration attempt, degrades that
* record to the unknown id (BLE_LOG_TASK_ID_UNKNOWN) and still emits
* it; the task retries the registration with its next record.
* - Bindings are broadcast on every periodic snapshot window, so a
* receiver that joined late or lost a frame converges on the next
* window; broadcasts are idempotent on the wire and a lost one
* self-heals on the next window. A task that starts logging between
* windows emits records tagged with its id; the receiver binds the id
* at the next window. */
/* Normalizes a task name to NUL-padded words. Word-level compare
* replaces strcmp on the record path: the first word acts as the hash,
* a miss costs one load per entry, and there is no call overhead. Inline:
* every ENCODE record resolves its writer id, so this runs per record. */
BLE_LOG_STATIC inline void ble_log_task_name_to_words(
const char *name, uint32_t w[BLE_LOG_TASK_NAME_WORDS])
{
BLE_LOG_MEMSET(w, 0, BLE_LOG_TASK_NAME_LEN);
BLE_LOG_MEMCPY(w, name, strnlen(name, BLE_LOG_TASK_NAME_LEN));
}
/* Per-record lookup: inline for the same reason as the normalizer above. */
BLE_LOG_STATIC inline uint8_t ble_log_task_lookup(
const uint32_t w[BLE_LOG_TASK_NAME_WORDS])
{
uint8_t cnt = BLE_LOG_ATOMIC_LOAD_ACQUIRE(s_task_cnt);
for (uint8_t i = 0; i < cnt; i++) {
if (s_task_names[i][0] != w[0]) {
continue;
}
if (w[1] == s_task_names[i][1] && w[2] == s_task_names[i][2] &&
w[3] == s_task_names[i][3]) {
return i;
}
}
return BLE_LOG_TASK_ID_UNKNOWN;
}
/* Cold path, once per task lifetime. A single CAS attempt serializes
* inserters: on contention this record degrades to the unknown id
* instead of blocking, and the next record of the task retries. */
BLE_LOG_STATIC uint8_t ble_log_task_register(const uint32_t w[BLE_LOG_TASK_NAME_WORDS])
{
uint8_t id = BLE_LOG_TASK_ID_UNKNOWN;
if (!BLE_LOG_CAS_ACQUIRE(&s_task_reg_lock)) {
return BLE_LOG_TASK_ID_UNKNOWN;
}
uint8_t cnt = s_task_cnt;
for (uint8_t i = 0; i < cnt; i++) {
if (w[0] == s_task_names[i][0] && w[1] == s_task_names[i][1] &&
w[2] == s_task_names[i][2] && w[3] == s_task_names[i][3]) {
BLE_LOG_CAS_RELEASE(&s_task_reg_lock);
return i; /* raced with another first lookup */
}
}
if (cnt < CONFIG_BLE_LOG_TASK_ID_MAX) {
BLE_LOG_MEMCPY(s_task_names[cnt], w, BLE_LOG_TASK_NAME_LEN);
id = cnt;
BLE_LOG_ATOMIC_STORE_RELEASE(s_task_cnt, cnt + 1);
}
BLE_LOG_CAS_RELEASE(&s_task_reg_lock);
return id;
}
uint8_t ble_log_task_id_current(void)
{
const char *cur_name = pcTaskGetName(NULL);
if (!cur_name) {
return BLE_LOG_TASK_ID_UNKNOWN;
}
uint32_t w[BLE_LOG_TASK_NAME_WORDS];
ble_log_task_name_to_words(cur_name, w);
uint8_t id = ble_log_task_lookup(w);
/* Registration mutates shared state; ISR callers stop at the
* lookup-hit path and read only. */
if (id == BLE_LOG_TASK_ID_UNKNOWN && !BLE_LOG_IN_ISR()) {
id = ble_log_task_register(w);
}
return id;
}
/* ----------------------------------- */
/* Periodic Binding Broadcast */
/* ----------------------------------- */
/* One binding frame on the dedicated registry transport, packing every
* registered entry in id order. Best effort, single CAS attempt: a busy
* transport (the previous broadcast still in DMA) skips this window and
* the next one rebroadcasts. The registry is only read here (ACQUIRE
* count, append-only entries), so this races no inserter. */
BLE_LOG_STATIC bool ble_log_task_binding_send(uint8_t cnt, uint32_t timestamp)
{
/* Snapshot-sequence semantics: the window SN is consumed before
* contending for the transport, so a skipped window burns it and
* the gap in the binding sequence counts skipped windows. */
uint32_t frame_sn = BLE_LOG_GET_TASK_BINDING_SN();
if (!BLE_LOG_CAS_ACQUIRE(&binding_trans->atomic_lock)) {
return false;
}
/* Acceptance load: pairs with the dedicated transport's lock-free
* recycle publication (pos=0, STORE_RELEASE(FREE)). */
if (BLE_LOG_ATOMIC_LOAD_ACQUIRE(binding_trans->state) !=
BLE_LOG_TRANS_STATE_FREE) {
BLE_LOG_CAS_RELEASE(&binding_trans->atomic_lock);
return false;
}
ble_log_frame_head_t frame_head = {
.length = (uint16_t)(sizeof(uint32_t) +
cnt * sizeof(ble_log_task_binding_t)),
.frame_meta = BLE_LOG_MAKE_FRAME_META(BLE_LOG_SRC_INTERNAL, frame_sn),
};
uint8_t *buf = binding_trans->buf;
BLE_LOG_MEMCPY(buf, &frame_head, sizeof(frame_head));
size_t pos = BLE_LOG_FRAME_HEAD_LEN;
BLE_LOG_MEMCPY(buf + pos, &timestamp, sizeof(timestamp));
pos += sizeof(timestamp);
for (uint8_t i = 0; i < cnt; i++) {
ble_log_task_binding_t binding = {
.int_src_code = BLE_LOG_INT_SRC_TASK_BINDING,
.task_id = i,
};
BLE_LOG_MEMCPY(binding.task_name, s_task_names[i],
BLE_LOG_TASK_NAME_LEN);
BLE_LOG_MEMCPY(buf + pos, &binding, sizeof(binding));
pos += sizeof(binding);
}
uint32_t checksum = ble_log_fast_checksum(
buf, BLE_LOG_FRAME_HEAD_LEN + frame_head.length);
BLE_LOG_MEMCPY(buf + BLE_LOG_FRAME_HEAD_LEN + frame_head.length,
&checksum, sizeof(checksum));
binding_trans->pos = (uint16_t)(pos + BLE_LOG_FRAME_TAIL_LEN);
BLE_LOG_ATOMIC_STORE_RELAXED(binding_trans->state,
BLE_LOG_TRANS_STATE_SENDING);
BLE_LOG_CAS_RELEASE(&binding_trans->atomic_lock);
ble_log_rt_submit_trans(binding_trans);
return true;
}
void ble_log_task_bindings_publish(void)
{
if (!ble_log_ref_count_try_acquire(&s_registry_ref_count, &s_registry_inited)) {
return;
}
/* Empty registry: nothing to broadcast; no window attempt, no SN. */
uint8_t cnt = BLE_LOG_ATOMIC_LOAD_ACQUIRE(s_task_cnt);
if (cnt != 0) {
uint32_t timestamp = (uint32_t)esp_timer_get_time();
(void)ble_log_task_binding_send(cnt, timestamp);
}
BLE_LOG_REF_COUNT_RELEASE(&s_registry_ref_count);
}
/* --------------------------- */
/* Module Lifetime */
/* --------------------------- */
bool ble_log_task_registry_init(void)
{
if (BLE_LOG_ATOMIC_LOAD_ACQUIRE(s_registry_inited)) {
return true;
}
/* Fresh epoch: empty registry, no broadcast sequence. init runs
* single-threaded (from ble_log_lbm_init), so the registry state and
* its lock are cleared by value. */
BLE_LOG_MEMSET(s_task_names, 0, sizeof(s_task_names));
BLE_LOG_ATOMIC_STORE_RELEASE(s_task_cnt, 0);
s_task_reg_lock = 0;
g_task_binding_sn = 0;
if (!ble_log_prph_trans_init(&binding_trans, BLE_LOG_TASK_BINDING_TRANS_SIZE)) {
return false;
}
binding_trans->id = BLE_LOG_TRANS_ID_NONE;
binding_trans->owner_kind = BLE_LOG_TRANS_OWNER_INTERNAL;
BLE_LOG_ATOMIC_STORE_RELEASE(s_registry_inited, true);
return true;
}
void ble_log_task_registry_begin_deinit(void)
{
/* Closing gate: pairs with the seq_cst acquire in publish. */
BLE_LOG_ATOMIC_STORE_SEQ_CST(s_registry_inited, false);
while (!ble_log_ref_count_wait(&s_registry_ref_count, 0)) {
BLE_LOG_ASSERT(false);
}
}
void ble_log_task_registry_deinit(void)
{
ble_log_task_registry_begin_deinit();
ble_log_prph_trans_deinit(&binding_trans);
}
#if CONFIG_BLE_LOG_PRPH_TEST
/* Test-only: wipes the task registry so test cases stay order-independent.
* Call between cases, with no writers in flight. */
void ble_log_test_task_registry_reset(void)
{
if (BLE_LOG_CAS_ACQUIRE(&s_task_reg_lock)) {
BLE_LOG_ATOMIC_STORE_RELEASE(s_task_cnt, 0);
BLE_LOG_CAS_RELEASE(&s_task_reg_lock);
}
}
#endif
@@ -1,92 +0,0 @@
/*
* SPDX-FileCopyrightText: 2025-2026 Espressif Systems (Shanghai) CO LTD
*
* SPDX-License-Identifier: Apache-2.0
*/
/* ----------------------------------- */
/* BLE Log - Timestamp Synchronization */
/* ----------------------------------- */
/* INCLUDE */
#include "ble_log_ts.h"
/* VARIABLE */
BLE_LOG_STATIC BLE_LOG_DRAM_ATTR bool ts_inited = false;
BLE_LOG_STATIC BLE_LOG_DRAM_ATTR ble_log_ts_info_t *ts_info = NULL;
/* INTERFACE */
bool ble_log_ts_init(void)
{
if (ts_inited) {
return true;
}
/* Initialize toggle IO */
gpio_config_t sync_io_conf = {
.intr_type = GPIO_INTR_DISABLE,
.mode = GPIO_MODE_OUTPUT,
.pin_bit_mask = BIT64(CONFIG_BLE_LOG_SYNC_IO_NUM),
};
if (gpio_config(&sync_io_conf) != ESP_OK) {
goto exit;
}
/* Initialize sync data */
ts_info = (ble_log_ts_info_t *)BLE_LOG_MALLOC(sizeof(ble_log_ts_info_t));
if (!ts_info) {
goto exit;
}
BLE_LOG_MEMSET(ts_info, 0, sizeof(ble_log_ts_info_t));
ts_info->int_src_code = BLE_LOG_INT_SRC_TS;
ts_inited = true;
return true;
exit:
ble_log_ts_deinit();
return false;
}
void ble_log_ts_deinit(void)
{
ts_inited = false;
/* Release sync data */
if (ts_info) {
BLE_LOG_FREE(ts_info);
ts_info = NULL;
}
/* Release toggle IO */
gpio_reset_pin(CONFIG_BLE_LOG_SYNC_IO_NUM);
}
void ble_log_ts_info_update(ble_log_ts_info_t **info)
{
if (!ts_inited) {
return;
}
BLE_LOG_ENTER_CRITICAL();
ts_info->io_level = !ts_info->io_level;
gpio_set_level(CONFIG_BLE_LOG_SYNC_IO_NUM, ts_info->io_level);
ts_info->lc_ts = BLE_LOG_GET_LC_TS;
ts_info->esp_ts = esp_timer_get_time();
ts_info->os_ts = pdTICKS_TO_MS(xTaskGetTickCountFromISR());
BLE_LOG_EXIT_CRITICAL();
*info = ts_info;
}
void ble_log_ts_reset(bool status)
{
if (!ts_inited) {
return;
}
if (!status && !ts_info->io_level) {
gpio_set_level(CONFIG_BLE_LOG_SYNC_IO_NUM, 1);
}
ts_info->io_level = 0;
gpio_set_level(CONFIG_BLE_LOG_SYNC_IO_NUM, 0);
}
@@ -25,9 +25,8 @@ BLE_LOG_DRAM_ATTR portMUX_TYPE ble_log_spin_lock = portMUX_INITIALIZER_UNLOCKED;
BLE_LOG_IRAM_ATTR BLE_LOG_STATIC BLE_LOG_INLINE
uint32_t ror32(uint32_t word, uint32_t shift)
{
if (unlikely(shift == 0)) {
return word;
}
/* The mask folds shift == 0 into a zero left-shift amount, so the
* expression needs no shift == 0 guard. */
return (word >> shift) | (word << ((32 - shift) & 0x1F));
}
@@ -74,12 +73,12 @@ uint32_t ble_log_fast_checksum(const uint8_t *data, size_t len)
BLE_LOG_IRAM_ATTR
bool ble_log_ref_count_try_acquire(volatile uint32_t *ref_count,
const uint32_t *inited)
const uint32_t *gate)
{
/* The seq_cst increment/check pairs with deinit's seq_cst gate close
* before it waits for the reference count. */
/* The seq_cst increment/check pairs with a seq_cst gate close before the
* owner waits for the reference count. */
BLE_LOG_REF_COUNT_ACQUIRE_SEQ_CST(ref_count);
if (BLE_LOG_ATOMIC_LOAD_SEQ_CST(*inited)) {
if (BLE_LOG_ATOMIC_LOAD_SEQ_CST(*gate)) {
return true;
}
BLE_LOG_REF_COUNT_RELEASE(ref_count);
@@ -98,3 +97,13 @@ bool ble_log_ref_count_wait(volatile uint32_t *ref_count, uint32_t max_ref_count
}
return true;
}
BLE_LOG_IRAM_ATTR
void ble_log_atomic_update_peak(volatile uint32_t *peak, uint32_t value)
{
uint32_t current = BLE_LOG_ATOMIC_LOAD_RELAXED(*peak);
while (value > current &&
!__atomic_compare_exchange_n(peak, &current, value, true,
__ATOMIC_RELAXED, __ATOMIC_RELAXED)) {
}
}
@@ -1,272 +0,0 @@
/*
* SPDX-FileCopyrightText: 2025-2026 Espressif Systems (Shanghai) CO LTD
*
* SPDX-License-Identifier: Apache-2.0
*/
#ifndef __BLE_LOG_LBM_H__
#define __BLE_LOG_LBM_H__
/* --------------------------------------- */
/* BLE Log - Log Buffer Management */
/* --------------------------------------- */
/* ---------------- */
/* Includes */
/* ---------------- */
#include "ble_log.h"
#include "ble_log_prph.h"
#include "freertos/FreeRTOS.h"
#if defined(CONFIG_BLE_LOG_PRPH_UART_DMA) && (CONFIG_BLE_LOG_PRPH_UART_DMA_PORT == 0)
#define BLE_LOG_UART_REDIR_ENABLED (1)
#else
#define BLE_LOG_UART_REDIR_ENABLED (0)
#endif
#include "freertos/semphr.h"
/* ------------------------- */
/* Log Frame Defines */
/* ------------------------- */
typedef struct {
uint16_t length;
uint32_t frame_meta;
} __attribute__((packed)) ble_log_frame_head_t;
#define BLE_LOG_FRAME_HEAD_LEN (sizeof(ble_log_frame_head_t))
#define BLE_LOG_FRAME_TAIL_LEN (sizeof(uint32_t))
#define BLE_LOG_FRAME_OVERHEAD (BLE_LOG_FRAME_HEAD_LEN + BLE_LOG_FRAME_TAIL_LEN)
#define BLE_LOG_MAKE_FRAME_META(src_code, sn) (((src_code) & 0xFF) | ((sn) << 8))
/* ---------------------------------- */
/* Log Buffer Manager Defines */
/* ---------------------------------- */
typedef enum {
BLE_LOG_LBM_LOCK_NONE,
BLE_LOG_LBM_LOCK_SPIN,
BLE_LOG_LBM_LOCK_ATOMIC,
BLE_LOG_LBM_LOCK_MUTEX,
} ble_log_lbm_lock_t;
typedef struct {
int trans_idx;
ble_log_prph_trans_t *trans[BLE_LOG_TRANS_BUF_CNT];
ble_log_lbm_lock_t lock_type;
union {
/* BLE_LOG_LBM_LOCK_NONE */
void *none;
/* BLE_LOG_LBM_LOCK_SPIN */
portMUX_TYPE spin_lock;
/* BLE_LOG_LBM_LOCK_ATOMIC */
volatile bool atomic_lock;
/* BLE_LOG_LBM_LOCK_MUTEX */
SemaphoreHandle_t mutex;
};
uint32_t trans_inflight;
uint32_t trans_inflight_peak;
} ble_log_lbm_t;
/* --------------------------------------- */
/* Log Buffer Manager Pool Defines */
/* --------------------------------------- */
enum {
#if CONFIG_BLE_LOG_LL_ENABLED
BLE_LOG_LBM_LL_TASK,
BLE_LOG_LBM_LL_HCI,
#endif /* CONFIG_BLE_LOG_LL_ENABLED */
BLE_LOG_LBM_LL_MAX,
};
enum {
BLE_LOG_LBM_SPIN_TASK = 0,
BLE_LOG_LBM_SPIN_ISR,
BLE_LOG_LBM_SPIN_MAX,
};
#define BLE_LOG_LBM_ATOMIC_TASK_CNT CONFIG_BLE_LOG_LBM_ATOMIC_LOCK_TASK_CNT
#define BLE_LOG_LBM_ATOMIC_ISR_CNT CONFIG_BLE_LOG_LBM_ATOMIC_LOCK_ISR_CNT
#define BLE_LOG_LBM_ATOMIC_CNT (BLE_LOG_LBM_ATOMIC_TASK_CNT +\
BLE_LOG_LBM_ATOMIC_ISR_CNT)
#define BLE_LOG_LBM_COMMON_CNT (BLE_LOG_LBM_ATOMIC_CNT + BLE_LOG_LBM_SPIN_MAX)
#define BLE_LOG_LBM_CNT (BLE_LOG_LBM_COMMON_CNT + BLE_LOG_LBM_LL_MAX)
/* Derived per-buffer size from user-configured total-per-LBM budget */
#define BLE_LOG_TRANS_SIZE (CONFIG_BLE_LOG_LBM_TRANS_BUF_SIZE / BLE_LOG_TRANS_BUF_CNT)
#define BLE_LOG_TRANS_LL_SIZE (CONFIG_BLE_LOG_LBM_LL_TRANS_BUF_SIZE / BLE_LOG_TRANS_BUF_CNT)
/* Unified queue depth derivation */
#define BLE_LOG_TRANS_POOL_CNT (BLE_LOG_LBM_CNT * BLE_LOG_TRANS_BUF_CNT)
#if BLE_LOG_UART_REDIR_ENABLED
#define BLE_LOG_TRANS_REDIR_CNT BLE_LOG_TRANS_BUF_CNT
#else
#define BLE_LOG_TRANS_REDIR_CNT (0)
#endif
#define BLE_LOG_TRANS_TOTAL_CNT (BLE_LOG_TRANS_POOL_CNT + BLE_LOG_TRANS_REDIR_CNT)
/* ------------------------------------------ */
/* Log Buffer Manager Context Defines */
/* ------------------------------------------ */
typedef struct {
union {
ble_log_lbm_t lbm_pool[BLE_LOG_LBM_CNT];
struct {
union {
ble_log_lbm_t lbm_common_pool[BLE_LOG_LBM_COMMON_CNT];
struct {
union {
ble_log_lbm_t spin_pool[BLE_LOG_LBM_SPIN_MAX];
struct {
ble_log_lbm_t spin_task;
ble_log_lbm_t spin_isr;
};
};
union {
ble_log_lbm_t atomic_pool[BLE_LOG_LBM_ATOMIC_CNT];
struct {
ble_log_lbm_t atomic_pool_task[BLE_LOG_LBM_ATOMIC_TASK_CNT];
ble_log_lbm_t atomic_pool_isr[BLE_LOG_LBM_ATOMIC_ISR_CNT];
};
};
};
};
union {
ble_log_lbm_t lbm_ll_pool[BLE_LOG_LBM_LL_MAX];
#if CONFIG_BLE_LOG_LL_ENABLED
struct {
ble_log_lbm_t lbm_ll_task;
ble_log_lbm_t lbm_ll_hci;
};
#endif /* CONFIG_BLE_LOG_LL_ENABLED */
};
};
};
} ble_log_lbm_ctx_t;
/* -------------------------------------------- */
/* Buffer Utilization Reporting Defines */
/* -------------------------------------------- */
typedef enum {
BLE_LOG_BUF_UTIL_POOL_COMMON_TASK = 0,
BLE_LOG_BUF_UTIL_POOL_COMMON_ISR = 1,
BLE_LOG_BUF_UTIL_POOL_LL = 2,
BLE_LOG_BUF_UTIL_POOL_REDIR = 3,
} ble_log_buf_util_pool_t;
typedef struct {
uint8_t int_src_code;
uint8_t lbm_id;
uint8_t trans_cnt;
uint8_t inflight_peak;
} __attribute__((packed)) ble_log_buf_util_t;
#define BLE_LOG_BUF_UTIL_MAKE_ID(pool, idx) (((pool) << 4) | ((idx) & 0x0F))
#define BLE_LOG_BUF_UTIL_GET_POOL(id) (((id) >> 4) & 0x0F)
#define BLE_LOG_BUF_UTIL_GET_INDEX(id) ((id) & 0x0F)
/* ---------------------------------------- */
/* Enhanced Statistics Data Defines */
/* ---------------------------------------- */
typedef struct {
uint8_t int_src_code;
uint8_t src_code;
uint32_t written_frame_cnt;
uint32_t lost_frame_cnt;
uint32_t written_bytes_cnt;
uint32_t lost_bytes_cnt;
} __attribute__((packed)) ble_log_enh_stat_t;
/* -------------------------------- */
/* Final Statistics Defines */
/* -------------------------------- */
typedef struct {
uint8_t src_code;
uint32_t written_frame_cnt;
uint32_t lost_frame_cnt;
uint32_t written_bytes_cnt;
uint32_t lost_bytes_cnt;
} __attribute__((packed)) ble_log_final_stat_entry_t;
typedef struct {
uint8_t int_src_code;
uint8_t src_cnt;
ble_log_final_stat_entry_t entries[BLE_LOG_SRC_MAX];
} __attribute__((packed)) ble_log_final_stat_t;
#define BLE_LOG_FINAL_STAT_LEN sizeof(ble_log_final_stat_t)
/* -------------------------------------- */
/* Log Statistics Manager Context */
/* -------------------------------------- */
typedef struct {
uint32_t frame_sn;
/* Aligned live counters — updated by ble_log_stat_mgr_update(),
* snapshot by ble_log_write_enh_stat(). Natural 4-byte alignment
* ensures each load/store compiles to a single l32i/s32i on
* Xtensa/RISC-V, so individual field access is atomic without locks.
* The packed ble_log_enh_stat_t wire format is built on the stack
* only when serializing to UART. */
uint32_t written_frame_cnt;
uint32_t lost_frame_cnt;
uint32_t written_bytes_cnt;
uint32_t lost_bytes_cnt;
} ble_log_stat_mgr_t;
#define BLE_LOG_GET_FRAME_SN(VAR) __atomic_fetch_add(VAR, 1, __ATOMIC_RELAXED)
/* -------------------------- */
/* Link Layer Defines */
/* -------------------------- */
#if CONFIG_BLE_LOG_LL_ENABLED
enum {
BLE_LOG_LL_FLAG_CONTINUE = 0,
BLE_LOG_LL_FLAG_END,
BLE_LOG_LL_FLAG_TASK,
BLE_LOG_LL_FLAG_ISR,
BLE_LOG_LL_FLAG_HCI,
BLE_LOG_LL_FLAG_RAW,
BLE_LOG_LL_FLAG_OMDATA,
BLE_LOG_LL_FLAG_HCI_UPSTREAM,
};
#endif /* CONFIG_BLE_LOG_LL_ENABLED */
/* ------------------------------- */
/* Compile-Time Guards */
/* ------------------------------- */
_Static_assert(CONFIG_BLE_LOG_LBM_TRANS_BUF_SIZE % BLE_LOG_TRANS_BUF_CNT == 0,
"Common LBM total buffer size must be a multiple of BLE_LOG_TRANS_BUF_CNT (4)");
#if CONFIG_BLE_LOG_LL_ENABLED
_Static_assert(CONFIG_BLE_LOG_LBM_LL_TRANS_BUF_SIZE % BLE_LOG_TRANS_BUF_CNT == 0,
"LL LBM total buffer size must be a multiple of BLE_LOG_TRANS_BUF_CNT (4)");
#endif
_Static_assert(CONFIG_BLE_LOG_LBM_TRANS_BUF_SIZE / BLE_LOG_TRANS_BUF_CNT >= BLE_LOG_FRAME_OVERHEAD,
"Common LBM per-buffer size too small for a single frame");
_Static_assert(BLE_LOG_TRANS_SIZE >= BLE_LOG_FINAL_STAT_LEN + sizeof(uint32_t) + BLE_LOG_FRAME_OVERHEAD,
"Common LBM per-buffer size too small for final statistics frame");
_Static_assert((BLE_LOG_TRANS_BUF_CNT & (BLE_LOG_TRANS_BUF_CNT - 1)) == 0,
"BLE_LOG_TRANS_BUF_CNT must be a power of 2");
_Static_assert(1 + BLE_LOG_LBM_ATOMIC_TASK_CNT <= 16,
"Common task pool exceeds lbm_id 4-bit index limit (max 15)");
_Static_assert(1 + BLE_LOG_LBM_ATOMIC_ISR_CNT <= 16,
"Common ISR pool exceeds lbm_id 4-bit index limit (max 15)");
_Static_assert(BLE_LOG_TRANS_BUF_CNT <= 255,
"BLE_LOG_TRANS_BUF_CNT must fit in uint8_t for ble_log_buf_util_t");
/* --------------------------- */
/* Internal Interfaces */
/* --------------------------- */
bool ble_log_lbm_init(void);
void ble_log_lbm_close(void);
void ble_log_lbm_deinit(void);
void ble_log_lbm_recycle_trans(ble_log_prph_trans_t *trans);
bool ble_log_write_internal(const uint8_t *addr, size_t len);
void ble_log_write_final_stat(void);
void ble_log_write_enh_stat(void);
void ble_log_write_buf_util(void);
#if BLE_LOG_UART_REDIR_ENABLED
void ble_log_lbm_stream_write(ble_log_lbm_t *lbm, ble_log_src_t src_code,
const uint8_t *data, size_t len);
void ble_log_lbm_stream_flush(ble_log_lbm_t *lbm, ble_log_src_t src_code);
ble_log_lbm_t *ble_log_prph_get_redir_lbm(void);
#endif
#endif /* __BLE_LOG_LBM_H__ */
@@ -0,0 +1,264 @@
/*
* SPDX-FileCopyrightText: 2026 Espressif Systems (Shanghai) CO LTD
*
* SPDX-License-Identifier: Apache-2.0
*/
#ifndef __BLE_LOG_LBM_V2_H__
#define __BLE_LOG_LBM_V2_H__
/* -------------------------------------------------- */
/* BLE Log - Unified Transport Pool (v8) */
/* -------------------------------------------------- */
/* Replaces the legacy multi-LBM design (ble_log_lbm.h) with one shared
* transport pool. Written as a new module so the legacy implementation
* stays untouched and reviewable as a pure addition. */
/* INCLUDE */
#include "ble_log.h"
#include "ble_log_prph.h"
#include "freertos/FreeRTOS.h"
#include "freertos/semphr.h"
/* ------------------------- */
/* Log Frame Defines */
/* ------------------------- */
typedef struct {
uint16_t length;
uint32_t frame_meta;
} __attribute__((packed)) ble_log_frame_head_t;
#define BLE_LOG_FRAME_HEAD_LEN (sizeof(ble_log_frame_head_t))
#define BLE_LOG_FRAME_TAIL_LEN (sizeof(uint32_t))
#define BLE_LOG_FRAME_OVERHEAD (BLE_LOG_FRAME_HEAD_LEN + BLE_LOG_FRAME_TAIL_LEN)
#define BLE_LOG_MAKE_FRAME_META(src, sn) \
(((src) & 0xffU) | (((sn) & 0x00ffffffU) << 8))
/* ------------------------------------- */
/* Unified Buffer Pool Defines */
/* ------------------------------------- */
#define BLE_LOG_POOL_TRANS_CNT CONFIG_BLE_LOG_POOL_TRANS_CNT
#define BLE_LOG_POOL_NON_YIELD_RESERVE_CNT CONFIG_BLE_LOG_POOL_NON_YIELD_RESERVE_CNT
#define BLE_LOG_POOL_SHARED_CNT (BLE_LOG_POOL_TRANS_CNT - BLE_LOG_POOL_NON_YIELD_RESERVE_CNT)
#define BLE_LOG_POOL_TRANS_SIZE CONFIG_BLE_LOG_POOL_TRANS_SIZE
#define BLE_LOG_TRANS_SIZE BLE_LOG_POOL_TRANS_SIZE
#define BLE_LOG_MAX_PAYLOAD_LEN (BLE_LOG_POOL_TRANS_SIZE - BLE_LOG_FRAME_OVERHEAD)
#define BLE_LOG_TRANS_INTERNAL_CNT (1)
/* Dedicated transport of the task-id registry binding broadcast. */
#define BLE_LOG_TRANS_TASK_BINDING_CNT (1)
#if BLE_LOG_UART_REDIR_ENABLED
#define BLE_LOG_TRANS_REDIR_CNT BLE_LOG_TRANS_BUF_CNT
#else
#define BLE_LOG_TRANS_REDIR_CNT (0)
#endif
#define BLE_LOG_TRANS_TOTAL_CNT \
(BLE_LOG_POOL_TRANS_CNT + BLE_LOG_TRANS_INTERNAL_CNT + \
BLE_LOG_TRANS_TASK_BINDING_CNT + BLE_LOG_TRANS_REDIR_CNT)
/* --------------------------------------- */
/* Protocol v8 Source ID Space */
/* --------------------------------------- */
/* The frozen public ble_log_src_t values are the on-wire and statistic
* source IDs: the frame source byte carries the bare enum value. */
/* Statistic slots in the Internal Snapshot: every public source that can
* produce core frames, i.e. CUSTOM through ENCODE. Snapshots share the
* Global SN but have no statistic slot; REDIR is a raw console stream. */
#define BLE_LOG_SRC_CORE_FIRST BLE_LOG_SRC_CUSTOM
#define BLE_LOG_SRC_CORE_COUNT (BLE_LOG_SRC_ENCODE - BLE_LOG_SRC_CORE_FIRST + 1)
/* ------------------------------------- */
/* UART Redirection Manager */
/* ------------------------------------- */
#if BLE_LOG_UART_REDIR_ENABLED
typedef struct {
ble_log_prph_trans_t *trans[BLE_LOG_TRANS_BUF_CNT];
SemaphoreHandle_t mutex;
int trans_idx;
/* The REDIR console stream keeps its own 24-bit frame sequence: it is
* not a log attempt, so it never consumes the Global SN; a gap counts
* a dropped console batch. Zeroed when the manager is created. */
volatile uint32_t frame_sn;
volatile uint32_t inflight;
volatile uint32_t inflight_peak;
} ble_log_redir_t;
#endif
/* -------------------------------- */
/* Compact Core Statistics */
/* -------------------------------- */
typedef struct {
uint32_t written_frame_cnt;
uint32_t lost_frame_cnt;
/* Successfully committed logical frame bytes, including head and tail,
* excluding DMA padding. Not a physical-TX acknowledgement. */
uint32_t written_bytes_cnt;
} __attribute__((packed)) ble_log_source_stat_t;
/* Runtime per-source counters. The aligned wrapper keeps the embedded
* packed counters word-aligned, so atomic updates stay single-instruction
* (amo/s32c1i) on both toolchains. */
typedef struct {
ble_log_source_stat_t counters;
} __attribute__((aligned(4))) ble_log_stat_mgr_t;
#define BLE_LOG_GET_FRAME_SN(VAR) BLE_LOG_ATOMIC_ADD_RELAXED(VAR, 1)
/* Core logs and INTERNAL snapshots share one 24-bit Global SN. Core logs
* consume it after entry validation and gate acceptance, before contention;
* failed log attempts leave gaps accounted for by lost_frame_cnt. Snapshots
* only consume it after acquiring their dedicated transport. Busy/skipped
* snapshots are not in core loss statistics and advance only the separate
* 24-bit anchor_count, never the Global SN.
* Task-binding broadcasts and REDIR retain independent header sequences.
* ble_log_init() resets every sequence; INIT starts a new receiver epoch.
* FLUSH resets interval statistics, but never the sequences or anchor count.
* Allocation order is not physical TX order; a snapshot is not a drain
* barrier. The wire SN is masked to 24 bits when frame_meta is packed. */
/* -------------------------------- */
/* Internal Snapshot Frame */
/* -------------------------------- */
/* Clock sample captured at one instant by the runtime periodic tick. */
typedef struct {
uint8_t int_src_code;
uint8_t io_level;
uint32_t lc_ts;
uint32_t esp_ts;
uint32_t os_ts;
} __attribute__((packed)) ble_log_ts_info_t;
#define BLE_LOG_SNAPSHOT_REASON_INIT BIT(0)
#define BLE_LOG_SNAPSHOT_REASON_PERIODIC BIT(1)
#define BLE_LOG_SNAPSHOT_REASON_FLUSH BIT(2)
#define BLE_LOG_SNAPSHOT_REASON_TS_VALID BIT(3)
typedef struct {
uint8_t int_src_code;
uint16_t reason_flags;
/* Snapshot attempts (INIT/PERIODIC/FLUSH), including skipped points.
* Little-endian low 24 bits; the runtime counter remains uint32_t. */
uint8_t anchor_count[3];
ble_log_version_info_t version_info;
/* Clock samples captured at the same instant, mirroring
* ble_log_ts_info_t (minus its int_src_code). */
struct {
uint8_t io_level;
uint32_t lc_ts; /* Link-layer clock; 0 when not available */
uint32_t esp_ts; /* esp_timer_get_time() */
uint32_t os_ts; /* FreeRTOS tick count in ms */
} __attribute__((packed)) ts;
/* Unified pool state at capture time. */
struct {
uint8_t trans_cnt;
uint8_t non_yield_reserve_cnt;
uint8_t inflight;
uint8_t inflight_peak;
} __attribute__((packed)) pool;
ble_log_source_stat_t stats[BLE_LOG_SRC_CORE_COUNT];
} __attribute__((packed)) ble_log_internal_snapshot_t;
#define BLE_LOG_INTERNAL_FRAME_LEN \
(BLE_LOG_FRAME_OVERHEAD + sizeof(uint32_t) + sizeof(ble_log_internal_snapshot_t))
#define BLE_LOG_INTERNAL_TRANS_SIZE \
((BLE_LOG_INTERNAL_FRAME_LEN + 3U) & ~3U)
/* -------------------------- */
/* Link Layer Defines */
/* -------------------------- */
#if CONFIG_BLE_LOG_LL_ENABLED
/* Numeric positions are an ABI with prebuilt controller libraries. */
enum {
BLE_LOG_LL_FLAG_CONTINUE = 0,
BLE_LOG_LL_FLAG_END = 1,
BLE_LOG_LL_FLAG_TASK = 2,
BLE_LOG_LL_FLAG_ISR = 3,
BLE_LOG_LL_FLAG_HCI = 4,
BLE_LOG_LL_FLAG_RAW = 5,
BLE_LOG_LL_FLAG_OMDATA = 6,
BLE_LOG_LL_FLAG_HCI_UPSTREAM = 7,
};
#endif
/* ------------------------------- */
/* Compile-Time Guards */
/* ------------------------------- */
_Static_assert(sizeof(ble_log_frame_head_t) == 6,
"Unexpected BLE Log frame header size");
_Static_assert(BLE_LOG_POOL_TRANS_CNT >= 2 && BLE_LOG_POOL_TRANS_CNT <= 32,
"BLE_LOG_POOL_TRANS_CNT must be within [2, 32]");
_Static_assert(BLE_LOG_POOL_NON_YIELD_RESERVE_CNT > 0 &&
BLE_LOG_POOL_NON_YIELD_RESERVE_CNT < BLE_LOG_POOL_TRANS_CNT,
"Non-yield reserve must leave at least one shared transport");
_Static_assert(BLE_LOG_POOL_TRANS_SIZE >= BLE_LOG_FRAME_OVERHEAD + sizeof(uint32_t),
"BLE_LOG_POOL_TRANS_SIZE is too small for a timestamped frame");
_Static_assert(BLE_LOG_POOL_TRANS_SIZE <= UINT16_MAX,
"BLE_LOG_POOL_TRANS_SIZE exceeds the transport size field");
_Static_assert(BLE_LOG_POOL_TRANS_SIZE <= 10240,
"BLE_LOG_POOL_TRANS_SIZE exceeds the peripheral transfer limit");
#if CONFIG_BLE_LOG_PRPH_SPI_MASTER_DMA || CONFIG_BLE_LOG_PRPH_SPI_MASTER_HD
_Static_assert((BLE_LOG_POOL_TRANS_SIZE & 3U) == 0,
"SPI BLE Log transport size must be four-byte aligned");
#endif
_Static_assert(sizeof(ble_log_version_info_t) == 58,
"Unexpected BLE Log version information size");
_Static_assert(sizeof(ble_log_source_stat_t) == 12,
"Unexpected BLE Log source statistic size");
_Static_assert(offsetof(ble_log_stat_mgr_t, counters) == 0 &&
sizeof(ble_log_stat_mgr_t) == 12,
"stat manager layout must keep the counters word-aligned");
_Static_assert(sizeof(ble_log_internal_snapshot_t) == 165,
"Unexpected BLE Log Internal Snapshot size");
_Static_assert(BLE_LOG_INTERNAL_FRAME_LEN == 179,
"Unexpected BLE Log Internal frame size");
_Static_assert(BLE_LOG_INTERNAL_TRANS_SIZE >= BLE_LOG_INTERNAL_FRAME_LEN,
"Internal transport is too small");
_Static_assert((BLE_LOG_TRANS_BUF_CNT & (BLE_LOG_TRANS_BUF_CNT - 1)) == 0,
"BLE_LOG_TRANS_BUF_CNT must be a power of two");
/* --------------------------- */
/* Internal Interfaces */
/* --------------------------- */
bool ble_log_lbm_init(void);
void ble_log_lbm_begin_deinit(void);
void ble_log_lbm_deinit(void);
bool ble_log_lbm_is_enabled(void);
/* Best-effort system flush, gated by LBM lifetime rather than producers. */
void ble_log_lbm_flush_open_trans(void);
/* Deinit drain: seal every OPEN transport and dispatch it to the runtime
* queue. Contract: called after ble_log_lbm_begin_deinit() (producer gate
* closed, writers drained) and before ble_log_rt_deinit(); every transport
* lock is then uncontended. The peripheral deinit wait completes the
* delivery of the dispatched buffers. */
void ble_log_lbm_drain_open_trans(void);
void ble_log_lbm_recycle_trans(ble_log_prph_trans_t *trans);
/* System output: gated by the LBM lifetime, not ble_log_enable(). A false
* wait_for_transport makes a busy dedicated transport a lossy fast path. */
bool ble_log_internal_snapshot(uint16_t reason_flags,
const ble_log_ts_info_t *ts_info,
bool wait_for_transport);
/* The task-id registry (protocol v8 attribution) lives in its own module:
* ble_log_task_registry.c/h, like the UART redirection writer. */
/* Claim/commit: the public ble_log_src_t is accepted for API stability, but
* only BLE_LOG_SRC_ENCODE is supported; its frames are stamped with the
* ENCODE source ID on the wire. wait_for_transport=false turns a busy pool
* into a lossy fast path (NULL, as in a non-yieldable context) instead of
* waiting. true requests backpressure in ordinary yieldable tasks; the
* shared ESP Timer task and non-yieldable contexts never wait, regardless
* of the requested policy. */
uint8_t *ble_log_claim(ble_log_src_t src_code, size_t max_len,
uint32_t *handle, bool wait_for_transport);
void ble_log_commit(uint32_t handle, size_t actual_len);
#if BLE_LOG_UART_REDIR_ENABLED
ble_log_redir_t *ble_log_prph_get_redir_lbm(void);
#endif
#endif /* __BLE_LOG_LBM_V2_H__ */
@@ -10,32 +10,68 @@
/* BLE Log - Peripheral Interface */
/* ------------------------------ */
/* INCLUDE */
#include "ble_log_util.h"
/* TYPEDEF */
#if defined(CONFIG_BLE_LOG_PRPH_UART_DMA) && (CONFIG_BLE_LOG_PRPH_UART_DMA_PORT == 0)
#define BLE_LOG_UART_REDIR_ENABLED (1)
#else
#define BLE_LOG_UART_REDIR_ENABLED (0)
#endif
typedef enum {
BLE_LOG_TRANS_STATE_FREE = 0,
BLE_LOG_TRANS_STATE_OPEN,
BLE_LOG_TRANS_STATE_CLAIMED,
BLE_LOG_TRANS_STATE_SENDING,
} ble_log_trans_state_t;
typedef enum {
BLE_LOG_TRANS_OWNER_POOL = 0,
BLE_LOG_TRANS_OWNER_INTERNAL,
BLE_LOG_TRANS_OWNER_REDIR,
} ble_log_trans_owner_t;
#define BLE_LOG_TRANS_ID_NONE (0xff)
typedef struct {
volatile uint32_t prph_owned;
/* Transport lifecycle ownership, shared with the runtime dispatch and
* the peripheral tx-done recycle. Claim/commit bookkeeping deliberately
* lives in the pool (ble_log_lbm_v2.c), not here. */
volatile ble_log_atomic_lock_t atomic_lock;
volatile uint8_t state;
uint8_t id;
uint8_t owner_kind;
/* Lazy flush marker, pool-owned: set by the periodic flusher (without
* holding atomic_lock) when the transport was busy at flush time; the
* next claim that takes the lock seals the buffered frames first.
* Cleared by seal_and_send and on recycle, but a delayed flusher may
* store true afterwards. Such a stale hint permits an extra partial
* seal in the next lifecycle, never sending a writer-owned buffer. */
volatile uint8_t pending_seal;
uint8_t *buf;
uint16_t size;
uint16_t pos;
/* Peripheral implementation specific context */
/* Peripheral implementation specific context. */
void *ctx;
/* Opaque back-reference to owning LBM, set once at init */
void *owner;
} ble_log_prph_trans_t;
#define BLE_LOG_TRANS_FREE_SPACE(trans) ((trans)->size - (trans)->pos)
#define BLE_LOG_TRANS_BUF_CNT (4)
/* INTERFACE */
bool ble_log_prph_init(size_t trans_cnt);
void ble_log_prph_deinit(void);
/* Allocates a transport whose storage is zeroed (every field except size
* starts at its zero value: state FREE, owner POOL, lock and pending_seal
* clear). Callers only need to set the non-zero identity fields. */
bool ble_log_prph_trans_init(ble_log_prph_trans_t **trans, size_t trans_size);
void ble_log_prph_trans_deinit(ble_log_prph_trans_t **trans);
void ble_log_prph_send_trans(ble_log_prph_trans_t *trans);
#if BLE_LOG_UART_REDIR_ENABLED
bool ble_log_prph_flush(void);
void ble_log_prph_reset_util_counters(void);
#endif
#endif /* __BLE_LOG_PRPH_H__ */
@@ -0,0 +1,21 @@
/*
* SPDX-FileCopyrightText: 2025-2026 Espressif Systems (Shanghai) CO LTD
*
* SPDX-License-Identifier: Apache-2.0
*/
#ifndef __BLE_LOG_REDIR_H__
#define __BLE_LOG_REDIR_H__
/* ---------------------------------------------- */
/* BLE Log - UART Redirection Stream API */
/* ---------------------------------------------- */
#include "ble_log_lbm_v2.h"
#if BLE_LOG_UART_REDIR_ENABLED
void ble_log_lbm_stream_write(ble_log_redir_t *redir, ble_log_src_t src_code,
const uint8_t *data, size_t len);
void ble_log_lbm_stream_flush(ble_log_redir_t *redir, ble_log_src_t src_code);
#endif /* BLE_LOG_UART_REDIR_ENABLED */
#endif /* __BLE_LOG_REDIR_H__ */
@@ -12,7 +12,7 @@
/* INCLUDE */
#include "ble_log_prph.h"
#include "ble_log_ts.h"
#include "ble_log_lbm_v2.h"
#include "freertos/FreeRTOS.h"
#include "freertos/task.h"
@@ -24,8 +24,16 @@
/* INTERFACE */
bool ble_log_rt_init(void);
/* Starts the always-on periodic path after the epoch INIT frame is queued. */
bool ble_log_rt_start_periodic(void);
void ble_log_rt_deinit(void);
bool ble_log_rt_drain(void);
void ble_log_rt_submit_trans(ble_log_prph_trans_t *trans);
/* Samples the link-layer, ESP and OS clocks at one instant. toggle_io allows
* the periodic path to toggle the sync IO when runtime IO toggling is enabled;
* one-shot snapshots (INIT/FLUSH) always pass false and leave the IO edge
* sequence untouched. io_level always reports the physical IO level. */
void ble_log_rt_ts_sample(ble_log_ts_info_t *info, bool toggle_io);
#endif /* __BLE_LOG_RT_H__ */
@@ -0,0 +1,87 @@
/*
* SPDX-FileCopyrightText: 2026 Espressif Systems (Shanghai) CO LTD
*
* SPDX-License-Identifier: Apache-2.0
*/
#ifndef __BLE_LOG_TASK_REGISTRY_H__
#define __BLE_LOG_TASK_REGISTRY_H__
/* ------------------------------------ */
/* BLE Log - Task-id Registry */
/* ------------------------------------ */
/* Self-contained module (one .c/.h pair, like the UART redirection
* writer): owns the name-to-id registry, its broadcast sequence and its
* dedicated transport, so it never contends with the internal snapshot
* transport or the pool. */
/* INCLUDE */
#include "ble_log_lbm_v2.h"
/* ------------------------- */
/* Wire Format (v8) */
/* ------------------------- */
/* Writer attribution: every ENCODE record names the task that formatted
* it (one byte after the record source); the registry maps task names to
* stable ids. The name width is a wire property of the binding record
* below. */
#define BLE_LOG_TASK_ID_UNKNOWN UINT8_C(0xff)
#define BLE_LOG_TASK_NAME_LEN (16U)
/* The binding record inside an INTERNAL frame: every periodic window
* broadcasts one frame that packs one record per registered entry, in id
* order. The name is NUL-padded to the registry width plus one byte, so
* a decoder can bind the id in place even when the task name fills the
* whole field. */
typedef struct {
uint8_t int_src_code;
uint8_t task_id;
uint8_t task_name[BLE_LOG_TASK_NAME_LEN + 1];
} __attribute__((packed)) ble_log_task_binding_t;
/* One binding frame must fit the dedicated transport in a single frame:
* one submit per window, and the transport is recycled only when the
* peripheral has read it. */
#define BLE_LOG_TASK_BINDING_FRAME_LEN \
(BLE_LOG_FRAME_OVERHEAD + sizeof(uint32_t) + \
CONFIG_BLE_LOG_TASK_ID_MAX * sizeof(ble_log_task_binding_t))
/* Word-aligned by construction (SPI builds require aligned transfers). */
#define BLE_LOG_TASK_BINDING_TRANS_SIZE \
((BLE_LOG_TASK_BINDING_FRAME_LEN + 3U) & ~3U)
_Static_assert(sizeof(ble_log_task_binding_t) == 19,
"Unexpected task-binding record layout");
/* --------------------------- */
/* Internal Interfaces */
/* --------------------------- */
/* Module lifetime, driven by the LBM layer (ble_log_lbm_init/deinit):
* init allocates the dedicated transport and wipes the registry and its
* sequence for a fresh epoch; begin_deinit closes the gate and waits for
* in-flight publishes; deinit frees the transport. */
bool ble_log_task_registry_init(void);
void ble_log_task_registry_begin_deinit(void);
void ble_log_task_registry_deinit(void);
/* Resolves the calling task's name to its stable registry id, registering
* the name on a miss. ISR-safe: an ISR caller reads only (a miss returns
* the unknown id). Every ENCODE record must resolve before its claim so
* the registry already holds the id the record carries. */
uint8_t ble_log_task_id_current(void);
/* Periodic window output: broadcasts one INTERNAL frame packing one
* fixed-layout binding record per registered entry, in id order, on the
* dedicated registry transport. Runs on the shared ESP timer task and
* must never block: a busy transport (previous broadcast still in DMA)
* skips this window and the next one rebroadcasts. Best-effort control
* traffic, never counted in the per-source written/lost stats, and
* carried on its own sequence (see ble_log_task_registry.c) so a skipped
* window cannot look like a lost snapshot. */
void ble_log_task_bindings_publish(void);
#if CONFIG_BLE_LOG_PRPH_TEST
/* Test-only: wipes the task registry so test cases stay order-independent.
* Call between cases, with no writers in flight. */
void ble_log_test_task_registry_reset(void);
#endif
#endif /* __BLE_LOG_TASK_REGISTRY_H__ */
@@ -1,58 +0,0 @@
/*
* SPDX-FileCopyrightText: 2025 Espressif Systems (Shanghai) CO LTD
*
* SPDX-License-Identifier: Apache-2.0
*/
#ifndef __BLE_LOG_TS_H__
#define __BLE_LOG_TS_H__
/* ----------------------------------- */
/* BLE Log - Timestamp Synchronization */
/* ----------------------------------- */
/* INCLUDE */
#include "ble_log_util.h"
#include "freertos/FreeRTOS.h"
#include "freertos/task.h"
#include "esp_timer.h"
#include "driver/gpio.h"
/* MACRO */
#if CONFIG_BLE_LOG_LL_ENABLED
/* ESP BLE Controller Gen 2 */
#if defined(CONFIG_IDF_TARGET_ESP32H2) || defined(CONFIG_IDF_TARGET_ESP32C6) || defined(CONFIG_IDF_TARGET_ESP32C5) ||\
defined(CONFIG_IDF_TARGET_ESP32C61) || defined(CONFIG_IDF_TARGET_ESP32H21) || defined(CONFIG_IDF_TARGET_ESP32H4)
extern uint32_t r_ble_lll_timer_current_tick_get(void);
#define BLE_LOG_GET_LC_TS r_ble_lll_timer_current_tick_get()
/* ESP BLE Controller Gen 1 */
#elif defined(CONFIG_IDF_TARGET_ESP32C2)
extern uint32_t r_os_cputime_get32(void);
#define BLE_LOG_GET_LC_TS r_os_cputime_get32()
/* Legacy BLE Controller */
#elif defined(CONFIG_IDF_TARGET_ESP32C3) || defined(CONFIG_IDF_TARGET_ESP32S3)
extern uint32_t lld_read_clock_us(void);
#define BLE_LOG_GET_LC_TS lld_read_clock_us()
#else /* Other targets */
#define BLE_LOG_GET_LC_TS 0
#endif /* BLE targets */
#else /* !CONFIG_BLE_LOG_LL_ENABLED */
#define BLE_LOG_GET_LC_TS 0
#endif /* CONFIG_BLE_LOG_LL_ENABLED */
/* TYPEDEF */
typedef struct {
uint8_t int_src_code;
uint8_t io_level;
uint32_t lc_ts;
uint32_t esp_ts;
uint32_t os_ts;
} __attribute__((packed)) ble_log_ts_info_t;
/* INTERFACE */
bool ble_log_ts_init(void);
void ble_log_ts_deinit(void);
void ble_log_ts_info_update(ble_log_ts_info_t **ts_info);
void ble_log_ts_reset(bool status);
#endif /* __BLE_LOG_TS_H__ */
@@ -27,9 +27,11 @@
#define BLE_LOG_ATOMIC_LOAD_RELAXED(VAR) __atomic_load_n(&(VAR), __ATOMIC_RELAXED)
#define BLE_LOG_ATOMIC_STORE_RELEASE(VAR, VALUE) __atomic_store_n(&(VAR), (VALUE), __ATOMIC_RELEASE)
#define BLE_LOG_ATOMIC_STORE_RELAXED(VAR, VALUE) __atomic_store_n(&(VAR), (VALUE), __ATOMIC_RELAXED)
#define BLE_LOG_ATOMIC_ADD_RELAXED(VAR, VALUE) __atomic_fetch_add(&(VAR), (VALUE), __ATOMIC_RELAXED)
typedef uint32_t ble_log_atomic_lock_t;
/* Reference counting macros */
#define BLE_LOG_REF_COUNT_ACQUIRE(VAR) __atomic_fetch_add(VAR, 1, __ATOMIC_ACQUIRE)
#define BLE_LOG_REF_COUNT_RELEASE(VAR) __atomic_fetch_sub(VAR, 1, __ATOMIC_RELEASE)
/* Closing gate: pairs an inited-flag store with a reference-count load (and
* vice versa) at seq_cst so deinit and a submitter cannot both observe the
@@ -76,22 +78,14 @@ extern void esp_panic_handler_feed_wdts(void);
#define BLE_LOG_FEED_WDT() esp_panic_handler_feed_wdts()
/* INLINE */
BLE_LOG_IRAM_ATTR static inline
bool ble_log_cas_acquire(volatile bool *cas_lock)
{
bool expected = false;
return __atomic_compare_exchange_n(
cas_lock, &expected, true, false, __ATOMIC_ACQUIRE, __ATOMIC_RELAXED
);
}
/* Compare-and-swap lock as macros: single-instruction acquire/release used
* from several IRAM sites; a function would add an IRAM call site each. */
#define BLE_LOG_CAS_ACQUIRE(cas_lock) \
(__atomic_exchange_n((cas_lock), 1, __ATOMIC_ACQUIRE) == 0)
#define BLE_LOG_CAS_RELEASE(cas_lock) \
__atomic_store_n((cas_lock), 0, __ATOMIC_RELEASE)
BLE_LOG_IRAM_ATTR static inline
void ble_log_cas_release(volatile bool *cas_lock)
{
__atomic_store_n(cas_lock, false, __ATOMIC_RELEASE);
}
#define BLE_LOG_VERSION (6)
#define BLE_LOG_VERSION (8)
#define BLE_LOG_IDF_COMMIT_LEN (12)
/* Lib commit hashes are at most 10 hex chars; zero-padded when shorter */
#define BLE_LOG_LIB_COMMIT_LEN (10)
@@ -106,6 +100,10 @@ typedef enum {
BLE_LOG_INT_SRC_BUF_UTIL,
BLE_LOG_INT_SRC_FINAL_STAT,
BLE_LOG_INT_SRC_VERSION_INFO,
BLE_LOG_INT_SRC_SNAPSHOT,
/* protocol v8: periodic task-id binding broadcast; its frames carry a
* sequence of their own (a gap counts a skipped broadcast window). */
BLE_LOG_INT_SRC_TASK_BINDING,
BLE_LOG_INT_SRC_MAX,
} ble_log_int_src_t;
@@ -131,9 +129,14 @@ uint32_t ble_log_fast_checksum(const uint8_t *data, size_t len);
/* Acquire a lifetime reference only while the closing gate remains open. */
bool ble_log_ref_count_try_acquire(volatile uint32_t *ref_count,
const uint32_t *inited);
const uint32_t *gate);
/* Task-context wait; returns false if the count stays above max for one second. */
bool ble_log_ref_count_wait(volatile uint32_t *ref_count, uint32_t max_ref_count);
/* Monotonic-peak publish: stores value into *peak only when it exceeds the
* current peak. Relaxed atomics are enough - a lost race can only leave the
* recorded peak below a transient maximum, and peaks are diagnostics. */
void ble_log_atomic_update_peak(volatile uint32_t *peak, uint32_t value);
#endif /* __BLE_LOG_UTIL_H__ */
@@ -9,7 +9,7 @@
/* INCLUDE */
#include "ble_log_prph_dummy.h"
#include "ble_log_lbm.h"
#include "ble_log_lbm_v2.h"
/* INTERFACE */
bool ble_log_prph_init(size_t trans_cnt)
@@ -82,11 +82,10 @@ void ble_log_prph_trans_deinit(ble_log_prph_trans_t **trans)
}
/* Dummy transport has no DMA/hardware -- recycle the buffer immediately
* so that ble_log_lbm_get_trans() can reuse it and ble_log_flush() does
* not hang waiting for prph_owned to clear. Real peripherals (UART DMA,
* so that the pool can reuse it and ble_log_flush() does not hang waiting
* for it to drain. Real peripherals (UART DMA,
* SPI DMA) do the same work inside their asynchronous tx_done callbacks. */
void ble_log_prph_send_trans(ble_log_prph_trans_t *trans)
{
trans->pos = 0;
ble_log_lbm_recycle_trans(trans);
}
@@ -10,7 +10,7 @@
/* INCLUDE */
#include "ble_log_prph_spi_master_dma.h"
#include "ble_log_prph_spi_common.h"
#include "ble_log_lbm.h"
#include "ble_log_lbm_v2.h"
#include "esp_timer.h"
@@ -26,6 +26,7 @@
/* VARIABLE */
BLE_LOG_STATIC bool prph_inited = false;
BLE_LOG_STATIC bool bus_inited = false;
BLE_LOG_STATIC spi_device_handle_t dev_handle = NULL;
BLE_LOG_STATIC BLE_LOG_DRAM_ATTR uint32_t last_tx_done_ts = 0;
@@ -37,16 +38,16 @@ BLE_LOG_STATIC void spi_master_dma_pre_tx_cb(spi_transaction_t *spi_trans);
BLE_LOG_SPI_MASTER_DMA_CB_ATTR BLE_LOG_STATIC void spi_master_dma_tx_done_cb(spi_transaction_t *spi_trans)
{
/* SPI slave performance issue workaround */
last_tx_done_ts = esp_timer_get_time();
last_tx_done_ts = (uint32_t)esp_timer_get_time();
/* Recycle transport */
ble_log_prph_trans_t *trans = (ble_log_prph_trans_t *)(spi_trans->user);
trans->pos = 0;
ble_log_lbm_recycle_trans(trans);
}
BLE_LOG_SPI_MASTER_DMA_CB_ATTR BLE_LOG_STATIC void spi_master_dma_pre_tx_cb(spi_transaction_t *spi_trans)
{
(void)spi_trans;
/* SPI slave performance issue workaround */
while ((esp_timer_get_time() - last_tx_done_ts) < BLE_LOG_SPI_TRANS_ITVL_MIN_US) {}
}
@@ -74,6 +75,7 @@ bool ble_log_prph_init(size_t trans_cnt)
if (spi_bus_initialize(BLE_LOG_SPI_BUS, &bus_config, SPI_DMA_CH_AUTO) != ESP_OK) {
goto exit;
}
bus_inited = true;
spi_device_interface_config_t dev_config = {
.clock_speed_hz = SPI_MASTER_FREQ_20M,
@@ -108,8 +110,10 @@ void ble_log_prph_deinit(void)
dev_handle = NULL;
}
/* Note: We don't care if the bus has been inited or not */
spi_bus_free(BLE_LOG_SPI_BUS);
if (bus_inited) {
spi_bus_free(BLE_LOG_SPI_BUS);
bus_inited = false;
}
}
bool ble_log_prph_trans_init(ble_log_prph_trans_t **trans, size_t trans_size)
@@ -10,7 +10,7 @@
/* INCLUDE */
#include "ble_log_prph_spi_master_hd.h"
#include "ble_log_prph_spi_common.h"
#include "ble_log_lbm.h"
#include "ble_log_lbm_v2.h"
#include "hal/spi_ll.h"
#include "hal/spi_types.h"
@@ -44,7 +44,6 @@ BLE_LOG_SPI_MASTER_HD_CB_ATTR BLE_LOG_STATIC void spi_master_hd_tx_done_cb(spi_t
}
}
ctx->trans->pos = 0;
ble_log_lbm_recycle_trans(ctx->trans);
}
@@ -219,9 +218,7 @@ BLE_LOG_IRAM_ATTR void ble_log_prph_send_trans(ble_log_prph_trans_t *trans)
if (spi_device_queue_trans(dev_handle, &ctx->end, 0) != ESP_OK) {
uint8_t old_status = __atomic_fetch_or(&ctx->status, BLE_LOG_SPI_HD_END_QUEUE_FAILED, __ATOMIC_ACQ_REL);
if (old_status & BLE_LOG_SPI_HD_DATA_DONE) {
/* Data already on the wire: drop it from the buffer so the next
* flush does not re-send these bytes (recycle keeps pos on purpose) */
trans->pos = 0;
/* Data is already on the wire; recycle it without re-sending. */
ble_log_lbm_recycle_trans(trans);
}
}
@@ -9,7 +9,7 @@
/* INCLUDE */
#include "ble_log_prph_test.h"
#include "ble_log_lbm.h"
#include "ble_log_lbm_v2.h"
#include "esp_timer.h"
#include "freertos/queue.h"
#include "freertos/semphr.h"
@@ -155,7 +155,6 @@ void ble_log_prph_send_trans(ble_log_prph_trans_t *trans)
uint32_t idx = __atomic_load_n(&s_auto_recycle_idx, __ATOMIC_ACQUIRE);
ble_log_prph_test_hook_reg_t reg = s_auto_recycle_slots[idx & 1];
if (reg.hook) {
trans->pos = 0;
ble_log_lbm_recycle_trans(trans);
reg.hook(reg.ctx);
__atomic_fetch_sub(&s_auto_recycle_busy, 1, __ATOMIC_RELEASE);
@@ -164,7 +163,6 @@ void ble_log_prph_send_trans(ble_log_prph_trans_t *trans)
__atomic_fetch_sub(&s_auto_recycle_busy, 1, __ATOMIC_RELEASE);
if (xQueueSend(s_pending_trans, &trans, 0) != pdTRUE) {
trans->pos = 0;
ble_log_lbm_recycle_trans(trans);
BLE_LOG_ASSERT(false);
}
@@ -217,7 +215,6 @@ size_t ble_log_prph_test_read(uint8_t *data, size_t len, TickType_t timeout,
if (delay_us > 0 &&
(esp_timer_start_once(s_tx_timer, (uint64_t)delay_us) != ESP_OK ||
xSemaphoreTake(s_tx_done, portMAX_DELAY) != pdTRUE)) {
trans->pos = 0;
ble_log_lbm_recycle_trans(trans);
BLE_LOG_ASSERT(false);
return 0;
@@ -233,7 +230,6 @@ size_t ble_log_prph_test_read(uint8_t *data, size_t len, TickType_t timeout,
}
size_t copied = len < trans->pos ? len : trans->pos;
BLE_LOG_MEMCPY(data, trans->buf, copied);
trans->pos = 0;
ble_log_lbm_recycle_trans(trans);
if (uxQueueMessagesWaiting(s_pending_trans) == 0) {
s_tx_deadline_us = 0;
@@ -11,7 +11,9 @@
/* INCLUDE */
#include "ble_log_prph_uart_dma.h"
#include "ble_log.h"
#include "ble_log_lbm.h"
#include "ble_log_lbm_v2.h"
#include "ble_log_redir.h"
#include "ble_log_rt.h"
#if BLE_LOG_PRPH_UART_DMA_REDIR
@@ -24,10 +26,11 @@
/* MACRO */
#define BLE_LOG_UART_MAX_TRANSFER_SIZE (10240)
#define BLE_LOG_UART_RX_BUF_SIZE (256)
/* ponytail: data burst disabled — UHCI enforces burst-size alignment (addr+len) on
/* ponytail: data burst disabled - UHCI enforces burst-size alignment (addr+len) on
* uhci_transmit() once GDMA weighted arbitration is enabled, and UART log bandwidth
* is baud-rate limited anyway, so burst buys nothing here */
#define BLE_LOG_UART_DMA_BURST_SIZE (1)
#define BLE_LOG_UART_FLUSH_TIMEOUT_TICKS pdMS_TO_TICKS(1000)
#if BLE_LOG_PRPH_UART_DMA_REDIR
#define BLE_LOG_UART_REDIR_BUF_SIZE (512)
#define BLE_LOG_UART_REDIR_FLUSH_PERIOD_US (1000 * 1000)
@@ -38,8 +41,9 @@ BLE_LOG_STATIC BLE_LOG_DRAM_ATTR bool prph_inited = false;
BLE_LOG_STATIC uhci_controller_handle_t dev_handle = NULL;
#if BLE_LOG_PRPH_UART_DMA_REDIR
BLE_LOG_STATIC bool uart_driver_inited = false;
BLE_LOG_STATIC ble_log_lbm_t *redir_lbm = NULL;
BLE_LOG_STATIC ble_log_redir_t *redir_lbm = NULL;
BLE_LOG_STATIC esp_timer_handle_t redir_flush_timer = NULL;
BLE_LOG_STATIC volatile uint32_t redir_writer_count = 0;
#endif /* BLE_LOG_PRPH_UART_DMA_REDIR */
/* PRIVATE FUNCTION DECLARATION */
@@ -56,20 +60,20 @@ BLE_LOG_IRAM_ATTR BLE_LOG_STATIC bool uart_dma_tx_done_cb(
/* Recycle transport */
ble_log_prph_trans_ctx_t *uart_trans_ctx = (ble_log_prph_trans_ctx_t *)(
(uint8_t *)edata->buffer - sizeof(ble_log_prph_trans_ctx_t)
);
(uint8_t *)edata->buffer - sizeof(ble_log_prph_trans_ctx_t)
);
ble_log_prph_trans_t *trans = uart_trans_ctx->trans;
trans->pos = 0;
ble_log_lbm_recycle_trans(trans);
return true;
}
#if BLE_LOG_PRPH_UART_DMA_REDIR
BLE_LOG_IRAM_ATTR BLE_LOG_STATIC void esp_timer_cb_flush_log(void *arg)
BLE_LOG_STATIC void esp_timer_cb_flush_log(void *arg)
{
(void)arg;
if (!prph_inited) {
/* Producer disable stops new writes, not periodic draining of old data. */
if (!BLE_LOG_ATOMIC_LOAD_ACQUIRE(prph_inited)) {
return;
}
@@ -87,7 +91,7 @@ BLE_LOG_IRAM_ATTR BLE_LOG_STATIC void esp_timer_cb_flush_log(void *arg)
bool ble_log_prph_init(size_t trans_cnt)
{
/* Avoid double init */
if (prph_inited) {
if (BLE_LOG_ATOMIC_LOAD_ACQUIRE(prph_inited)) {
return true;
}
@@ -99,8 +103,8 @@ bool ble_log_prph_init(size_t trans_cnt)
.stop_bits = UART_STOP_BITS_1,
};
if ((uart_param_config(CONFIG_BLE_LOG_PRPH_UART_DMA_PORT, &uart_config) != ESP_OK) ||
(uart_set_pin(CONFIG_BLE_LOG_PRPH_UART_DMA_PORT,
CONFIG_BLE_LOG_PRPH_UART_DMA_TX_IO_NUM, -1, -1, -1) != ESP_OK)) {
(uart_set_pin(CONFIG_BLE_LOG_PRPH_UART_DMA_PORT,
CONFIG_BLE_LOG_PRPH_UART_DMA_TX_IO_NUM, -1, -1, -1) != ESP_OK)) {
goto exit;
}
@@ -117,19 +121,18 @@ bool ble_log_prph_init(size_t trans_cnt)
.on_tx_trans_done = uart_dma_tx_done_cb,
};
if ((uhci_new_controller(&uhci_config, &dev_handle) != ESP_OK) ||
(uhci_register_event_callbacks(dev_handle, &uhci_cbs, NULL) != ESP_OK)) {
(uhci_register_event_callbacks(dev_handle, &uhci_cbs, NULL) != ESP_OK)) {
goto exit;
}
/* Redirection is required when utilizing UART port 0 */
/* Redirection is required when utilizing UART port 0 */
#if BLE_LOG_PRPH_UART_DMA_REDIR
/* Initialize a dedicated LBM for redirection */
redir_lbm = (ble_log_lbm_t *)BLE_LOG_MALLOC(sizeof(ble_log_lbm_t));
/* Initialize a dedicated redirection manager (separate from the pool) */
redir_lbm = (ble_log_redir_t *)BLE_LOG_MALLOC(sizeof(ble_log_redir_t));
if (!redir_lbm) {
goto exit;
}
BLE_LOG_MEMSET(redir_lbm, 0, sizeof(ble_log_lbm_t));
redir_lbm->lock_type = BLE_LOG_LBM_LOCK_MUTEX;
BLE_LOG_MEMSET(redir_lbm, 0, sizeof(ble_log_redir_t));
/* Transport initialization */
for (int i = 0; i < BLE_LOG_TRANS_BUF_CNT; i++) {
@@ -137,7 +140,9 @@ bool ble_log_prph_init(size_t trans_cnt)
BLE_LOG_UART_REDIR_BUF_SIZE)) {
goto exit;
}
redir_lbm->trans[i]->owner = (void *)redir_lbm;
/* Redirection transports are not part of the global pool. */
redir_lbm->trans[i]->id = BLE_LOG_TRANS_ID_NONE;
redir_lbm->trans[i]->owner_kind = BLE_LOG_TRANS_OWNER_REDIR;
}
/* Mutex initialization */
@@ -146,11 +151,13 @@ bool ble_log_prph_init(size_t trans_cnt)
goto exit;
}
/* Initialize UART driver for redirection */
/* Initialize UART driver for redirection. */
if (!uart_is_driver_installed(UART_NUM_0)) {
if (uart_driver_install(UART_NUM_0, BLE_LOG_UART_RX_BUF_SIZE, 0, 0, NULL, 0) == ESP_OK) {
uart_driver_inited = true;
if (uart_driver_install(UART_NUM_0, BLE_LOG_UART_RX_BUF_SIZE,
0, 0, NULL, 0) != ESP_OK) {
goto exit;
}
uart_driver_inited = true;
}
uart_vfs_dev_use_driver(UART_NUM_0);
@@ -158,15 +165,19 @@ bool ble_log_prph_init(size_t trans_cnt)
esp_timer_create_args_t timer_args = {
.callback = esp_timer_cb_flush_log,
.dispatch_method = ESP_TIMER_TASK,
.skip_unhandled_events = true,
};
if (esp_timer_create(&timer_args, &redir_flush_timer) != ESP_OK) {
goto exit;
}
#endif /* BLE_LOG_PRPH_UART_DMA_REDIR */
prph_inited = true;
BLE_LOG_ATOMIC_STORE_RELEASE(prph_inited, true);
#if BLE_LOG_PRPH_UART_DMA_REDIR
esp_timer_start_periodic(redir_flush_timer, BLE_LOG_UART_REDIR_FLUSH_PERIOD_US);
if (esp_timer_start_periodic(redir_flush_timer,
BLE_LOG_UART_REDIR_FLUSH_PERIOD_US) != ESP_OK) {
goto exit;
}
#endif /* BLE_LOG_PRPH_UART_DMA_REDIR */
return true;
@@ -178,27 +189,45 @@ exit:
void ble_log_prph_deinit(void)
{
prph_inited = false;
__atomic_store_n(&prph_inited, false, __ATOMIC_SEQ_CST);
#if BLE_LOG_PRPH_UART_DMA_REDIR
/* Release flush timer */
if (redir_flush_timer) {
esp_timer_stop(redir_flush_timer);
esp_timer_stop_blocking(redir_flush_timer, portMAX_DELAY);
esp_timer_delete(redir_flush_timer);
redir_flush_timer = NULL;
}
/* Delete UART driver if it's installed by current module */
if (uart_driver_inited) {
uart_driver_delete(UART_NUM_0);
while (__atomic_load_n(&redir_writer_count, __ATOMIC_SEQ_CST) > 0) {
vTaskDelay(1);
}
/* Release redirection LBM */
/* Flush redirection buffers before waiting for all submitted DMA. */
if (redir_lbm) {
if (redir_lbm->mutex) {
xSemaphoreTake(redir_lbm->mutex, portMAX_DELAY);
ble_log_lbm_stream_flush(redir_lbm, BLE_LOG_SRC_REDIR);
xSemaphoreGive(redir_lbm->mutex);
}
}
#endif /* BLE_LOG_PRPH_UART_DMA_REDIR */
if (dev_handle) {
uhci_wait_all_tx_transaction_done(dev_handle, portMAX_DELAY);
}
#if BLE_LOG_PRPH_UART_DMA_REDIR
/* Restore the VFS before deleting a driver installed by this module. */
if (uart_driver_inited) {
uart_vfs_dev_use_nonblocking(UART_NUM_0);
uart_driver_delete(UART_NUM_0);
uart_driver_inited = false;
}
/* Release redirection LBM only after DMA callbacks have completed. */
if (redir_lbm) {
if (redir_lbm->mutex) {
vSemaphoreDelete(redir_lbm->mutex);
}
@@ -214,7 +243,6 @@ void ble_log_prph_deinit(void)
#endif /* BLE_LOG_PRPH_UART_DMA_REDIR */
if (dev_handle) {
uhci_wait_all_tx_transaction_done(dev_handle, portMAX_DELAY);
uhci_del_controller(dev_handle);
dev_handle = NULL;
}
@@ -277,67 +305,105 @@ void ble_log_prph_trans_deinit(ble_log_prph_trans_t **trans)
BLE_LOG_IRAM_ATTR void ble_log_prph_send_trans(ble_log_prph_trans_t *trans)
{
if (uhci_transmit(dev_handle, trans->buf, trans->pos) != ESP_OK) {
/* The UHCI queue depth matches the transport count and each transport
* occupies at most one slot, so a full queue cannot occur here: this
* is a driver fault. The assert compiles out with NDEBUG; the recycle
* below still covers that case (no tx_done will fire on failure). */
BLE_LOG_ASSERT(false);
ble_log_lbm_recycle_trans(trans);
}
}
/* Redirection is required when utilizing UART port 0 */
#if BLE_LOG_PRPH_UART_DMA_REDIR
BLE_LOG_IRAM_ATTR BLE_LOG_STATIC
void ble_log_redir_uart_tx_chars(const char *src, size_t len)
BLE_LOG_STATIC
bool ble_log_redir_uart_tx_chars(const char *src, size_t len)
{
__atomic_add_fetch(&redir_writer_count, 1, __ATOMIC_SEQ_CST);
if (!__atomic_load_n(&prph_inited, __ATOMIC_SEQ_CST) ||
!ble_log_lbm_is_enabled()) {
__atomic_sub_fetch(&redir_writer_count, 1, __ATOMIC_SEQ_CST);
return false;
}
if (BLE_LOG_IN_ISR() || xTaskGetSchedulerState() == taskSCHEDULER_SUSPENDED) {
return;
__atomic_sub_fetch(&redir_writer_count, 1, __ATOMIC_SEQ_CST);
return true;
}
xSemaphoreTake(redir_lbm->mutex, portMAX_DELAY);
ble_log_lbm_stream_write(redir_lbm, BLE_LOG_SRC_REDIR,
(const uint8_t *)src, len);
(const uint8_t *)src, len);
xSemaphoreGive(redir_lbm->mutex);
__atomic_sub_fetch(&redir_writer_count, 1, __ATOMIC_SEQ_CST);
return true;
}
int __real_uart_tx_chars(uart_port_t uart_num, const char *buffer, uint32_t len);
int __wrap_uart_tx_chars(uart_port_t uart_num, const char *buffer, uint32_t len)
{
if (!prph_inited || (uart_num != UART_NUM_0)) {
if ((uart_num != UART_NUM_0) ||
!ble_log_redir_uart_tx_chars(buffer, len)) {
return __real_uart_tx_chars(uart_num, buffer, len);
}
ble_log_redir_uart_tx_chars(buffer, len);
return len;
}
int __real_uart_write_bytes(uart_port_t uart_num, const void *src, size_t size);
int __wrap_uart_write_bytes(uart_port_t uart_num, const void *src, size_t size)
{
if (!prph_inited || (uart_num != UART_NUM_0)) {
if ((uart_num != UART_NUM_0) ||
!ble_log_redir_uart_tx_chars(src, size)) {
return __real_uart_write_bytes(uart_num, src, size);
}
ble_log_redir_uart_tx_chars(src, size);
return size;
}
int __real_uart_write_bytes_with_break(uart_port_t uart_num, const void *src, size_t size, int brk_len);
int __wrap_uart_write_bytes_with_break(uart_port_t uart_num, const void *src, size_t size, int brk_len)
{
if (!prph_inited || (uart_num != UART_NUM_0)) {
if ((uart_num != UART_NUM_0) ||
!ble_log_redir_uart_tx_chars(src, size)) {
return __real_uart_write_bytes_with_break(uart_num, src, size, brk_len);
} else {
(void)brk_len;
return __wrap_uart_write_bytes(uart_num, src, size);
}
return size;
}
ble_log_lbm_t *ble_log_prph_get_redir_lbm(void)
BLE_LOG_IRAM_ATTR ble_log_redir_t *ble_log_prph_get_redir_lbm(void)
{
return redir_lbm;
}
#endif /* BLE_LOG_PRPH_UART_DMA_REDIR */
#if BLE_LOG_PRPH_UART_DMA_REDIR
bool ble_log_prph_flush(void)
{
while (__atomic_load_n(&redir_writer_count, __ATOMIC_SEQ_CST) > 0) {
vTaskDelay(1);
}
if (!redir_lbm) {
return true;
}
xSemaphoreTake(redir_lbm->mutex, portMAX_DELAY);
ble_log_lbm_stream_flush(redir_lbm, BLE_LOG_SRC_REDIR);
xSemaphoreGive(redir_lbm->mutex);
(void)ble_log_rt_drain();
TickType_t start_tick = xTaskGetTickCount();
while (BLE_LOG_ATOMIC_LOAD_ACQUIRE(redir_lbm->inflight) > 0) {
if ((xTaskGetTickCount() - start_tick) >= BLE_LOG_UART_FLUSH_TIMEOUT_TICKS) {
return false;
}
vTaskDelay(1);
}
return true;
}
void ble_log_prph_reset_util_counters(void)
{
#if BLE_LOG_PRPH_UART_DMA_REDIR
if (redir_lbm) {
__atomic_store_n(&redir_lbm->trans_inflight, 0, __ATOMIC_RELAXED);
__atomic_store_n(&redir_lbm->trans_inflight_peak, 0, __ATOMIC_RELAXED);
uint32_t inflight = BLE_LOG_ATOMIC_LOAD_RELAXED(redir_lbm->inflight);
BLE_LOG_ATOMIC_STORE_RELAXED(redir_lbm->inflight_peak, inflight);
}
#endif
}
#endif /* BLE_LOG_PRPH_UART_DMA_REDIR */
@@ -28,9 +28,12 @@ Runtime dispatch behavior and latency are covered by the sibling
- `throughput`: fixed 32B / 64B / 128B / mixed 8-64B payload profiles, each at
2 Mbps, 20 Mbps, and unlimited link. Runs 3 write_hex writers + LL task + LL
HCI + compressed writer + 1 kHz ISR writer concurrently.
- `write_hex cycles`: single writer, no link cap, payload 8/32/64/128 B.
- `write_hex drop path cycles`: saturated 2 Mbps link, measures the cost of a
failed (dropped) write.
- `write_hex cycles`: single writer, no link cap, payload 8/32/64/128 B. The
scheduler remains active during each measured call, followed by an unmeasured
one-tick pacing delay so the no-loss profile does not become a saturation test.
- `write_hex drop path cycles`: saturated 2 Mbps link, measures the backpressure
cost of a parked write (wait and wake on transport recycle) without the
no-loss pacing delay.
- `write_hex_ll cycles`: payload 8/32/64/128 B; plus a 32+32 B append case.
- `compressed write cycles`: workload matrix of the compressed entry points —
U32 args (0/1/2/mixed), U64 values (full 8B / leading-zero LZ / zero),
@@ -10,7 +10,7 @@
#include "unity_test_runner.h"
#include "ble_log.h"
#include "ble_log_lbm.h"
#include "ble_log_lbm_v2.h"
#include "test_ble_log_main.h"
bool test_ble_log_walk_frames(const uint8_t *data, size_t len,
@@ -36,7 +36,7 @@ bool test_ble_log_walk_frames(const uint8_t *data, size_t len,
if (observer) {
test_ble_log_frame_t frame = {
.src = head.frame_meta & 0xff,
.src = (ble_log_src_t)(head.frame_meta & 0xff),
.sn = head.frame_meta >> 8,
.payload = data + offset + BLE_LOG_FRAME_HEAD_LEN,
.payload_len = head.length,
@@ -12,7 +12,7 @@
#include <string.h>
#include "ble_log.h"
#include "ble_log_lbm.h"
#include "ble_log_lbm_v2.h"
#include "ble_log_prph_test.h"
#include "log_compression/utils.h"
#include "esp_cpu.h"
@@ -125,7 +125,7 @@ typedef struct {
uint32_t ll_flag; /* UINT32_MAX: use ble_log_write_hex */
bool compressed; /* call ble_log_compressed_hex_print instead */
bool record_cycles;
bool isolate_write; /* vTaskSuspendAll around the timed write */
bool pace_after_write; /* one tick outside a no-loss timed call */
const uint8_t *ll_append; /* write_hex_ll append part */
size_t ll_append_len;
const perf_compress_cfg_t *compress_cfg;
@@ -174,7 +174,6 @@ typedef struct {
bool compress;
bool isr;
bool measure_cycles;
bool isolate_write;
bool expect_no_loss;
const uint8_t *ll_append;
size_t ll_append_len;
@@ -316,8 +315,7 @@ static void print_run_separator(const char *tag, const perf_run_cfg_t *cfg)
tag, (unsigned)cfg->run_idx, (unsigned)cfg->run_total,
cfg->mode_name, cfg->profile_name);
print_link(cfg->bytes_per_second);
printf(" isolate=%s ============\n",
cfg->isolate_write ? "sched" : "none");
printf(" isolate=none ============\n");
}
/* ---------------- */
@@ -349,9 +347,6 @@ static void perf_writer_task(void *arg)
size_t payload_len = w->profile[frame_index % w->profile_count];
memcpy(payload, &frame_index, sizeof(frame_index));
if (w->isolate_write) {
vTaskSuspendAll();
}
uint32_t start_cycles = w->record_cycles ? esp_cpu_get_cycle_count() : 0;
bool ok;
@@ -427,9 +422,6 @@ static void perf_writer_task(void *arg)
if (w->record_cycles) {
write_cycles = esp_cpu_get_cycle_count() - start_cycles;
}
if (w->isolate_write) {
xTaskResumeAll();
}
if (ok) {
w->cycles->ok_frames++;
@@ -443,7 +435,14 @@ static void perf_writer_task(void *arg)
}
}
frame_index++;
taskYIELD();
if (w->pace_after_write) {
/* Cycle profiles measure one production-semantics call, then
* yield enough time for deferred dispatch and sink recycling.
* Throughput and explicit drop profiles remain unpaced. */
vTaskDelay(1);
} else {
taskYIELD();
}
}
xSemaphoreGive(w->done);
@@ -485,21 +484,26 @@ static void observe_perf_frame(const test_ble_log_frame_t *frame, void *ctx)
sink->frames_by_src[frame->src]++;
}
/* Capture enhanced statistics records (written/lost per source).
* Frames carry a 4-byte os_timestamp prefix before the record. */
if (frame->src == BLE_LOG_SRC_INTERNAL &&
frame->payload_len == sizeof(uint32_t) + sizeof(ble_log_enh_stat_t) &&
frame->payload[sizeof(uint32_t)] == BLE_LOG_INT_SRC_ENH_STAT) {
ble_log_enh_stat_t stat;
memcpy(&stat, frame->payload + sizeof(uint32_t), sizeof(stat));
if (stat.src_code < BLE_LOG_SRC_MAX) {
sink->stat_written[stat.src_code] = stat.written_frame_cnt;
sink->stat_lost[stat.src_code] = stat.lost_frame_cnt;
frame->payload_len == sizeof(uint32_t) +
sizeof(ble_log_internal_snapshot_t)) {
ble_log_internal_snapshot_t snapshot;
memcpy(&snapshot, frame->payload + sizeof(uint32_t), sizeof(snapshot));
if (snapshot.int_src_code != BLE_LOG_INT_SRC_SNAPSHOT) {
return;
}
/* Latch the final counters only from the FLUSH snapshot: periodic
* snapshots keep arriving after it and carry interval counters
* that the flush reset; letting them through would overwrite the
* final result the run report and assertions rely on. */
if (snapshot.reason_flags & BLE_LOG_SNAPSHOT_REASON_FLUSH) {
for (int i = 0; i < BLE_LOG_SRC_CORE_COUNT; i++) {
int src = BLE_LOG_SRC_CORE_FIRST + i;
sink->stat_written[src] = snapshot.stats[i].written_frame_cnt;
sink->stat_lost[src] = snapshot.stats[i].lost_frame_cnt;
}
sink->stat_final_seen = true;
}
} else if (frame->src == BLE_LOG_SRC_INTERNAL &&
frame->payload_len == sizeof(uint32_t) + sizeof(ble_log_final_stat_t) &&
frame->payload[sizeof(uint32_t)] == BLE_LOG_INT_SRC_FINAL_STAT) {
sink->stat_final_seen = true;
}
}
@@ -541,7 +545,7 @@ static void fill_writer(perf_writer_t *w, const char *name, ble_log_src_t src,
w->ll_flag = ll_flag;
w->compressed = compressed;
w->record_cycles = cfg->measure_cycles;
w->isolate_write = cfg->isolate_write;
w->pace_after_write = cfg->measure_cycles && cfg->expect_no_loss;
w->ll_append = cfg->ll_append;
w->ll_append_len = cfg->ll_append_len;
w->compress_cfg = cfg->compress_cfg;
@@ -651,8 +655,8 @@ static void run_perf_case(const perf_run_cfg_t *cfg)
}
if (ll_hci) {
fill_writer(&writers[writer_count], "write_hex_ll_hci", BLE_LOG_SRC_LL_HCI,
BIT(BLE_LOG_LL_FLAG_HCI), false, cfg, &ll_hci_cycles, start);
fill_writer(&writers[writer_count], "write_hex_hci", BLE_LOG_SRC_HCI,
UINT32_MAX, false, cfg, &ll_hci_cycles, start);
TEST_ASSERT_EQUAL(pdPASS,
xTaskCreatePinnedToCore(perf_writer_task, "perf_hci",
PERF_WRITER_STACK_SIZE,
@@ -744,6 +748,8 @@ static void run_perf_case(const perf_run_cfg_t *cfg)
}
sink.stop = true;
TEST_ASSERT_EQUAL(pdTRUE, xSemaphoreTake(sink.done, pdMS_TO_TICKS(1000)));
TEST_ASSERT_TRUE_MESSAGE(sink.stat_final_seen,
"Final statistics snapshot was not received");
uint8_t discard[BLE_LOG_TRANS_SIZE];
while (ble_log_prph_test_read(discard, sizeof(discard), 0, 0, NULL)) {
@@ -753,12 +759,12 @@ static void run_perf_case(const perf_run_cfg_t *cfg)
printf("BLE_LOG_PERF mode=%s profile=%s payload=%uB ",
cfg->mode_name, cfg->profile_name, cfg->profile[0]);
print_link(cfg->bytes_per_second);
printf(" isolate=%s duration=%" PRIu64 " ms\n",
cfg->isolate_write ? "sched" : "none", elapsed_us / 1000);
printf(" isolate=none duration=%" PRIu64 " ms\n", elapsed_us / 1000);
printf("BLE_LOG_PERF flush=%" PRIu32 " cycles\n", flush_cycles);
uint64_t ok_total = 0;
uint64_t failed_total = 0;
uint64_t custom_failed_total = 0;
for (i = 0; i < cfg->custom_writer_count; i++) {
char name[32];
snprintf(name, sizeof(name), "write_hex%" PRIu32, i);
@@ -769,6 +775,7 @@ static void run_perf_case(const perf_run_cfg_t *cfg)
}
ok_total += custom_cycles[i].ok_frames;
failed_total += custom_cycles[i].failed_frames;
custom_failed_total += custom_cycles[i].failed_frames;
}
#if CONFIG_BLE_LOG_LL_ENABLED
if (ll_task) {
@@ -782,9 +789,9 @@ static void run_perf_case(const perf_run_cfg_t *cfg)
}
if (ll_hci) {
if (cfg->measure_cycles) {
print_cycles("write_hex_ll_hci", &ll_hci_cycles, true);
print_cycles("write_hex_hci", &ll_hci_cycles, false);
} else {
print_writer_counts("write_hex_ll_hci", &ll_hci_cycles);
print_writer_counts("write_hex_hci", &ll_hci_cycles);
}
ok_total += ll_hci_cycles.ok_frames;
failed_total += ll_hci_cycles.failed_frames;
@@ -827,10 +834,12 @@ static void run_perf_case(const perf_run_cfg_t *cfg)
}
}
#endif
uint64_t ll_frames = sink.frames_by_src[BLE_LOG_SRC_LL_TASK] +
sink.frames_by_src[BLE_LOG_SRC_LL_HCI] +
sink.frames_by_src[BLE_LOG_SRC_LL_ISR];
uint64_t sink_frames = sink.frames_by_src[BLE_LOG_SRC_CUSTOM] +
sink.frames_by_src[BLE_LOG_SRC_LL_TASK] +
sink.frames_by_src[BLE_LOG_SRC_LL_HCI] +
sink.frames_by_src[BLE_LOG_SRC_LL_ISR] +
ll_frames +
sink.frames_by_src[BLE_LOG_SRC_HCI] +
sink.frames_by_src[BLE_LOG_SRC_ENCODE];
printf("BLE_LOG_PERF total ok=%" PRIu64 " failed=%" PRIu64
" sink_frames=%" PRIu64 " sink_bytes=%" PRIu64
@@ -840,19 +849,21 @@ static void run_perf_case(const perf_run_cfg_t *cfg)
if (!cfg->measure_cycles) {
print_throughput(sink.transport_bytes, elapsed_us, cfg->bytes_per_second);
}
printf("BLE_LOG_PERF stat written=[custom=%" PRIu64 " ll_task=%" PRIu64
" ll_hci=%" PRIu64 " ll_isr=%" PRIu64 " encode=%" PRIu64
"] lost=[custom=%" PRIu64 " ll_task=%" PRIu64 " ll_hci=%" PRIu64
" ll_isr=%" PRIu64 " encode=%" PRIu64 "]\n",
printf("BLE_LOG_PERF stat written=[custom=%" PRIu64 " ll=%" PRIu64
" hci=%" PRIu64 " encode=%" PRIu64
"] lost=[custom=%" PRIu64 " ll=%" PRIu64
" hci=%" PRIu64 " encode=%" PRIu64 "]\n",
sink.stat_written[BLE_LOG_SRC_CUSTOM],
sink.stat_written[BLE_LOG_SRC_LL_TASK],
sink.stat_written[BLE_LOG_SRC_LL_HCI],
sink.stat_written[BLE_LOG_SRC_LL_TASK] +
sink.stat_written[BLE_LOG_SRC_LL_HCI] +
sink.stat_written[BLE_LOG_SRC_LL_ISR],
sink.stat_written[BLE_LOG_SRC_HCI],
sink.stat_written[BLE_LOG_SRC_ENCODE],
sink.stat_lost[BLE_LOG_SRC_CUSTOM],
sink.stat_lost[BLE_LOG_SRC_LL_TASK],
sink.stat_lost[BLE_LOG_SRC_LL_HCI],
sink.stat_lost[BLE_LOG_SRC_LL_TASK] +
sink.stat_lost[BLE_LOG_SRC_LL_HCI] +
sink.stat_lost[BLE_LOG_SRC_LL_ISR],
sink.stat_lost[BLE_LOG_SRC_HCI],
sink.stat_lost[BLE_LOG_SRC_ENCODE]);
print_run_separator("END", cfg);
@@ -862,13 +873,19 @@ static void run_perf_case(const perf_run_cfg_t *cfg)
TEST_ASSERT_GREATER_THAN_UINT64(0, ok_total);
if (cfg->expect_no_loss) {
TEST_ASSERT_EQUAL_UINT64(0, failed_total);
TEST_ASSERT_EQUAL_UINT64(0, sink.stat_lost[BLE_LOG_SRC_CUSTOM]);
TEST_ASSERT_EQUAL_UINT64(0, sink.stat_lost[BLE_LOG_SRC_LL_TASK]);
TEST_ASSERT_EQUAL_UINT64(0, sink.stat_lost[BLE_LOG_SRC_LL_HCI]);
TEST_ASSERT_EQUAL_UINT64(0, sink.stat_lost[BLE_LOG_SRC_LL_ISR]);
TEST_ASSERT_EQUAL_UINT64(0, sink.stat_lost[BLE_LOG_SRC_ENCODE]);
for (int i = 0; i < BLE_LOG_SRC_CORE_COUNT; i++) {
TEST_ASSERT_EQUAL_UINT64(0,
sink.stat_lost[BLE_LOG_SRC_CORE_FIRST + i]);
}
} else if (sink.stat_final_seen) {
TEST_ASSERT_EQUAL_UINT64(failed_total, sink.stat_lost[BLE_LOG_SRC_CUSTOM]);
TEST_ASSERT_EQUAL_UINT64(custom_failed_total,
sink.stat_lost[BLE_LOG_SRC_CUSTOM]);
#if CONFIG_BLE_LOG_LL_ENABLED
if (ll_hci) {
TEST_ASSERT_EQUAL_UINT64(ll_hci_cycles.failed_frames,
sink.stat_lost[BLE_LOG_SRC_HCI]);
}
#endif
#if CONFIG_BLE_COMPRESSED_LOG_ENABLE
if (compress) {
/* Every hex_print call reaches write_hex(ENCODE) exactly once;
@@ -934,7 +951,6 @@ static void run_cycle_case(const char *name, const uint16_t *profile, size_t cou
.ll_hci = ll_hci,
.compress = compress_cfg != NULL,
.measure_cycles = true,
.isolate_write = true,
.expect_no_loss = true,
.compress_cfg = compress_cfg,
};
@@ -968,8 +984,9 @@ TEST_CASE("BLE Log write_hex cycles (single writer, link=0)", "[ble_log][perf][c
}
}
/* Saturated link: most writes fail. Measures the drop-path cost and
* cross-checks client failed counts against the LBM's lost counters. */
/* Saturated link: yieldable writers park on backpressure instead of dropping;
* measures the park/wake cost and cross-checks client failed counts against
* the LBM's lost counters. */
TEST_CASE("BLE Log write_hex drop path cycles (link=2Mbps)", "[ble_log][perf][cycle][ignore]")
{
perf_run_cfg_t cfg = {
@@ -982,7 +999,6 @@ TEST_CASE("BLE Log write_hex drop path cycles (link=2Mbps)", "[ble_log][perf][cy
.bytes_per_second = PERF_LINK_2MBPS_BPS,
.custom_writer_count = 1,
.measure_cycles = true,
.isolate_write = true,
};
run_perf_case(&cfg);
}
@@ -1011,7 +1027,6 @@ TEST_CASE("BLE Log write_hex_ll append cycles (32+32B)", "[ble_log][perf][cycle]
.custom_writer_count = 0,
.ll_task = true,
.measure_cycles = true,
.isolate_write = true,
.expect_no_loss = true,
.ll_append = append_buf,
.ll_append_len = 32,
@@ -1021,6 +1036,88 @@ TEST_CASE("BLE Log write_hex_ll append cycles (32+32B)", "[ble_log][perf][cycle]
#endif
#if CONFIG_BLE_COMPRESSED_LOG_ENABLE
/* ---------------------- */
/* Attribution cycles */
/* ---------------------- */
/* Compressed records attribute every record to their writer task by
* normalizing the FreeRTOS task name to NUL-padded words and scanning
* the registry. A hand-rolled copy (no libc calls) was measured on
* ESP32-H2 at -Og against this libc version: the two trade places
* across name lengths (inline wins ~31 cycles on 3-char names, loses
* ~31 on full 16-char names, ties in between) against ~1.6k cycles per
* compressed record - no variant is meaningfully faster. The module
* keeps the libc version because it is three lines; this case records
* the numbers so the decision does not get re-litigated blind. */
#define NORM_WORDS 4 /* BLE_CP_TASK_NAME_WORDS, private to the module */
#define NORM_LEN (NORM_WORDS * sizeof(uint32_t))
#define NORM_ROUNDS 5
#define NORM_ITERS 20000
typedef void (*norm_fn_t)(const char *name, uint32_t w[NORM_WORDS]);
static void norm_libc(const char *name, uint32_t w[NORM_WORDS])
{
memset(w, 0, NORM_LEN);
memcpy(w, name, strnlen(name, NORM_LEN));
}
static void norm_inline(const char *name, uint32_t w[NORM_WORDS])
{
for (unsigned i = 0; i < NORM_WORDS; i++) {
uint32_t v = 0;
for (unsigned b = 0; b < sizeof(uint32_t); b++) {
uint8_t c = (uint8_t)*name;
if (c == '\0') {
break;
}
v |= (uint32_t)c << (8 * b);
name++;
}
w[i] = v;
}
}
static volatile uint32_t s_norm_sink;
static uint32_t norm_bench_once(norm_fn_t fn, const char *name)
{
uint32_t sink = 0;
uint32_t start = esp_cpu_get_cycle_count();
for (uint32_t i = 0; i < NORM_ITERS; i++) {
uint32_t w[NORM_WORDS];
fn(name, w);
sink ^= w[0] ^ w[1] ^ w[2] ^ w[3];
}
s_norm_sink = sink; /* the copies must stay live */
return (esp_cpu_get_cycle_count() - start) / NORM_ITERS;
}
TEST_CASE("BLE Log task-name normalization cycles", "[ble_log][perf][cycle][ignore]")
{
static const char *const names[] = {"BTU", "NIMBLE_HOST", "0123456789ABCDEF"};
for (size_t i = 0; i < sizeof(names) / sizeof(names[0]); i++) {
/* both variants must agree on every shape before timing them */
uint32_t wa[NORM_WORDS], wb[NORM_WORDS];
norm_libc(names[i], wa);
norm_inline(names[i], wb);
TEST_ASSERT_EQUAL_UINT32_ARRAY(wa, wb, NORM_WORDS);
uint32_t best_libc = UINT32_MAX;
uint32_t best_inline = UINT32_MAX;
for (int r = 0; r < NORM_ROUNDS; r++) { /* interleaved rounds */
uint32_t a = norm_bench_once(norm_libc, names[i]);
uint32_t b = norm_bench_once(norm_inline, names[i]);
best_libc = a < best_libc ? a : best_libc;
best_inline = b < best_inline ? b : best_inline;
}
printf("BLE_LOG_PERF norm name=%-16s libc=%4" PRIu32 " inline=%4" PRIu32
" delta=%+" PRId32 " cycles/call\n",
names[i], best_libc, best_inline,
(int32_t)best_libc - (int32_t)best_inline);
}
}
/* Compressed records are log_index + 0..2 U32 args, not a raw payload
* length. One case per arg count splits encode vs downstream write_hex
* cost for each workload shape. */
@@ -19,12 +19,12 @@ the hand-over time, so dispatch latency is measured without a real link.
- `runtime` regressions: shared ESP Timer task fairness, periodic timestamp
delivery without light-sleep wakeups, ISR-only submission delivery,
consumer-independent receipt timing, extra-marker detection, exact 1 ms
first-submission defer scheduling, full task-pool snapshot dispatch, deinit
first-submission defer scheduling, full shared-pool snapshot dispatch, deinit
racing submissions (SMP-pinned writer, failure-safe recovery), bounded
inflight-peak statistics, and monotonic millisecond waits at both supported
tick rates.
The first-deadline and full task-pool regressions require dispatch exclusion
The first-deadline and full shared-pool regressions require dispatch exclusion
while enqueueing, so they run on single-core builds only (they are ignored on
SMP targets). The deinit-race regression pins its writer to the other core on
SMP.
@@ -10,7 +10,7 @@
#include "unity_test_runner.h"
#include "ble_log.h"
#include "ble_log_lbm.h"
#include "ble_log_lbm_v2.h"
#include "ble_log_prph_test.h"
#include "test_ble_log_main.h"
@@ -37,7 +37,7 @@ bool test_ble_log_walk_frames(const uint8_t *data, size_t len,
if (observer) {
test_ble_log_frame_t frame = {
.src = head.frame_meta & 0xff,
.src = (ble_log_src_t)(head.frame_meta & 0xff),
.sn = head.frame_meta >> 8,
.payload = data + offset + BLE_LOG_FRAME_HEAD_LEN,
.payload_len = head.length,
@@ -51,14 +51,15 @@ bool test_ble_log_walk_frames(const uint8_t *data, size_t len,
void setUp(void)
{
/* Preserve the external test-system contract: every test starts with the
* optional sync IO disabled and low. Periodic snapshots remain active. */
(void)ble_log_sync_enable(false);
}
void tearDown(void)
{
ble_log_prph_test_set_auto_recycle_hook(NULL, NULL);
#if CONFIG_BLE_LOG_TS_ENABLED
(void)ble_log_sync_enable(false);
#endif
}
void app_main(void)
@@ -12,7 +12,7 @@
#include <string.h>
#include "ble_log.h"
#include "ble_log_lbm.h"
#include "ble_log_lbm_v2.h"
#include "ble_log_prph_test.h"
#include "ble_log_rt.h"
#include "esp_timer.h"
@@ -24,7 +24,6 @@
#define RT_SAMPLE_COUNT (32)
#define RT_BURST_SIZE (4)
#define RT_TASK_POOL_TRANS_COUNT ((BLE_LOG_LBM_ATOMIC_TASK_CNT + 1) * BLE_LOG_TRANS_BUF_CNT)
#define RT_READ_TIMEOUT_MS (100)
#define RT_QUIET_TIMEOUT_MS (10)
#define RT_QUIET_DRAIN_DEADLINE_MS (2000)
@@ -37,7 +36,7 @@
#define RT_CONSUMER_DELAY_MS (30)
#define RT_RECEIVE_MAX_LATENCY_US (10000)
#define RT_BURST_SPAN_MAX_US (500)
#define RT_PEAK_WRITES (8)
#define RT_PEAK_WRITES (BLE_LOG_POOL_SHARED_CNT)
#define RT_DEINIT_ROUNDS (200)
#define RT_JOIN_TIMEOUT_MS (5000)
@@ -52,6 +51,13 @@ typedef struct {
uint32_t ts_count;
} rt_marker_observer_t;
#if CONFIG_BLE_LOG_TS_SYNC_TOGGLE_IO_ENABLED
typedef struct {
bool found;
uint8_t io_level;
} rt_snapshot_observer_t;
#endif
typedef struct {
SemaphoreHandle_t done;
uint32_t remaining;
@@ -100,9 +106,14 @@ static void observe_runtime_marker(const test_ble_log_frame_t *frame, void *ctx)
{
rt_marker_observer_t *observer = ctx;
if (frame->src == BLE_LOG_SRC_INTERNAL &&
frame->payload_len > sizeof(uint32_t) &&
frame->payload[sizeof(uint32_t)] == BLE_LOG_INT_SRC_TS) {
observer->ts_count++;
frame->payload_len == sizeof(uint32_t) +
sizeof(ble_log_internal_snapshot_t)) {
ble_log_internal_snapshot_t snapshot;
memcpy(&snapshot, frame->payload + sizeof(uint32_t), sizeof(snapshot));
if (snapshot.int_src_code == BLE_LOG_INT_SRC_SNAPSHOT &&
(snapshot.reason_flags & BLE_LOG_SNAPSHOT_REASON_TS_VALID)) {
observer->ts_count++;
}
}
if (frame->src != BLE_LOG_SRC_CUSTOM ||
@@ -118,6 +129,29 @@ static void observe_runtime_marker(const test_ble_log_frame_t *frame, void *ctx)
}
}
#if CONFIG_BLE_LOG_TS_SYNC_TOGGLE_IO_ENABLED
static void observe_periodic_snapshot(const test_ble_log_frame_t *frame,
void *ctx)
{
rt_snapshot_observer_t *observer = ctx;
if (observer->found || frame->src != BLE_LOG_SRC_INTERNAL ||
frame->payload_len != sizeof(uint32_t) +
sizeof(ble_log_internal_snapshot_t)) {
return;
}
ble_log_internal_snapshot_t snapshot;
memcpy(&snapshot, frame->payload + sizeof(uint32_t), sizeof(snapshot));
uint16_t expected = BLE_LOG_SNAPSHOT_REASON_PERIODIC |
BLE_LOG_SNAPSHOT_REASON_TS_VALID;
if (snapshot.int_src_code == BLE_LOG_INT_SRC_SNAPSHOT &&
(snapshot.reason_flags & expected) == expected) {
observer->found = true;
observer->io_level = snapshot.ts.io_level;
}
}
#endif
static TickType_t runtime_timeout_ticks(uint32_t timeout_ms)
{
uint64_t ticks = ((uint64_t)timeout_ms * configTICK_RATE_HZ + 999) / 1000;
@@ -155,11 +189,12 @@ static bool write_runtime_marker(uint32_t seq, int64_t *enqueued_at_us)
return true;
}
static bool read_runtime_marker(uint32_t *seq, uint32_t *ts_count,
int64_t *received_at_us)
static bool read_runtime_marker_with_timeout(uint32_t *seq, uint32_t *ts_count,
int64_t *received_at_us,
uint32_t timeout_ms)
{
const int64_t deadline_us = esp_timer_get_time() +
(int64_t)RT_READ_TIMEOUT_MS * 1000;
(int64_t)timeout_ms * 1000;
uint32_t observed_ts = 0;
while (true) {
@@ -193,6 +228,13 @@ static bool read_runtime_marker(uint32_t *seq, uint32_t *ts_count,
}
}
static bool read_runtime_marker(uint32_t *seq, uint32_t *ts_count,
int64_t *received_at_us)
{
return read_runtime_marker_with_timeout(seq, ts_count, received_at_us,
RT_READ_TIMEOUT_MS);
}
static bool runtime_stream_is_quiet(void)
{
const int64_t drain_deadline_us = esp_timer_get_time() +
@@ -225,6 +267,35 @@ static bool runtime_stream_is_quiet(void)
return false;
}
#if CONFIG_BLE_LOG_TS_SYNC_TOGGLE_IO_ENABLED
static bool read_periodic_snapshot(uint8_t *io_level)
{
const int64_t deadline_us = esp_timer_get_time() +
(int64_t)BLE_LOG_TS_TRIGGER_TIMEOUT_US + 1000000;
while (true) {
TickType_t remaining;
if (!runtime_deadline_ticks(deadline_us, &remaining)) {
return false;
}
size_t len = ble_log_prph_test_read(s_capture, sizeof(s_capture),
remaining, 0, NULL);
if (!len) {
continue;
}
rt_snapshot_observer_t observer = {0};
if (!test_ble_log_walk_frames(s_capture, len,
observe_periodic_snapshot, &observer)) {
return false;
}
if (observer.found) {
*io_level = observer.io_level;
return true;
}
}
}
#endif
static void refill_runtime_queue(void *arg)
{
rt_starvation_ctx_t *ctx = arg;
@@ -275,18 +346,21 @@ static void observe_buf_util(const test_ble_log_frame_t *frame, void *ctx)
{
rt_peak_observer_t *observer = ctx;
if (frame->src != BLE_LOG_SRC_INTERNAL ||
frame->payload_len < sizeof(uint32_t) + sizeof(ble_log_buf_util_t) ||
frame->payload[sizeof(uint32_t)] != BLE_LOG_INT_SRC_BUF_UTIL) {
frame->payload_len != sizeof(uint32_t) +
sizeof(ble_log_internal_snapshot_t)) {
return;
}
ble_log_buf_util_t util;
memcpy(&util, frame->payload + sizeof(uint32_t), sizeof(util));
observer->buf_util_frames++;
if (util.inflight_peak > observer->max_inflight_peak) {
observer->max_inflight_peak = util.inflight_peak;
ble_log_internal_snapshot_t snapshot;
memcpy(&snapshot, frame->payload + sizeof(uint32_t), sizeof(snapshot));
if (snapshot.int_src_code != BLE_LOG_INT_SRC_SNAPSHOT) {
return;
}
if (util.inflight_peak > util.trans_cnt) {
observer->buf_util_frames++;
if (snapshot.pool.inflight_peak > observer->max_inflight_peak) {
observer->max_inflight_peak = snapshot.pool.inflight_peak;
}
if (snapshot.pool.inflight_peak > snapshot.pool.trans_cnt) {
observer->over_limit = true;
}
}
@@ -441,7 +515,6 @@ TEST_CASE("BLE Log ISR-only submission arms runtime dispatch",
#endif
}
#if CONFIG_BLE_LOG_TS_ENABLED
TEST_CASE("BLE Log periodic timestamp skips light sleep wakeups",
"[ble_log][runtime][timestamp][ignore]")
{
@@ -474,7 +547,7 @@ TEST_CASE("BLE Log periodic timestamp skips light sleep wakeups",
TEST_ASSERT_TRUE(runtime_stream_is_quiet());
TEST_ASSERT_TRUE(ble_log_sync_enable(true));
for (int i = 0; i < 3; i++) {
vTaskDelay(runtime_timeout_ticks(CONFIG_BLE_LOG_TS_TRIGGER_TIMEOUT_MS));
vTaskDelay(runtime_timeout_ticks(BLE_LOG_TS_TRIGGER_TIMEOUT_MS));
}
TEST_ASSERT_TRUE(ble_log_sync_enable(false));
@@ -489,7 +562,65 @@ TEST_CASE("BLE Log periodic timestamp skips light sleep wakeups",
0, ts_count,
"Periodic ESP timer did not emit a timestamp frame");
}
TEST_CASE("BLE Log sync IO control leaves periodic snapshots running",
"[ble_log][runtime][timestamp][ignore]")
{
#if !CONFIG_BLE_LOG_TS_SYNC_TOGGLE_IO_ENABLED
TEST_IGNORE_MESSAGE("Requires BLE Log TS sync IO toggle support");
#else
const uint32_t seq = UINT32_C(0x41000);
uint32_t received_seq;
uint8_t io_level;
TEST_ASSERT_TRUE(ble_log_enable(true));
TEST_ASSERT_TRUE(ble_log_ts_sync_io_toggle_enable(false));
TEST_ASSERT_TRUE(runtime_stream_is_quiet());
TEST_ASSERT_TRUE_MESSAGE(read_periodic_snapshot(&io_level),
"No periodic clock snapshot while sync IO was disabled");
TEST_ASSERT_EQUAL_UINT8(0, io_level);
TEST_ASSERT_TRUE(runtime_stream_is_quiet());
/* Establish the timer phase above, then park a partial OPEN transport and
* close the public producer gate. The next periodic callback must still
* flush the transport and emit its Internal Snapshot. */
prepare_payload(seq);
TEST_ASSERT_TRUE(ble_log_write_hex(BLE_LOG_SRC_CUSTOM, s_payload,
sizeof(rt_marker_t)));
TEST_ASSERT_TRUE(ble_log_enable(false));
bool marker_received = read_runtime_marker_with_timeout(
&received_seq, NULL, NULL,
BLE_LOG_TS_TRIGGER_TIMEOUT_MS + 1000);
bool snapshot_received = read_periodic_snapshot(&io_level);
TEST_ASSERT_TRUE(ble_log_enable(true));
TEST_ASSERT_TRUE_MESSAGE(
marker_received,
"Producer disable stopped the periodic OPEN transport flush");
TEST_ASSERT_EQUAL_UINT32(seq, received_seq);
TEST_ASSERT_TRUE_MESSAGE(
snapshot_received,
"Producer disable stopped periodic Internal Snapshots");
TEST_ASSERT_EQUAL_UINT8(0, io_level);
TEST_ASSERT_TRUE(runtime_stream_is_quiet());
TEST_ASSERT_TRUE(ble_log_ts_sync_io_toggle_enable(true));
bool high_seen = false;
for (int i = 0; i < 3 && !high_seen; i++) {
TEST_ASSERT_TRUE_MESSAGE(read_periodic_snapshot(&io_level),
"No periodic snapshot while sync IO was enabled");
high_seen = io_level != 0;
}
TEST_ASSERT_TRUE_MESSAGE(high_seen, "Enabled sync IO never toggled high");
/* Exercise the compatibility shim on disable. */
TEST_ASSERT_TRUE(ble_log_sync_enable(false));
TEST_ASSERT_TRUE(runtime_stream_is_quiet());
TEST_ASSERT_TRUE_MESSAGE(read_periodic_snapshot(&io_level),
"Sync IO disable stopped periodic snapshots");
TEST_ASSERT_EQUAL_UINT8(0, io_level);
#endif
}
TEST_CASE("BLE Log runtime dispatch yields to other timer callbacks",
"[ble_log][runtime][ignore]")
@@ -654,7 +785,7 @@ TEST_CASE("BLE Log runtime dispatch latency", "[ble_log][runtime][perf][ignore]"
print_latency_stats("burst_last", RT_BURST_SIZE, s_burst_last_latency_us);
}
TEST_CASE("BLE Log runtime drains the full task pool in one batch",
TEST_CASE("BLE Log runtime drains the full shared pool in one batch",
"[ble_log][runtime][ignore]")
{
#if !CONFIG_FREERTOS_UNICORE
@@ -666,8 +797,8 @@ TEST_CASE("BLE Log runtime drains the full task pool in one batch",
TEST_ASSERT_TRUE(ble_log_enable(true));
/* Flush from this ordinary test task so every task-pool transport is free
* before constructing the callback-entry snapshot. */
/* Flush from this ordinary test task so every shared-pool transport is
* free before constructing the callback-entry snapshot. */
ble_log_prph_test_set_auto_recycle_hook(noop_callback, NULL);
ble_log_flush();
ble_log_prph_test_set_auto_recycle_hook(NULL, NULL);
@@ -678,15 +809,15 @@ TEST_CASE("BLE Log runtime drains the full task pool in one batch",
* without an artificial item cap. */
bool wrote = true;
vTaskSuspendAll();
for (uint32_t i = 0; i < RT_TASK_POOL_TRANS_COUNT; i++) {
for (uint32_t i = 0; i < BLE_LOG_POOL_SHARED_CNT; i++) {
prepare_payload(base_seq + i);
wrote = wrote &&
ble_log_write_hex(BLE_LOG_SRC_CUSTOM, s_payload, sizeof(s_payload));
}
(void)xTaskResumeAll();
TEST_ASSERT_TRUE_MESSAGE(wrote, "Full task-pool enqueue failed");
TEST_ASSERT_TRUE_MESSAGE(wrote, "Full shared-pool enqueue failed");
for (uint32_t i = 0; i < RT_TASK_POOL_TRANS_COUNT; i++) {
for (uint32_t i = 0; i < BLE_LOG_POOL_SHARED_CNT; i++) {
uint32_t received_seq;
int64_t received_at_us;
TEST_ASSERT_TRUE_MESSAGE(read_runtime_marker(&received_seq, NULL,
@@ -722,10 +853,20 @@ TEST_CASE("BLE Log LBM inflight peak stays bounded under bursts",
TEST_ASSERT_TRUE(write_runtime_marker(seq, NULL));
}
/* Snapshot the recorded peaks. A full marker forces the partial BUF_UTIL
* transport to roll over through the normal LBM submission path. */
ble_log_write_buf_util();
TEST_ASSERT_TRUE(write_runtime_marker(UINT32_C(0x81000), NULL));
/* Recycle the burst after its peak has been recorded. A periodic tick may
* also have occupied the dedicated Internal transport, so drain twice. */
for (int round = 0; round < 2; round++) {
TEST_ASSERT_TRUE(ble_log_rt_drain());
while (ble_log_prph_test_read(s_capture, sizeof(s_capture),
0, 0, NULL) > 0) {
}
}
/* Snapshot the retained peak through the dedicated Internal transport. */
ble_log_ts_info_t ts_info;
ble_log_rt_ts_sample(&ts_info, false);
TEST_ASSERT_TRUE(ble_log_internal_snapshot(
BLE_LOG_SNAPSHOT_REASON_PERIODIC, &ts_info, true));
TEST_ASSERT_TRUE(ble_log_rt_drain());
const int64_t deadline_us = esp_timer_get_time() +
@@ -747,7 +888,7 @@ TEST_CASE("BLE Log LBM inflight peak stays bounded under bursts",
TEST_ASSERT_GREATER_THAN_UINT32_MESSAGE(
0, observer.buf_util_frames,
"No BUF_UTIL snapshots observed after flush");
"No Internal utilization snapshot observed");
TEST_ASSERT_FALSE_MESSAGE(observer.over_limit,
"inflight_peak exceeded the LBM transport count");
TEST_ASSERT_GREATER_THAN_UINT32_MESSAGE(
@@ -763,6 +904,7 @@ TEST_CASE("BLE Log runtime survives deinit racing submissions",
"[ble_log][runtime][ignore]")
{
rt_deinit_writer_ctx_t *ctx = &s_deinit_race;
TaskHandle_t writer_task = NULL;
bool reinit_ok = true;
memset(ctx, 0, sizeof(*ctx));
prepare_payload(UINT32_C(0x70000));
@@ -770,13 +912,14 @@ TEST_CASE("BLE Log runtime survives deinit racing submissions",
#if CONFIG_FREERTOS_UNICORE
BaseType_t task_created = xTaskCreate(
deinit_writer_task, "ble_log_deinit_wr", 4096, ctx,
uxTaskPriorityGet(NULL), NULL);
uxTaskPriorityGet(NULL), &writer_task);
#else
/* Pin the writer away from this core so submissions run concurrently
* with deinit instead of alternating at yield points. */
BaseType_t task_created = xTaskCreatePinnedToCore(
deinit_writer_task, "ble_log_deinit_wr", 4096, ctx,
uxTaskPriorityGet(NULL), NULL, (xPortGetCoreID() == 0) ? 1 : 0);
uxTaskPriorityGet(NULL), &writer_task,
(xPortGetCoreID() == 0) ? 1 : 0);
#endif
TEST_ASSERT_EQUAL_MESSAGE(pdPASS, task_created, "Writer task create failed");
@@ -786,9 +929,16 @@ TEST_CASE("BLE Log runtime survives deinit racing submissions",
taskYIELD();
}
/* Stop the writer and join with a bound before touching ctx or asserting:
* a unity longjmp past a live writer would leave it on a dead stack. */
/* Stop the writer and join with a bound before asserting so a Unity
* longjmp cannot leak the writer into later tests. */
__atomic_store_n(&ctx->stop, true, __ATOMIC_RELEASE);
/* A writer parked inside ble_log_claim() cannot observe stop: only the
* deinit waiter wake returns it. Deinit here, before the join, so its
* drain closes the producer gate, wakes any parked writer and waits
* for it to leave the pool API. The vTaskDelete fallback below can
* then never cut a task down inside pool bookkeeping (which would
* leak waiting_task_count and hang the recovery deinit). */
ble_log_deinit();
const int64_t join_deadline_us = esp_timer_get_time() +
(int64_t)RT_JOIN_TIMEOUT_MS * 1000;
while (!__atomic_load_n(&ctx->exited, __ATOMIC_ACQUIRE)) {
@@ -799,16 +949,20 @@ TEST_CASE("BLE Log runtime survives deinit racing submissions",
vTaskDelay(join_ticks);
}
bool writer_exited = __atomic_load_n(&ctx->exited, __ATOMIC_ACQUIRE);
if (!writer_exited && writer_task) {
vTaskDelete(writer_task);
}
/* Recover module state before any assertion can abort the test: a
* failed re-init leaves the module deinit-ed and tearDown does not
* restore it, which would cascade into every later test. */
ble_log_deinit();
* restore it, which would cascade into every later test. Deinit ran
* before the join (see above); only the init half remains. */
bool recovered = ble_log_init();
reinit_ok = reinit_ok && recovered;
TEST_ASSERT_TRUE_MESSAGE(
__atomic_load_n(&ctx->exited, __ATOMIC_ACQUIRE),
"Writer task did not exit after stop");
TEST_ASSERT_TRUE_MESSAGE(writer_exited,
"Writer task did not exit after stop");
TEST_ASSERT_TRUE_MESSAGE(reinit_ok, "BLE Log re-init failed during the race");
TEST_ASSERT_GREATER_THAN_UINT32_MESSAGE(
RT_DEINIT_ROUNDS, ctx->attempts,
@@ -6,7 +6,7 @@ CONFIG_ESP_TIMER_SUPPORTS_ISR_DISPATCH_METHOD=y
# Production tick rate; the 1000 Hz regression variant is built from
# sdkconfig.defaults.tick_1000.
CONFIG_FREERTOS_HZ=100
CONFIG_BLE_LOG_TS_ENABLED=y
CONFIG_BLE_LOG_TS_SYNC_TOGGLE_IO_ENABLED=y
# Keep the production TS/hook cadence (Kconfig default 1000 ms) so the
# regressions see the production info/stat/buf-util cadence.
CONFIG_ESP_TASK_WDT_CHECK_IDLE_TASK_CPU0=n
@@ -7,12 +7,16 @@
| Supported Targets |
| ----------------- |
This test app verifies the BLE Log runtime behaviour on target, using the
in-memory test peripheral (`CONFIG_BLE_LOG_PRPH_TEST=y`) to capture the
transport stream written by the runtime dispatch hook.
This app uses the in-memory test peripheral (`CONFIG_BLE_LOG_PRPH_TEST=y`) to
validate the BLE Log transport on target.
Currently covered:
It covers:
- `BLE_LOG_INT_SRC_VERSION_INFO` frame: BLE Log version, ESP-IDF build commit,
controller lib commit, btdm_common lib commit, BLE Mesh and BLE Audio lib
commits, chip model and chip revision
- literal protocol-v8 framing and fixed Internal Snapshot ABI;
- build, library, chip, and protocol versions inside the snapshot;
- task and critical-section writes plus HCI direction encoding;
- direct compression claim/commit, stale handles, and per-source serialization;
- oversized-record rejection, flush sequence continuity, pool exhaustion, and non-yield reserve use;
- shared log/snapshot Global SN, independent 24-bit anchor counts, and snapshot busy/loss behavior;
- successful logical-byte counts for public, claim/commit, and LL writes, plus FLUSH reset;
- enable, disable, parked-writer, and deinit races.
@@ -10,7 +10,7 @@
#include "unity_test_runner.h"
#include "ble_log.h"
#include "ble_log_lbm.h"
#include "ble_log_lbm_v2.h"
#include "test_ble_log_main.h"
bool test_ble_log_walk_frames(const uint8_t *data, size_t len,
@@ -36,7 +36,7 @@ bool test_ble_log_walk_frames(const uint8_t *data, size_t len,
if (observer) {
test_ble_log_frame_t frame = {
.src = head.frame_meta & 0xff,
.src = (ble_log_src_t)(head.frame_meta & 0xff),
.sn = head.frame_meta >> 8,
.payload = data + offset + BLE_LOG_FRAME_HEAD_LEN,
.payload_len = head.length,
@@ -50,6 +50,9 @@ bool test_ble_log_walk_frames(const uint8_t *data, size_t len,
void setUp(void)
{
/* Preserve the external test-system contract: every test starts with the
* optional sync IO disabled and low. Periodic snapshots remain active. */
(void)ble_log_sync_enable(false);
}
void tearDown(void)
File diff suppressed because it is too large Load Diff
@@ -4,3 +4,8 @@ CONFIG_BLE_LOG_PRPH_TEST=y
CONFIG_ESP_TASK_WDT_CHECK_IDLE_TASK_CPU0=n
CONFIG_UNITY_ENABLE_64BIT=y
CONFIG_BLE_MESH=y
# Exercise the compressed-log encoders and the task-id registry (protocol v8).
CONFIG_BLE_COMPRESSED_LOG_ENABLE=y
CONFIG_BLE_HOST_COMPRESSED_LOG_ENABLE=y
# Small registry so the table-full degradation is reachable on target.
CONFIG_BLE_LOG_TASK_ID_MAX=4
@@ -99,9 +99,9 @@ void hci_host_send_packet(uint8_t *data, uint16_t len)
#if CONFIG_BT_BLE_LOG_SPI_OUT_HCI_ENABLED
ble_log_spi_out_hci_write(BLE_LOG_SPI_OUT_SOURCE_HCI_DOWNSTREAM, data, len);
#endif // CONFIG_BT_BLE_LOG_SPI_OUT_HCI_ENABLED
#if CONFIG_BLE_LOG_HOST_SIDE_HCI_LOG_ENABLED
#if CONFIG_BLE_LOG_HCI_LOG_ENABLED
ble_log_write_hci(BLE_LOG_HCI_DOWNSTREAM, data, len);
#endif /* CONFIG_BLE_LOG_HOST_SIDE_HCI_LOG_ENABLED */
#endif /* CONFIG_BLE_LOG_HCI_LOG_ENABLED */
#if (BT_CONTROLLER_INCLUDED == TRUE)
esp_vhci_host_send_packet(data, len);
#else /* BT_CONTROLLER_INCLUDED == TRUE */
@@ -619,9 +619,9 @@ static int host_recv_pkt_cb(uint8_t *data, uint16_t len)
#if CONFIG_BT_BLE_LOG_SPI_OUT_HCI_ENABLED
ble_log_spi_out_hci_write(BLE_LOG_SPI_OUT_SOURCE_HCI_UPSTREAM, data, len);
#endif // CONFIG_BT_BLE_LOG_SPI_OUT_HCI_ENABLED
#if CONFIG_BLE_LOG_HOST_SIDE_HCI_LOG_ENABLED
#if CONFIG_BLE_LOG_HCI_LOG_ENABLED
ble_log_write_hci(BLE_LOG_HCI_UPSTREAM, data, len);
#endif /* CONFIG_BLE_LOG_HOST_SIDE_HCI_LOG_ENABLED */
#endif /* CONFIG_BLE_LOG_HCI_LOG_ENABLED */
//Target has packet to host, malloc new buffer for packet
BT_HDR *pkt = NULL;
#if (BLE_42_SCAN_EN == TRUE)
@@ -87,9 +87,9 @@ void esp_vhci_host_send_packet_wrapper(uint8_t *data, uint16_t len)
#if CONFIG_BT_BLE_LOG_SPI_OUT_HCI_ENABLED
ble_log_spi_out_hci_write(BLE_LOG_SPI_OUT_SOURCE_HCI_DOWNSTREAM, data, len);
#endif // CONFIG_BT_BLE_LOG_SPI_OUT_HCI_ENABLED
#if CONFIG_BLE_LOG_HOST_SIDE_HCI_LOG_ENABLED
#if CONFIG_BLE_LOG_HCI_LOG_ENABLED
ble_log_write_hci(BLE_LOG_HCI_DOWNSTREAM, data, len);
#endif /* CONFIG_BLE_LOG_HOST_SIDE_HCI_LOG_ENABLED */
#endif /* CONFIG_BLE_LOG_HCI_LOG_ENABLED */
esp_vhci_host_send_packet(data, len);
}
@@ -274,9 +274,9 @@ static int host_rcv_pkt(uint8_t *data, uint16_t len)
#if CONFIG_BT_BLE_LOG_SPI_OUT_HCI_ENABLED
ble_log_spi_out_hci_write(BLE_LOG_SPI_OUT_SOURCE_HCI_UPSTREAM, data, len);
#endif // CONFIG_BT_BLE_LOG_SPI_OUT_HCI_ENABLED
#if CONFIG_BLE_LOG_HOST_SIDE_HCI_LOG_ENABLED
#if CONFIG_BLE_LOG_HCI_LOG_ENABLED
ble_log_write_hci(BLE_LOG_HCI_UPSTREAM, data, len);
#endif /* CONFIG_BLE_LOG_HOST_SIDE_HCI_LOG_ENABLED */
#endif /* CONFIG_BLE_LOG_HCI_LOG_ENABLED */
bt_record_hci_data(data, len);
+4
View File
@@ -286,3 +286,7 @@ CONFIG_BT_NIMBLE_HCI_EVT_LO_BUF_COUNT CONFIG_BT_NIMBLE_TRA
CONFIG_BT_NIMBLE_COEX_PHY_CODED_TX_RX_TLIM_EN CONFIG_BT_LE_COEX_PHY_CODED_TX_RX_TLIM_EN
CONFIG_BT_NIMBLE_COEX_PHY_CODED_TX_RX_TLIM_DIS CONFIG_BT_LE_COEX_PHY_CODED_TX_RX_TLIM_DIS
# BLE Log: periodic Internal Snapshots are always enabled now; the legacy
# TS switch only gates the analyzer toggle IO.
CONFIG_BLE_LOG_TS_ENABLED CONFIG_BLE_LOG_TS_SYNC_TOGGLE_IO_ENABLED