mirror of
https://github.com/espressif/esp-idf.git
synced 2026-10-01 18:50:34 +03:00
feat(ble_log): write compressed logs directly into the pool
Compression encoders claim pool storage through the new ble_log_claim/ble_log_commit interface and encode in place: the per-channel static payload buffers and their CAS busy management go away, and each record is one ENCODE frame. The timestamp and CAS helper macros (and their lbm call sites) are capitalized to the all-uppercase convention for function-like macros as part of the rewrite. Test coverage lands with the feature: - ble_log_test: golden v7 wire bytes, snapshot layout, pool exhaustion and reserve use, claim/commit stale-handle rejection, periodic snapshot busy/loss, FLUSH reset semantics; the stale-claim assertions are sabotage-verified to fail when the state or generation check is deleted; - ble_log_rt_test: runtime dispatch latency and batch drain, TS-valid snapshot cadence, deinit races across repeated init/deinit rounds (valid HCI macro inputs, corrected regression setup); - ble_log_perf_test: per-writer throughput and cycle measurement against the unified pool with the shared/reserve split and paced no-loss profiles.
This commit is contained in:
Zhou Xiao
guozifan
@@ -1,495 +1,216 @@
|
||||
# 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 public writes are non-blocking.
|
||||
Only the ordinary controller LL task path waits for a shared transport.
|
||||
|
||||
The Internal Snapshot and UART0 redirection transports are not members of the
|
||||
bitmap pool.
|
||||
|
||||
## 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 7 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..6 base source
|
||||
bit 7 NON_YIELD
|
||||
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 frames begin their payload with:
|
||||
|
||||
```text
|
||||
[4-byte low32 esp_timer_get_time() microseconds][source payload]
|
||||
```
|
||||
|
||||
The timestamp is captured at API entry before any pool or UART0 redirection
|
||||
mutex wait. It wraps approximately every 71.6 minutes and must be unwrapped
|
||||
modulo 2^32 by the receiver. UART0 redirection retains its extension-specific
|
||||
stream aggregation while using the same ESP Timer timestamp semantics.
|
||||
|
||||
### Sources
|
||||
|
||||
The public `ble_log_src_t` ABI is frozen and its values are the on-wire
|
||||
source IDs of protocol v7 frames — the frame source byte carries the enum
|
||||
value directly, so existing decoders keep working:
|
||||
|
||||
```text
|
||||
0 INTERNAL
|
||||
1 CUSTOM
|
||||
2 LL_TASK
|
||||
3 LL_HCI
|
||||
4 LL_ISR
|
||||
5 HOST
|
||||
6 HCI
|
||||
7 ENCODE
|
||||
8 REDIR extension
|
||||
```
|
||||
|
||||
All non-INTERNAL sources share one 24-bit Global SN: it is consumed at API
|
||||
entry, so it totally orders log attempts — including equal-timestamp records
|
||||
from different sources — and every lost or rejected attempt leaves a gap
|
||||
in the sequence. Internal Snapshot frames carry their own separate
|
||||
sequence; a gap there counts skipped snapshots. Neither sequence is reset.
|
||||
Actual ISR and critical-section records carry `NON_YIELD` in source bit 7.
|
||||
|
||||
Controller-side HCI records are not emitted by BLE Log, and the controller no
|
||||
longer maintains its own internal LL HCI log. Host-side Bluedroid and NimBLE
|
||||
HCI capture (`CONFIG_BLE_LOG_HCI_LOG_ENABLED`) is the single HCI logging
|
||||
switch and the authoritative `HCI` stream for both Host and Controller
|
||||
traffic. Its direction bit continues to use HCI payload byte 0 bit 7; this is
|
||||
independent of the source metadata bit.
|
||||
|
||||
## Internal Snapshot
|
||||
|
||||
All BLE Log-owned Internal information is emitted as one fixed-layout frame
|
||||
from one dedicated 148-byte transport. Its logical frame length is 148 bytes.
|
||||
|
||||
The snapshot contains:
|
||||
|
||||
- reason flags (`INIT`, `PERIODIC`, `FLUSH`, `TS_VALID`);
|
||||
- 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).
|
||||
|
||||
A skipped periodic snapshot burns one snapshot SN instead: the gap in the
|
||||
snapshot sequence is the loss signal, and it is visible directly in the
|
||||
frame header without a dedicated payload field.
|
||||
|
||||
Each source statistic contains only:
|
||||
|
||||
```c
|
||||
#include "ble_log.h"
|
||||
uint32_t written_frame_cnt;
|
||||
uint32_t lost_frame_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. Core counts and the pool
|
||||
peak restart after a completed FLUSH; the Global SN and the snapshot
|
||||
sequence 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 snapshot is not an Anchor: it does not seal the shared pool and does not
|
||||
define a Log Segment 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);
|
||||
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);
|
||||
```
|
||||
|
||||
`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);
|
||||
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. 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. Each logical compression source uses a non-blocking
|
||||
trylock so its task-switch state follows commit order; a contending record is
|
||||
canceled and counted as lost.
|
||||
|
||||
```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);
|
||||
## 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` | target dependent | Host-side HCI capture |
|
||||
| `CONFIG_BLE_LOG_TS_ENABLED` | n | GPIO/LC timestamp synchronization |
|
||||
|
||||
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 v7 bytes, the consolidated Internal Snapshot,
|
||||
source/HCI metadata, 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.
|
||||
|
||||
@@ -11,12 +11,27 @@
|
||||
#include "freertos/FreeRTOS.h"
|
||||
#include "freertos/task.h"
|
||||
#include "sdkconfig.h"
|
||||
#include "ble_log_lbm_v2.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,61 +39,39 @@
|
||||
} \
|
||||
} 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;
|
||||
static ble_log_atomic_lock_t mesh_source_lock;
|
||||
#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;
|
||||
static ble_log_atomic_lock_t iso_source_lock;
|
||||
#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;
|
||||
static ble_log_atomic_lock_t host_source_lock;
|
||||
#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;
|
||||
static ble_log_atomic_lock_t nimble_source_lock;
|
||||
#endif
|
||||
|
||||
#if CONFIG_BLE_LOG_PRPH_TEST
|
||||
extern void ble_log_test_compression_after_lock_hook(uint8_t source)
|
||||
__attribute__((weak));
|
||||
#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;
|
||||
ble_log_atomic_lock_t *source_lock = NULL;
|
||||
uint16_t claim_len = 0;
|
||||
char * cur_handle = pcTaskGetName(NULL);
|
||||
|
||||
switch (source)
|
||||
@@ -86,25 +79,28 @@ int ble_compressed_log_cb_get(uint8_t source, ble_cp_log_buffer_mgmt_t **mgmt)
|
||||
#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;
|
||||
source_lock = &mesh_source_lock;
|
||||
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;
|
||||
source_lock = &iso_source_lock;
|
||||
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:
|
||||
claim_len = CONFIG_BLE_HOST_COMPRESSED_LOG_BUFFER_LEN;
|
||||
#if CONFIG_BT_BLUEDROID_ENABLED
|
||||
buffer_mgmt = BUF_MGMT_NAME(host);
|
||||
last_handle = &host_last_task_handle;
|
||||
source_lock = &host_source_lock;
|
||||
#elif CONFIG_BT_NIMBLE_ENABLED
|
||||
buffer_mgmt = BUF_MGMT_NAME(nimble);
|
||||
last_handle = &nimble_last_task_handle;
|
||||
source_lock = &nimble_source_lock;
|
||||
#endif
|
||||
break;
|
||||
#endif
|
||||
@@ -113,37 +109,59 @@ 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->source_lock = source_lock;
|
||||
mgmt->last_task_handle = last_handle;
|
||||
mgmt->current_task_handle = cur_handle;
|
||||
mgmt->task_switched = false;
|
||||
mgmt->buffer = ble_log_claim(BLE_LOG_SRC_ENCODE, claim_len, &mgmt->handle);
|
||||
if (!mgmt->buffer) {
|
||||
return -1;
|
||||
}
|
||||
if (!BLE_LOG_CAS_ACQUIRE(source_lock)) {
|
||||
ble_log_commit(mgmt->handle, 0);
|
||||
return -1;
|
||||
}
|
||||
#if CONFIG_BLE_LOG_PRPH_TEST
|
||||
if (ble_log_test_compression_after_lock_hook) {
|
||||
ble_log_test_compression_after_lock_hook(source);
|
||||
}
|
||||
#endif
|
||||
|
||||
return -1;
|
||||
if (ble_log_cp_push_u8(mgmt, source) != 0) {
|
||||
ble_log_commit(mgmt->handle, 0);
|
||||
BLE_LOG_CAS_RELEASE(source_lock);
|
||||
return -1;
|
||||
}
|
||||
char *previous_handle = __atomic_load_n(last_handle, __ATOMIC_RELAXED);
|
||||
if (previous_handle == NULL || previous_handle != cur_handle) {
|
||||
if (ble_log_cp_push_u8(
|
||||
mgmt, LOG_HEADER(LOG_TYPE_INFO, LOG_TYPE_INFO_TASK_SWITCH)) != 0) {
|
||||
ble_log_commit(mgmt->handle, 0);
|
||||
BLE_LOG_CAS_RELEASE(source_lock);
|
||||
return -1;
|
||||
}
|
||||
mgmt->task_switched = true;
|
||||
}
|
||||
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);
|
||||
if (mgmt->task_switched) {
|
||||
__atomic_store_n(mgmt->last_task_handle, mgmt->current_task_handle,
|
||||
__ATOMIC_RELAXED);
|
||||
}
|
||||
BLE_LOG_CAS_RELEASE(mgmt->source_lock);
|
||||
return 0;
|
||||
}
|
||||
|
||||
static inline int ble_compressed_log_abort(ble_cp_log_buffer_mgmt_t *mgmt)
|
||||
{
|
||||
ble_log_commit(mgmt->handle, 0);
|
||||
BLE_LOG_CAS_RELEASE(mgmt->source_lock);
|
||||
return 0;
|
||||
}
|
||||
|
||||
@@ -287,76 +305,72 @@ 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);
|
||||
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_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 */
|
||||
|
||||
+8
-77
@@ -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,9 +29,6 @@ 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
|
||||
@@ -87,32 +41,22 @@ enum {
|
||||
#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 */
|
||||
volatile uint32_t *source_lock;
|
||||
char **last_task_handle;
|
||||
char *current_task_handle;
|
||||
bool task_switched;
|
||||
} 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 +126,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 */
|
||||
|
||||
@@ -33,7 +33,7 @@
|
||||
#define BLE_LOG_WAIT_TIMEOUT_TICKS pdMS_TO_TICKS(1000)
|
||||
|
||||
/* Single-instruction clock read; a function would add an IRAM call site. */
|
||||
#define ble_log_timestamp_now() ((uint32_t)esp_timer_get_time())
|
||||
#define BLE_LOG_TIMESTAMP_NOW() ((uint32_t)esp_timer_get_time())
|
||||
|
||||
/* ------------------------------- */
|
||||
/* Global Pool Context */
|
||||
@@ -196,7 +196,7 @@ ble_log_pool_publish_open_and_unlock(ble_log_prph_trans_t *trans)
|
||||
BLE_LOG_ATOMIC_STORE_RELAXED(trans->state, BLE_LOG_TRANS_STATE_OPEN);
|
||||
/* The following lock release publishes both state and frame data. */
|
||||
__atomic_fetch_or(&g_pool.open_bitmap, BIT(trans->id), __ATOMIC_RELAXED);
|
||||
ble_log_cas_release(&trans->atomic_lock);
|
||||
BLE_LOG_CAS_RELEASE(&trans->atomic_lock);
|
||||
ble_log_pool_notify_waiter(trans->id);
|
||||
}
|
||||
|
||||
@@ -253,7 +253,7 @@ BLE_LOG_IRAM_ATTR void ble_log_pool_seal_and_send(ble_log_prph_trans_t *trans)
|
||||
|
||||
/* Release the lock BEFORE submitting. The buffer is now in no bitmap and
|
||||
* is SENDING, so no other writer can find it. */
|
||||
ble_log_cas_release(&trans->atomic_lock);
|
||||
BLE_LOG_CAS_RELEASE(&trans->atomic_lock);
|
||||
ble_log_rt_submit_trans(trans);
|
||||
}
|
||||
|
||||
@@ -281,12 +281,12 @@ ble_log_prph_trans_t *ble_log_pool_try_claim_from(volatile uint32_t *bitmap,
|
||||
}
|
||||
|
||||
ble_log_prph_trans_t *trans = g_pool.trans[id];
|
||||
if (!ble_log_cas_acquire(&trans->atomic_lock)) {
|
||||
if (!BLE_LOG_CAS_ACQUIRE(&trans->atomic_lock)) {
|
||||
continue;
|
||||
}
|
||||
if (BLE_LOG_ATOMIC_LOAD_RELAXED(trans->state) != expected_state) {
|
||||
/* The bitmap is only a hint; another owner may have changed state. */
|
||||
ble_log_cas_release(&trans->atomic_lock);
|
||||
BLE_LOG_CAS_RELEASE(&trans->atomic_lock);
|
||||
continue;
|
||||
}
|
||||
|
||||
@@ -323,7 +323,7 @@ ble_log_prph_trans_t *ble_log_pool_try_claim_available(uint32_t frame_len, bool
|
||||
uint8_t open_id = (uint8_t)BLE_LOG_ATOMIC_LOAD_RELAXED(g_pool.open_cursor);
|
||||
if (open_domain & BIT(open_id)) {
|
||||
ble_log_prph_trans_t *open_trans = g_pool.trans[open_id];
|
||||
if (ble_log_cas_acquire(&open_trans->atomic_lock)) {
|
||||
if (BLE_LOG_CAS_ACQUIRE(&open_trans->atomic_lock)) {
|
||||
if (BLE_LOG_ATOMIC_LOAD_RELAXED(open_trans->state) == BLE_LOG_TRANS_STATE_OPEN) {
|
||||
if (BLE_LOG_TRANS_FREE_SPACE(open_trans) >= frame_len) {
|
||||
ble_log_pool_bitmap_clear(&g_pool.open_bitmap, open_id);
|
||||
@@ -331,7 +331,7 @@ ble_log_prph_trans_t *ble_log_pool_try_claim_available(uint32_t frame_len, bool
|
||||
}
|
||||
ble_log_pool_seal_and_send(open_trans); /* releases the lock */
|
||||
} else {
|
||||
ble_log_cas_release(&open_trans->atomic_lock);
|
||||
BLE_LOG_CAS_RELEASE(&open_trans->atomic_lock);
|
||||
}
|
||||
}
|
||||
}
|
||||
@@ -479,7 +479,7 @@ uint8_t *ble_log_claim(ble_log_src_t src_code, size_t max_len, uint32_t *handle)
|
||||
uint32_t frame_sn = BLE_LOG_GET_GLOBAL_SN();
|
||||
|
||||
/* The timestamp is the log occurrence time, before pool contention. */
|
||||
uint32_t timestamp = ble_log_timestamp_now();
|
||||
uint32_t timestamp = BLE_LOG_TIMESTAMP_NOW();
|
||||
bool non_yield = !xPortCanYield() ||
|
||||
xTaskGetSchedulerState() != taskSCHEDULER_RUNNING;
|
||||
size_t payload_capacity = sizeof(timestamp) + max_len;
|
||||
@@ -535,7 +535,7 @@ void ble_log_commit(uint32_t handle, size_t actual_len)
|
||||
if (trans->pos == 0) {
|
||||
BLE_LOG_ATOMIC_STORE_RELEASE(trans->state, BLE_LOG_TRANS_STATE_FREE);
|
||||
ble_log_pool_bitmap_set(&g_pool.free_bitmap, trans->id);
|
||||
ble_log_cas_release(&trans->atomic_lock);
|
||||
BLE_LOG_CAS_RELEASE(&trans->atomic_lock);
|
||||
ble_log_pool_notify_waiter(trans->id);
|
||||
} else {
|
||||
ble_log_pool_publish_open_and_unlock(trans);
|
||||
@@ -835,15 +835,15 @@ bool ble_log_internal_snapshot(uint16_t reason_flags,
|
||||
/* Capture the complete occurrence sample before any dedicated-buffer
|
||||
* drain or wait. Without a TS sync sample, esp_ts comes from the frame
|
||||
* timestamp and os_ts from the current tick. */
|
||||
uint32_t timestamp = ts_info ? ts_info->esp_ts : ble_log_timestamp_now();
|
||||
uint32_t timestamp = ts_info ? ts_info->esp_ts : BLE_LOG_TIMESTAMP_NOW();
|
||||
TickType_t start_tick = xTaskGetTickCount();
|
||||
for (;;) {
|
||||
if (ble_log_cas_acquire(&internal_trans->atomic_lock)) {
|
||||
if (BLE_LOG_CAS_ACQUIRE(&internal_trans->atomic_lock)) {
|
||||
if (BLE_LOG_ATOMIC_LOAD_RELAXED(internal_trans->state) ==
|
||||
BLE_LOG_TRANS_STATE_FREE) {
|
||||
break;
|
||||
}
|
||||
ble_log_cas_release(&internal_trans->atomic_lock);
|
||||
BLE_LOG_CAS_RELEASE(&internal_trans->atomic_lock);
|
||||
}
|
||||
if (!required ||
|
||||
(xTaskGetTickCount() - start_tick) >= BLE_LOG_WAIT_TIMEOUT_TICKS) {
|
||||
@@ -885,7 +885,7 @@ bool ble_log_internal_snapshot(uint16_t reason_flags,
|
||||
internal_trans->pos = BLE_LOG_INTERNAL_FRAME_LEN;
|
||||
BLE_LOG_ATOMIC_STORE_RELAXED(internal_trans->state,
|
||||
BLE_LOG_TRANS_STATE_SENDING);
|
||||
ble_log_cas_release(&internal_trans->atomic_lock);
|
||||
BLE_LOG_CAS_RELEASE(&internal_trans->atomic_lock);
|
||||
ble_log_rt_submit_trans(internal_trans);
|
||||
BLE_LOG_REF_COUNT_RELEASE(&lbm_ref_count);
|
||||
return true;
|
||||
@@ -905,14 +905,14 @@ BLE_LOG_STATIC bool ble_log_pool_flush_all_trans(void)
|
||||
* current frame copy. Seal every remaining OPEN transport. */
|
||||
for (int id = 0; id < BLE_LOG_POOL_TRANS_CNT; id++) {
|
||||
ble_log_prph_trans_t *trans = g_pool.trans[id];
|
||||
while (!ble_log_cas_acquire(&trans->atomic_lock)) {
|
||||
while (!BLE_LOG_CAS_ACQUIRE(&trans->atomic_lock)) {
|
||||
}
|
||||
if (BLE_LOG_ATOMIC_LOAD_RELAXED(trans->state) == BLE_LOG_TRANS_STATE_OPEN &&
|
||||
trans->pos > 0) {
|
||||
ble_log_pool_bitmap_clear(&g_pool.open_bitmap, id);
|
||||
ble_log_pool_seal_and_send(trans); /* releases the lock */
|
||||
} else {
|
||||
ble_log_cas_release(&trans->atomic_lock);
|
||||
BLE_LOG_CAS_RELEASE(&trans->atomic_lock);
|
||||
}
|
||||
}
|
||||
|
||||
@@ -941,14 +941,14 @@ void ble_log_lbm_flush_open_transports(void)
|
||||
continue;
|
||||
}
|
||||
ble_log_prph_trans_t *trans = g_pool.trans[id];
|
||||
if (!ble_log_cas_acquire(&trans->atomic_lock)) {
|
||||
if (!BLE_LOG_CAS_ACQUIRE(&trans->atomic_lock)) {
|
||||
continue;
|
||||
}
|
||||
if (BLE_LOG_ATOMIC_LOAD_RELAXED(trans->state) == BLE_LOG_TRANS_STATE_OPEN &&
|
||||
trans->pos > 0) {
|
||||
ble_log_pool_seal_and_send(trans);
|
||||
} else {
|
||||
ble_log_cas_release(&trans->atomic_lock);
|
||||
BLE_LOG_CAS_RELEASE(&trans->atomic_lock);
|
||||
}
|
||||
}
|
||||
|
||||
@@ -1096,7 +1096,7 @@ bool ble_log_write_hex(ble_log_src_t src_code, const uint8_t *addr, size_t len)
|
||||
bool is_isr = BLE_LOG_IN_ISR();
|
||||
bool can_yield = !is_isr && xPortCanYield() &&
|
||||
xTaskGetSchedulerState() == taskSCHEDULER_RUNNING;
|
||||
uint32_t timestamp = ble_log_timestamp_now();
|
||||
uint32_t timestamp = BLE_LOG_TIMESTAMP_NOW();
|
||||
size_t payload_len = sizeof(timestamp) + len;
|
||||
ble_log_prph_trans_t *trans =
|
||||
ble_log_pool_acquire(payload_len, !can_yield, false);
|
||||
|
||||
@@ -80,9 +80,9 @@ extern void esp_panic_handler_feed_wdts(void);
|
||||
/* INLINE */
|
||||
/* 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) \
|
||||
#define BLE_LOG_CAS_ACQUIRE(cas_lock) \
|
||||
(__atomic_exchange_n((cas_lock), 1, __ATOMIC_ACQUIRE) == 0)
|
||||
#define ble_log_cas_release(cas_lock) \
|
||||
#define BLE_LOG_CAS_RELEASE(cas_lock) \
|
||||
__atomic_store_n((cas_lock), 0, __ATOMIC_RELEASE)
|
||||
|
||||
#define BLE_LOG_VERSION (7)
|
||||
|
||||
@@ -28,9 +28,11 @@ 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 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 cost of a
|
||||
failed (dropped) write.
|
||||
failed (dropped) write 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,
|
||||
@@ -35,8 +35,10 @@ bool test_ble_log_walk_frames(const uint8_t *data, size_t len,
|
||||
}
|
||||
|
||||
if (observer) {
|
||||
uint8_t source_meta = head.frame_meta & 0xff;
|
||||
test_ble_log_frame_t frame = {
|
||||
.src = head.frame_meta & 0xff,
|
||||
.src = BLE_LOG_SRC_ID(source_meta),
|
||||
.source_meta = source_meta,
|
||||
.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,21 @@ 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;
|
||||
}
|
||||
} 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;
|
||||
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 =
|
||||
(snapshot.reason_flags & BLE_LOG_SNAPSHOT_REASON_FLUSH) != 0;
|
||||
}
|
||||
}
|
||||
|
||||
@@ -541,7 +540,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 +650,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 +743,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 +754,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 +770,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 +784,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 +829,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 +844,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 +868,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 +946,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,
|
||||
};
|
||||
@@ -982,7 +993,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 +1021,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,
|
||||
|
||||
@@ -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"
|
||||
|
||||
@@ -36,8 +36,10 @@ bool test_ble_log_walk_frames(const uint8_t *data, size_t len,
|
||||
}
|
||||
|
||||
if (observer) {
|
||||
uint8_t source_meta = head.frame_meta & 0xff;
|
||||
test_ble_log_frame_t frame = {
|
||||
.src = head.frame_meta & 0xff,
|
||||
.src = BLE_LOG_SRC_ID(source_meta),
|
||||
.source_meta = source_meta,
|
||||
.sn = head.frame_meta >> 8,
|
||||
.payload = data + offset + BLE_LOG_FRAME_HEAD_LEN,
|
||||
.payload_len = head.length,
|
||||
|
||||
+53
-32
@@ -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)
|
||||
|
||||
@@ -100,9 +99,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 ||
|
||||
@@ -275,18 +279,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;
|
||||
}
|
||||
}
|
||||
@@ -654,7 +661,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 +673,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 +685,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 +729,18 @@ 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 runtime hook 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. */
|
||||
TEST_ASSERT_TRUE(ble_log_internal_snapshot(
|
||||
BLE_LOG_SNAPSHOT_REASON_PERIODIC, NULL, true));
|
||||
TEST_ASSERT_TRUE(ble_log_rt_drain());
|
||||
|
||||
const int64_t deadline_us = esp_timer_get_time() +
|
||||
@@ -747,7 +762,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 +778,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 +786,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,8 +803,8 @@ 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);
|
||||
const int64_t join_deadline_us = esp_timer_get_time() +
|
||||
(int64_t)RT_JOIN_TIMEOUT_MS * 1000;
|
||||
@@ -799,6 +816,11 @@ 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. */
|
||||
@@ -806,9 +828,8 @@ TEST_CASE("BLE Log runtime survives deinit racing submissions",
|
||||
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,
|
||||
|
||||
@@ -7,12 +7,15 @@
|
||||
| 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-v7 framing and fixed Internal Snapshot ABI;
|
||||
- build, library, chip, and protocol versions inside the snapshot;
|
||||
- task and `NON_YIELD` source metadata 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;
|
||||
- periodic snapshot busy/loss behavior;
|
||||
- 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,
|
||||
@@ -35,8 +35,10 @@ bool test_ble_log_walk_frames(const uint8_t *data, size_t len,
|
||||
}
|
||||
|
||||
if (observer) {
|
||||
uint8_t source_meta = head.frame_meta & 0xff;
|
||||
test_ble_log_frame_t frame = {
|
||||
.src = head.frame_meta & 0xff,
|
||||
.src = BLE_LOG_SRC_ID(source_meta),
|
||||
.source_meta = source_meta,
|
||||
.sn = head.frame_meta >> 8,
|
||||
.payload = data + offset + BLE_LOG_FRAME_HEAD_LEN,
|
||||
.payload_len = head.length,
|
||||
|
||||
@@ -16,9 +16,13 @@
|
||||
#include "unity.h"
|
||||
|
||||
#include "ble_log.h"
|
||||
#include "ble_log_lbm_v2.h"
|
||||
#include "ble_log_prph_test.h"
|
||||
#include "ble_log_rt.h"
|
||||
#include "test_ble_log_main.h"
|
||||
#if CONFIG_BLE_HOST_COMPRESSED_LOG_ENABLE
|
||||
#include "log_compression/utils.h"
|
||||
#endif
|
||||
|
||||
#if !CONFIG_BLE_LOG_PRPH_TEST
|
||||
#error "BLE Log test app requires CONFIG_BLE_LOG_PRPH_TEST"
|
||||
@@ -35,6 +39,8 @@
|
||||
#define TEST_READ_BUF_SIZE (4096)
|
||||
#define TEST_READER_STACK_SIZE (3072)
|
||||
#define TEST_READER_PRIO (2)
|
||||
#define TEST_LIFECYCLE_STACK_SIZE (2048)
|
||||
#define TEST_LIFECYCLE_PRIO (3)
|
||||
|
||||
typedef struct {
|
||||
size_t version_info_count;
|
||||
@@ -49,6 +55,65 @@ typedef struct {
|
||||
} reader_ctx_t;
|
||||
|
||||
static uint8_t s_read_buf[TEST_READ_BUF_SIZE];
|
||||
static bool s_claim_hook_armed;
|
||||
static uint32_t s_stale_claim_handle;
|
||||
static volatile bool s_enable_hook_armed;
|
||||
static SemaphoreHandle_t s_enable_hook_entered;
|
||||
static SemaphoreHandle_t s_enable_hook_continue;
|
||||
static volatile bool s_disable_hook_armed;
|
||||
static SemaphoreHandle_t s_disable_hook_entered;
|
||||
static SemaphoreHandle_t s_disable_hook_continue;
|
||||
#if CONFIG_BLE_HOST_COMPRESSED_LOG_ENABLE
|
||||
static volatile bool s_compression_hook_armed;
|
||||
static SemaphoreHandle_t s_compression_hook_entered;
|
||||
static SemaphoreHandle_t s_compression_hook_continue;
|
||||
#endif
|
||||
|
||||
void ble_log_test_claim_pre_publish_hook(void);
|
||||
void ble_log_test_enable_before_lifecycle_lock_hook(void);
|
||||
void ble_log_test_disable_before_wake_hook(void);
|
||||
#if CONFIG_BLE_HOST_COMPRESSED_LOG_ENABLE
|
||||
void ble_log_test_compression_after_lock_hook(uint8_t source);
|
||||
extern int ble_log_compressed_hex_print(uint8_t source, uint32_t log_index,
|
||||
size_t args_cnt, ...);
|
||||
#endif
|
||||
|
||||
void ble_log_test_claim_pre_publish_hook(void)
|
||||
{
|
||||
if (s_claim_hook_armed) {
|
||||
/* A valid length exercises the state check on the still-OPEN
|
||||
* transport: a deleted check would frame stale claim metadata
|
||||
* (duplicate SN) on the wire. */
|
||||
ble_log_commit(s_stale_claim_handle, 1);
|
||||
}
|
||||
}
|
||||
|
||||
void ble_log_test_enable_before_lifecycle_lock_hook(void)
|
||||
{
|
||||
if (s_enable_hook_armed) {
|
||||
xSemaphoreGive(s_enable_hook_entered);
|
||||
xSemaphoreTake(s_enable_hook_continue, portMAX_DELAY);
|
||||
}
|
||||
}
|
||||
|
||||
void ble_log_test_disable_before_wake_hook(void)
|
||||
{
|
||||
if (s_disable_hook_armed) {
|
||||
xSemaphoreGive(s_disable_hook_entered);
|
||||
xSemaphoreTake(s_disable_hook_continue, portMAX_DELAY);
|
||||
}
|
||||
}
|
||||
|
||||
#if CONFIG_BLE_HOST_COMPRESSED_LOG_ENABLE
|
||||
void ble_log_test_compression_after_lock_hook(uint8_t source)
|
||||
{
|
||||
if (s_compression_hook_armed &&
|
||||
source == BLE_COMPRESSED_LOG_OUT_SOURCE_HOST) {
|
||||
xSemaphoreGive(s_compression_hook_entered);
|
||||
xSemaphoreTake(s_compression_hook_continue, portMAX_DELAY);
|
||||
}
|
||||
}
|
||||
#endif
|
||||
|
||||
/* A commit field is hex characters, zero-padded after a shorter value;
|
||||
* anything else (garbage, non-hex, zeros after data) is invalid. */
|
||||
@@ -83,14 +148,19 @@ static bool commit_is_zero(const uint8_t *commit, size_t len)
|
||||
static void capture_version_info_frame(const test_ble_log_frame_t *frame, void *ctx)
|
||||
{
|
||||
version_capture_t *capture = ctx;
|
||||
/* Every frame payload starts with a 4-byte timestamp prefix */
|
||||
if (frame->payload_len < sizeof(uint32_t)) {
|
||||
return;
|
||||
}
|
||||
const uint8_t *record = frame->payload + sizeof(uint32_t);
|
||||
size_t record_len = frame->payload_len - sizeof(uint32_t);
|
||||
|
||||
if (frame->src == BLE_LOG_SRC_INTERNAL &&
|
||||
record_len == sizeof(ble_log_version_info_t) &&
|
||||
record[0] == BLE_LOG_INT_SRC_VERSION_INFO) {
|
||||
memcpy(&capture->version_info, record, sizeof(capture->version_info));
|
||||
record_len == sizeof(ble_log_internal_snapshot_t) &&
|
||||
record[0] == BLE_LOG_INT_SRC_SNAPSHOT) {
|
||||
ble_log_internal_snapshot_t snapshot;
|
||||
memcpy(&snapshot, record, sizeof(snapshot));
|
||||
memcpy(&capture->version_info, &snapshot.version_info,
|
||||
sizeof(capture->version_info));
|
||||
capture->version_info_count++;
|
||||
}
|
||||
}
|
||||
@@ -114,6 +184,72 @@ static void test_reader_task(void *arg)
|
||||
vTaskDelete(NULL);
|
||||
}
|
||||
|
||||
typedef struct {
|
||||
size_t count;
|
||||
test_ble_log_frame_t frame;
|
||||
} golden_capture_t;
|
||||
|
||||
static void capture_golden_frame(const test_ble_log_frame_t *frame, void *ctx)
|
||||
{
|
||||
golden_capture_t *capture = ctx;
|
||||
capture->frame = *frame;
|
||||
capture->count++;
|
||||
}
|
||||
|
||||
TEST_CASE("BLE Log v7 framing matches golden bytes", "[ble_log][wire]")
|
||||
{
|
||||
static const uint8_t golden_frame[] = {
|
||||
0x05, 0x00, 0x87, 0xde, 0xc0, 0x00,
|
||||
0x78, 0x56, 0x34, 0x12, 0xab,
|
||||
0xf1, 0x12, 0x54, 0x88,
|
||||
};
|
||||
static const uint8_t golden_payload[] = {
|
||||
0x78, 0x56, 0x34, 0x12, 0xab,
|
||||
};
|
||||
|
||||
TEST_ASSERT_EQUAL_UINT8(7, BLE_LOG_VERSION);
|
||||
TEST_ASSERT_EQUAL_HEX8(0x80, BLE_LOG_SRC_FLAG_NON_YIELD);
|
||||
TEST_ASSERT_EQUAL_UINT8(1, BLE_LOG_SRC_CORE_FIRST);
|
||||
TEST_ASSERT_EQUAL_UINT8(7, BLE_LOG_SRC_CORE_COUNT);
|
||||
TEST_ASSERT_EQUAL_UINT8(7, BLE_LOG_SRC_ENCODE);
|
||||
TEST_ASSERT_EQUAL_UINT8(7, BLE_LOG_INT_SRC_VERSION_INFO);
|
||||
TEST_ASSERT_EQUAL_UINT8(8, BLE_LOG_INT_SRC_SNAPSHOT);
|
||||
TEST_ASSERT_EQUAL_size_t(8, sizeof(ble_log_source_stat_t));
|
||||
TEST_ASSERT_EQUAL_size_t(134, sizeof(ble_log_internal_snapshot_t));
|
||||
TEST_ASSERT_EQUAL_size_t(
|
||||
4, offsetof(ble_log_internal_snapshot_t, version_info));
|
||||
TEST_ASSERT_EQUAL_size_t(
|
||||
62, offsetof(ble_log_internal_snapshot_t, ts.lc_ts));
|
||||
TEST_ASSERT_EQUAL_size_t(
|
||||
66, offsetof(ble_log_internal_snapshot_t, ts.esp_ts));
|
||||
TEST_ASSERT_EQUAL_size_t(
|
||||
70, offsetof(ble_log_internal_snapshot_t, ts.os_ts));
|
||||
TEST_ASSERT_EQUAL_size_t(
|
||||
78, offsetof(ble_log_internal_snapshot_t, stats));
|
||||
TEST_ASSERT_EQUAL_UINT32(148, BLE_LOG_INTERNAL_FRAME_LEN);
|
||||
#if CONFIG_BLE_LOG_LL_ENABLED
|
||||
TEST_ASSERT_EQUAL_UINT8(4, BLE_LOG_LL_FLAG_HCI);
|
||||
TEST_ASSERT_EQUAL_UINT8(7, BLE_LOG_LL_FLAG_HCI_UPSTREAM);
|
||||
#endif
|
||||
TEST_ASSERT_EQUAL_HEX32(
|
||||
0x00c0de87, BLE_LOG_MAKE_FRAME_META(0x87, 0x00c0de));
|
||||
TEST_ASSERT_EQUAL_HEX32(
|
||||
0x00000007, BLE_LOG_MAKE_FRAME_META(0x07, 0x01000000));
|
||||
|
||||
golden_capture_t capture = {0};
|
||||
TEST_ASSERT_TRUE(test_ble_log_walk_frames(golden_frame,
|
||||
sizeof(golden_frame),
|
||||
capture_golden_frame,
|
||||
&capture));
|
||||
TEST_ASSERT_EQUAL_size_t(1, capture.count);
|
||||
TEST_ASSERT_EQUAL_UINT8(BLE_LOG_SRC_ENCODE, capture.frame.src);
|
||||
TEST_ASSERT_EQUAL_HEX8(0x87, capture.frame.source_meta);
|
||||
TEST_ASSERT_EQUAL_HEX32(0x00c0de, capture.frame.sn);
|
||||
TEST_ASSERT_EQUAL_size_t(sizeof(golden_payload), capture.frame.payload_len);
|
||||
TEST_ASSERT_EQUAL_MEMORY(golden_payload, capture.frame.payload,
|
||||
sizeof(golden_payload));
|
||||
}
|
||||
|
||||
TEST_CASE("BLE Log runtime hook reports build and chip versions", "[ble_log]")
|
||||
{
|
||||
static const uint8_t payload[TEST_PAYLOAD_LEN] = {0};
|
||||
@@ -128,12 +264,8 @@ TEST_CASE("BLE Log runtime hook reports build and chip versions", "[ble_log]")
|
||||
TEST_READER_PRIO, &reader));
|
||||
TEST_ASSERT_TRUE(ble_log_enable(true));
|
||||
|
||||
/* Transports are auto-submitted once full, which arms the defer alarm;
|
||||
* after the throttle window elapses, a hook pass writes the version frame
|
||||
* into the LBM and a later transport carries it out. ble_log_flush()
|
||||
* cannot be used here: it disables the module while waiting for the
|
||||
* transports to drain, so the hook frame written during the flush window
|
||||
* would be dropped. */
|
||||
/* A hook pass submits one consolidated Internal Snapshot containing the
|
||||
* version, statistics, utilization, and optional TS sample. */
|
||||
for (int round = 0; round < TEST_MAX_ROUNDS && ctx.capture.version_info_count == 0; round++) {
|
||||
vTaskDelay(pdMS_TO_TICKS(TEST_HOOK_SETTLE_MS));
|
||||
for (int i = 0; i < TEST_WRITES_PER_ROUND; i++) {
|
||||
@@ -187,3 +319,765 @@ TEST_CASE("BLE Log runtime hook reports build and chip versions", "[ble_log]")
|
||||
|
||||
vSemaphoreDelete(ctx.done);
|
||||
}
|
||||
|
||||
typedef struct {
|
||||
bool task_frame;
|
||||
bool non_yield_frame;
|
||||
bool hci_downstream_frame;
|
||||
bool hci_upstream_frame;
|
||||
bool claimed_frame;
|
||||
bool stale_protected_frame;
|
||||
int encode_frame_cnt;
|
||||
} frame_meta_capture_t;
|
||||
|
||||
static void capture_frame_meta(const test_ble_log_frame_t *frame, void *ctx)
|
||||
{
|
||||
frame_meta_capture_t *capture = ctx;
|
||||
if (frame->src == BLE_LOG_SRC_ENCODE) {
|
||||
capture->encode_frame_cnt++;
|
||||
}
|
||||
if (frame->payload_len < sizeof(uint32_t) + 1) {
|
||||
return;
|
||||
}
|
||||
|
||||
uint8_t marker = frame->payload[sizeof(uint32_t)];
|
||||
if (frame->src == BLE_LOG_SRC_CUSTOM && marker == 0x11) {
|
||||
capture->task_frame = !BLE_LOG_SRC_IS_NON_YIELD(frame->source_meta);
|
||||
} else if (frame->src == BLE_LOG_SRC_CUSTOM && marker == 0x22) {
|
||||
capture->non_yield_frame =
|
||||
BLE_LOG_SRC_IS_NON_YIELD(frame->source_meta);
|
||||
} else if (frame->src == BLE_LOG_SRC_HCI && marker == 0x01) {
|
||||
capture->hci_downstream_frame = true;
|
||||
} else if (frame->src == BLE_LOG_SRC_HCI && marker == 0x82) {
|
||||
capture->hci_upstream_frame = true;
|
||||
} else if (frame->src == BLE_LOG_SRC_ENCODE && marker == 0x33) {
|
||||
capture->claimed_frame = true;
|
||||
} else if (frame->src == BLE_LOG_SRC_ENCODE && marker == 0x44) {
|
||||
capture->stale_protected_frame = true;
|
||||
}
|
||||
}
|
||||
|
||||
TEST_CASE("BLE Log marks non-yield context and commits claimed payload",
|
||||
"[ble_log][lbm]")
|
||||
{
|
||||
const uint8_t task_marker = 0x11;
|
||||
const uint8_t critical_marker = 0x22;
|
||||
TEST_ASSERT_TRUE(ble_log_enable(true));
|
||||
ble_log_lbm_flush_open_trans();
|
||||
for (int round = 0; round < 2; round++) {
|
||||
TEST_ASSERT_TRUE(ble_log_rt_drain());
|
||||
while (ble_log_prph_test_read(s_read_buf, sizeof(s_read_buf),
|
||||
0, 0, NULL) > 0) {
|
||||
}
|
||||
}
|
||||
TEST_ASSERT_TRUE(ble_log_write_hex(BLE_LOG_SRC_CUSTOM,
|
||||
&task_marker, sizeof(task_marker)));
|
||||
|
||||
portMUX_TYPE mux = portMUX_INITIALIZER_UNLOCKED;
|
||||
portENTER_CRITICAL(&mux);
|
||||
bool critical_written = ble_log_write_hex(BLE_LOG_SRC_CUSTOM,
|
||||
&critical_marker,
|
||||
sizeof(critical_marker));
|
||||
portEXIT_CRITICAL(&mux);
|
||||
TEST_ASSERT_TRUE(critical_written);
|
||||
|
||||
uint8_t hci_type = 0x81;
|
||||
ble_log_write_hci(BLE_LOG_HCI_DOWNSTREAM, &hci_type, sizeof(hci_type));
|
||||
TEST_ASSERT_EQUAL_HEX8(0x81, hci_type);
|
||||
hci_type = 0x02;
|
||||
ble_log_write_hci(BLE_LOG_HCI_UPSTREAM, &hci_type, sizeof(hci_type));
|
||||
TEST_ASSERT_EQUAL_HEX8(0x02, hci_type);
|
||||
/* The HCI macro requires one writable type byte. Exercise invalid public
|
||||
* input at the validating API instead. */
|
||||
TEST_ASSERT_FALSE(ble_log_write_hex(BLE_LOG_SRC_HCI, NULL, 1));
|
||||
|
||||
uint32_t handle;
|
||||
uint8_t *claimed = ble_log_claim(BLE_LOG_SRC_ENCODE, 8, &handle);
|
||||
TEST_ASSERT_NOT_NULL(claimed);
|
||||
claimed[0] = 0x33;
|
||||
ble_log_commit(handle, 1);
|
||||
|
||||
/* Invoke the stale commit immediately before the next claim publishes
|
||||
* CLAIMED. It must see the prior OPEN state and leave the new claim
|
||||
* intact. */
|
||||
s_stale_claim_handle = handle;
|
||||
s_claim_hook_armed = true;
|
||||
uint32_t fresh_handle;
|
||||
claimed = ble_log_claim(BLE_LOG_SRC_ENCODE, 8, &fresh_handle);
|
||||
s_claim_hook_armed = false;
|
||||
TEST_ASSERT_NOT_NULL(claimed);
|
||||
TEST_ASSERT_NOT_EQUAL(handle, fresh_handle);
|
||||
/* The fresh claim is published: the same stale handle must now be
|
||||
* rejected by the generation check instead. A zero length mirrors a
|
||||
* stale abort, which would otherwise consume the fresh claim. */
|
||||
ble_log_commit(s_stale_claim_handle, 0);
|
||||
claimed[0] = 0x44;
|
||||
ble_log_commit(fresh_handle, 1);
|
||||
|
||||
ble_log_lbm_flush_open_transports();
|
||||
TEST_ASSERT_TRUE(ble_log_rt_drain());
|
||||
|
||||
frame_meta_capture_t capture = {0};
|
||||
for (int i = 0; i < BLE_LOG_TRANS_TOTAL_CNT; i++) {
|
||||
size_t len = ble_log_prph_test_read(s_read_buf, sizeof(s_read_buf),
|
||||
pdMS_TO_TICKS(TEST_READ_TIMEOUT_MS),
|
||||
0, NULL);
|
||||
if (!len) {
|
||||
break;
|
||||
}
|
||||
TEST_ASSERT_TRUE(test_ble_log_walk_frames(s_read_buf, len,
|
||||
capture_frame_meta,
|
||||
&capture));
|
||||
}
|
||||
|
||||
TEST_ASSERT_TRUE(capture.task_frame);
|
||||
TEST_ASSERT_TRUE(capture.non_yield_frame);
|
||||
TEST_ASSERT_TRUE(capture.hci_downstream_frame);
|
||||
TEST_ASSERT_TRUE(capture.hci_upstream_frame);
|
||||
TEST_ASSERT_TRUE(capture.claimed_frame);
|
||||
TEST_ASSERT_TRUE(capture.stale_protected_frame);
|
||||
/* Exactly the two committed claims: a stale commit that slipped past
|
||||
* the state or generation check would add or consume an ENCODE frame. */
|
||||
TEST_ASSERT_EQUAL(2, capture.encode_frame_cnt);
|
||||
}
|
||||
|
||||
#if CONFIG_BLE_HOST_COMPRESSED_LOG_ENABLE
|
||||
#define TEST_CP_INDEX_FIRST UINT16_C(0x601)
|
||||
#define TEST_CP_INDEX_DROPPED UINT16_C(0x602)
|
||||
#define TEST_CP_INDEX_SECOND UINT16_C(0x603)
|
||||
#define TEST_CP_TASK_SWITCH UINT8_C(0xc2)
|
||||
#define TEST_CP_ZERO_ARGS UINT8_C(0x40)
|
||||
|
||||
typedef struct {
|
||||
bool first_found;
|
||||
uint32_t first_sn;
|
||||
bool dropped_found;
|
||||
bool second_found;
|
||||
bool second_switched;
|
||||
uint32_t second_sn;
|
||||
bool third_found;
|
||||
bool third_switched;
|
||||
uint32_t third_sn;
|
||||
} compression_capture_t;
|
||||
|
||||
typedef struct {
|
||||
SemaphoreHandle_t committed;
|
||||
SemaphoreHandle_t exit;
|
||||
SemaphoreHandle_t exited;
|
||||
} compression_writer_ctx_t;
|
||||
|
||||
static void capture_compressed_frame(const test_ble_log_frame_t *frame,
|
||||
void *ctx)
|
||||
{
|
||||
compression_capture_t *capture = ctx;
|
||||
if (frame->src != BLE_LOG_SRC_ENCODE ||
|
||||
frame->payload_len < sizeof(uint32_t) + 4) {
|
||||
return;
|
||||
}
|
||||
|
||||
const uint8_t *record = frame->payload + sizeof(uint32_t);
|
||||
size_t offset = 0;
|
||||
if (record[offset++] != BLE_COMPRESSED_LOG_OUT_SOURCE_HOST) {
|
||||
return;
|
||||
}
|
||||
size_t record_len = frame->payload_len - sizeof(uint32_t);
|
||||
bool switched = record[offset] == TEST_CP_TASK_SWITCH;
|
||||
offset += switched;
|
||||
if (record_len - offset < 3 || record[offset++] != TEST_CP_ZERO_ARGS) {
|
||||
return;
|
||||
}
|
||||
uint16_t log_index;
|
||||
memcpy(&log_index, record + offset, sizeof(log_index));
|
||||
|
||||
if (log_index == TEST_CP_INDEX_FIRST) {
|
||||
capture->first_found = true;
|
||||
capture->first_sn = frame->sn;
|
||||
} else if (log_index == TEST_CP_INDEX_DROPPED) {
|
||||
capture->dropped_found = true;
|
||||
} else if (log_index == TEST_CP_INDEX_SECOND) {
|
||||
capture->second_found = true;
|
||||
capture->second_switched = switched;
|
||||
capture->second_sn = frame->sn;
|
||||
} else if (log_index == TEST_CP_INDEX_SECOND + 1) {
|
||||
capture->third_found = true;
|
||||
capture->third_switched = switched;
|
||||
capture->third_sn = frame->sn;
|
||||
}
|
||||
}
|
||||
|
||||
static void compression_writer_task(void *arg)
|
||||
{
|
||||
compression_writer_ctx_t *ctx = arg;
|
||||
ble_log_compressed_hex_print(BLE_COMPRESSED_LOG_OUT_SOURCE_HOST,
|
||||
TEST_CP_INDEX_SECOND, 0);
|
||||
xSemaphoreGive(ctx->committed);
|
||||
xSemaphoreTake(ctx->exit, portMAX_DELAY);
|
||||
xSemaphoreGive(ctx->exited);
|
||||
vTaskDelete(NULL);
|
||||
}
|
||||
|
||||
TEST_CASE("BLE Log serializes task context per compression source",
|
||||
"[ble_log][compression]")
|
||||
{
|
||||
TEST_ASSERT_TRUE(ble_log_enable(true));
|
||||
ble_log_lbm_flush_open_transports();
|
||||
for (int round = 0; round < 2; round++) {
|
||||
TEST_ASSERT_TRUE(ble_log_rt_drain());
|
||||
while (ble_log_prph_test_read(s_read_buf, sizeof(s_read_buf),
|
||||
0, 0, NULL) > 0) {
|
||||
}
|
||||
}
|
||||
|
||||
ble_log_compressed_hex_print(BLE_COMPRESSED_LOG_OUT_SOURCE_HOST,
|
||||
TEST_CP_INDEX_FIRST, 0);
|
||||
|
||||
s_compression_hook_entered = xSemaphoreCreateBinary();
|
||||
s_compression_hook_continue = xSemaphoreCreateBinary();
|
||||
compression_writer_ctx_t writer = {
|
||||
.committed = xSemaphoreCreateBinary(),
|
||||
.exit = xSemaphoreCreateBinary(),
|
||||
.exited = xSemaphoreCreateBinary(),
|
||||
};
|
||||
TEST_ASSERT_NOT_NULL(s_compression_hook_entered);
|
||||
TEST_ASSERT_NOT_NULL(s_compression_hook_continue);
|
||||
TEST_ASSERT_NOT_NULL(writer.committed);
|
||||
TEST_ASSERT_NOT_NULL(writer.exit);
|
||||
TEST_ASSERT_NOT_NULL(writer.exited);
|
||||
|
||||
s_compression_hook_armed = true;
|
||||
TEST_ASSERT_EQUAL(
|
||||
pdTRUE,
|
||||
xTaskCreate(compression_writer_task, "ble_log_cp",
|
||||
TEST_LIFECYCLE_STACK_SIZE, &writer,
|
||||
TEST_LIFECYCLE_PRIO, NULL));
|
||||
TEST_ASSERT_TRUE(xSemaphoreTake(s_compression_hook_entered,
|
||||
pdMS_TO_TICKS(1000)));
|
||||
|
||||
/* This call claims pool space but fails the per-source trylock. It must
|
||||
* cancel immediately, count one lost ENCODE SN, and leave task state to
|
||||
* the lock owner. */
|
||||
ble_log_compressed_hex_print(BLE_COMPRESSED_LOG_OUT_SOURCE_HOST,
|
||||
TEST_CP_INDEX_DROPPED, 0);
|
||||
xSemaphoreGive(s_compression_hook_continue);
|
||||
TEST_ASSERT_TRUE(xSemaphoreTake(writer.committed,
|
||||
pdMS_TO_TICKS(1000)));
|
||||
s_compression_hook_armed = false;
|
||||
|
||||
ble_log_compressed_hex_print(BLE_COMPRESSED_LOG_OUT_SOURCE_HOST,
|
||||
TEST_CP_INDEX_SECOND + 1, 0);
|
||||
xSemaphoreGive(writer.exit);
|
||||
TEST_ASSERT_TRUE(xSemaphoreTake(writer.exited, pdMS_TO_TICKS(1000)));
|
||||
|
||||
ble_log_lbm_flush_open_transports();
|
||||
TEST_ASSERT_TRUE(ble_log_rt_drain());
|
||||
compression_capture_t capture = {0};
|
||||
for (int i = 0; i < BLE_LOG_TRANS_TOTAL_CNT; i++) {
|
||||
size_t len = ble_log_prph_test_read(
|
||||
s_read_buf, sizeof(s_read_buf), pdMS_TO_TICKS(TEST_READ_TIMEOUT_MS),
|
||||
0, NULL);
|
||||
if (!len) {
|
||||
break;
|
||||
}
|
||||
TEST_ASSERT_TRUE(test_ble_log_walk_frames(
|
||||
s_read_buf, len, capture_compressed_frame, &capture));
|
||||
}
|
||||
|
||||
TEST_ASSERT_TRUE(capture.first_found);
|
||||
TEST_ASSERT_FALSE(capture.dropped_found);
|
||||
TEST_ASSERT_TRUE(capture.second_found);
|
||||
TEST_ASSERT_TRUE(capture.second_switched);
|
||||
TEST_ASSERT_TRUE(capture.third_found);
|
||||
TEST_ASSERT_TRUE(capture.third_switched);
|
||||
/* The blocked writer claims its SN before taking the compression lock;
|
||||
* the rejected contender burns the following SN. */
|
||||
TEST_ASSERT_EQUAL_HEX32((capture.first_sn + 1) & 0x00ffffffU,
|
||||
capture.second_sn);
|
||||
TEST_ASSERT_EQUAL_HEX32((capture.second_sn + 2) & 0x00ffffffU,
|
||||
capture.third_sn);
|
||||
|
||||
vSemaphoreDelete(writer.committed);
|
||||
vSemaphoreDelete(writer.exit);
|
||||
vSemaphoreDelete(writer.exited);
|
||||
vSemaphoreDelete(s_compression_hook_entered);
|
||||
vSemaphoreDelete(s_compression_hook_continue);
|
||||
s_compression_hook_entered = NULL;
|
||||
s_compression_hook_continue = NULL;
|
||||
}
|
||||
#endif /* CONFIG_BLE_HOST_COMPRESSED_LOG_ENABLE */
|
||||
|
||||
typedef struct {
|
||||
ble_log_src_t src;
|
||||
uint8_t marker;
|
||||
bool found;
|
||||
uint32_t sn;
|
||||
} sequence_capture_t;
|
||||
|
||||
typedef struct {
|
||||
sequence_capture_t *captures;
|
||||
size_t count;
|
||||
} sequence_capture_set_t;
|
||||
|
||||
static void capture_sequence_frame(const test_ble_log_frame_t *frame, void *ctx)
|
||||
{
|
||||
sequence_capture_set_t *set = ctx;
|
||||
bool is_ll = frame->src == BLE_LOG_SRC_LL_TASK ||
|
||||
frame->src == BLE_LOG_SRC_LL_ISR;
|
||||
size_t marker_offset = is_ll ? 0 : sizeof(uint32_t);
|
||||
/* LL payloads already carry the controller's LC timestamp; unlike the
|
||||
* other sources, they must not gain an ESP timestamp prefix. */
|
||||
if (frame->payload_len != marker_offset + 1) {
|
||||
return;
|
||||
}
|
||||
|
||||
uint8_t marker = frame->payload[marker_offset];
|
||||
for (size_t i = 0; i < set->count; i++) {
|
||||
sequence_capture_t *capture = &set->captures[i];
|
||||
if (frame->src == capture->src && marker == capture->marker) {
|
||||
capture->found = true;
|
||||
capture->sn = frame->sn;
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
static void read_sequence_frames(sequence_capture_t *captures, size_t count)
|
||||
{
|
||||
sequence_capture_set_t set = {
|
||||
.captures = captures,
|
||||
.count = count,
|
||||
};
|
||||
for (int i = 0; i < BLE_LOG_TRANS_TOTAL_CNT; i++) {
|
||||
size_t len = ble_log_prph_test_read(
|
||||
s_read_buf, sizeof(s_read_buf), pdMS_TO_TICKS(TEST_READ_TIMEOUT_MS),
|
||||
0, NULL);
|
||||
if (!len) {
|
||||
break;
|
||||
}
|
||||
TEST_ASSERT_TRUE(test_ble_log_walk_frames(
|
||||
s_read_buf, len, capture_sequence_frame, &set));
|
||||
}
|
||||
}
|
||||
|
||||
static void auto_recycle_noop(void *ctx)
|
||||
{
|
||||
(void)ctx;
|
||||
}
|
||||
|
||||
TEST_CASE("BLE Log preserves LL payload and rejects oversized records",
|
||||
"[ble_log][lbm][wire]")
|
||||
{
|
||||
enum {
|
||||
CUSTOM_BEFORE,
|
||||
CUSTOM_OVERSIZED,
|
||||
CUSTOM_AFTER,
|
||||
#if CONFIG_BLE_LOG_LL_ENABLED
|
||||
LL_BEFORE,
|
||||
LL_PRIMARY_OVERSIZED,
|
||||
LL_APPEND_OVERSIZED,
|
||||
LL_AFTER,
|
||||
#endif
|
||||
SEQUENCE_CAPTURE_COUNT,
|
||||
};
|
||||
static uint8_t custom_oversized_payload[
|
||||
BLE_LOG_MAX_PAYLOAD_LEN - sizeof(uint32_t) + 1];
|
||||
#if CONFIG_BLE_LOG_LL_ENABLED
|
||||
static uint8_t ll_oversized_payload[BLE_LOG_MAX_PAYLOAD_LEN + 1];
|
||||
static uint8_t ll_oversized_append[BLE_LOG_MAX_PAYLOAD_LEN];
|
||||
#endif
|
||||
const uint8_t custom_before = 0x61;
|
||||
const uint8_t custom_oversized = 0x62;
|
||||
const uint8_t custom_after = 0x63;
|
||||
#if CONFIG_BLE_LOG_LL_ENABLED
|
||||
const uint8_t ll_before = 0x64;
|
||||
const uint8_t ll_primary_oversized = 0x65;
|
||||
const uint8_t ll_append_oversized = 0x66;
|
||||
const uint8_t ll_after = 0x67;
|
||||
#endif
|
||||
sequence_capture_t captures[SEQUENCE_CAPTURE_COUNT] = {
|
||||
[CUSTOM_BEFORE] = {.src = BLE_LOG_SRC_CUSTOM, .marker = custom_before},
|
||||
[CUSTOM_OVERSIZED] = {
|
||||
.src = BLE_LOG_SRC_CUSTOM,
|
||||
.marker = custom_oversized,
|
||||
},
|
||||
[CUSTOM_AFTER] = {.src = BLE_LOG_SRC_CUSTOM, .marker = custom_after},
|
||||
#if CONFIG_BLE_LOG_LL_ENABLED
|
||||
[LL_BEFORE] = {.src = BLE_LOG_SRC_LL_TASK, .marker = ll_before},
|
||||
[LL_PRIMARY_OVERSIZED] = {
|
||||
.src = BLE_LOG_SRC_LL_TASK,
|
||||
.marker = ll_primary_oversized,
|
||||
},
|
||||
[LL_APPEND_OVERSIZED] = {
|
||||
.src = BLE_LOG_SRC_LL_TASK,
|
||||
.marker = ll_append_oversized,
|
||||
},
|
||||
[LL_AFTER] = {.src = BLE_LOG_SRC_LL_TASK, .marker = ll_after},
|
||||
#endif
|
||||
};
|
||||
|
||||
TEST_ASSERT_TRUE(ble_log_enable(true));
|
||||
ble_log_lbm_flush_open_transports();
|
||||
for (int round = 0; round < 2; round++) {
|
||||
TEST_ASSERT_TRUE(ble_log_rt_drain());
|
||||
while (ble_log_prph_test_read(s_read_buf, sizeof(s_read_buf),
|
||||
0, 0, NULL) > 0) {
|
||||
}
|
||||
}
|
||||
|
||||
TEST_ASSERT_TRUE(ble_log_write_hex(BLE_LOG_SRC_CUSTOM,
|
||||
&custom_before, sizeof(custom_before)));
|
||||
memset(custom_oversized_payload, 0, sizeof(custom_oversized_payload));
|
||||
custom_oversized_payload[0] = custom_oversized;
|
||||
TEST_ASSERT_FALSE(ble_log_write_hex(BLE_LOG_SRC_CUSTOM,
|
||||
custom_oversized_payload,
|
||||
sizeof(custom_oversized_payload)));
|
||||
TEST_ASSERT_TRUE(ble_log_write_hex(BLE_LOG_SRC_CUSTOM,
|
||||
&custom_after, sizeof(custom_after)));
|
||||
|
||||
#if CONFIG_BLE_LOG_LL_ENABLED
|
||||
ble_log_write_hex_ll(sizeof(ll_before), &ll_before, 0, NULL,
|
||||
BIT(BLE_LOG_LL_FLAG_TASK));
|
||||
memset(ll_oversized_payload, 0, sizeof(ll_oversized_payload));
|
||||
ll_oversized_payload[0] = ll_primary_oversized;
|
||||
ble_log_write_hex_ll(sizeof(ll_oversized_payload), ll_oversized_payload,
|
||||
0, NULL, BIT(BLE_LOG_LL_FLAG_TASK));
|
||||
memset(ll_oversized_append, 0, sizeof(ll_oversized_append));
|
||||
ble_log_write_hex_ll(sizeof(ll_append_oversized), &ll_append_oversized,
|
||||
sizeof(ll_oversized_append), ll_oversized_append,
|
||||
BIT(BLE_LOG_LL_FLAG_TASK));
|
||||
ble_log_write_hex_ll(sizeof(ll_after), &ll_after, 0, NULL,
|
||||
BIT(BLE_LOG_LL_FLAG_TASK));
|
||||
#endif
|
||||
|
||||
ble_log_lbm_flush_open_transports();
|
||||
TEST_ASSERT_TRUE(ble_log_rt_drain());
|
||||
read_sequence_frames(captures, SEQUENCE_CAPTURE_COUNT);
|
||||
|
||||
TEST_ASSERT_TRUE(captures[CUSTOM_BEFORE].found);
|
||||
TEST_ASSERT_FALSE(captures[CUSTOM_OVERSIZED].found);
|
||||
TEST_ASSERT_TRUE(captures[CUSTOM_AFTER].found);
|
||||
TEST_ASSERT_EQUAL_HEX32(
|
||||
(captures[CUSTOM_BEFORE].sn + 2) & 0x00ffffffU,
|
||||
captures[CUSTOM_AFTER].sn);
|
||||
#if CONFIG_BLE_LOG_LL_ENABLED
|
||||
TEST_ASSERT_TRUE(captures[LL_BEFORE].found);
|
||||
TEST_ASSERT_FALSE(captures[LL_PRIMARY_OVERSIZED].found);
|
||||
TEST_ASSERT_FALSE(captures[LL_APPEND_OVERSIZED].found);
|
||||
TEST_ASSERT_TRUE(captures[LL_AFTER].found);
|
||||
TEST_ASSERT_EQUAL_HEX32(
|
||||
(captures[LL_BEFORE].sn + 3) & 0x00ffffffU,
|
||||
captures[LL_AFTER].sn);
|
||||
#endif
|
||||
}
|
||||
|
||||
TEST_CASE("BLE Log flush preserves source-local sequence continuity",
|
||||
"[ble_log][wire]")
|
||||
{
|
||||
const uint8_t before_marker = 0x71;
|
||||
const uint8_t after_marker = 0x72;
|
||||
TEST_ASSERT_TRUE(ble_log_enable(true));
|
||||
ble_log_lbm_flush_open_transports();
|
||||
for (int round = 0; round < 2; round++) {
|
||||
TEST_ASSERT_TRUE(ble_log_rt_drain());
|
||||
while (ble_log_prph_test_read(s_read_buf, sizeof(s_read_buf),
|
||||
0, 0, NULL) > 0) {
|
||||
}
|
||||
}
|
||||
|
||||
TEST_ASSERT_TRUE(ble_log_write_hex(BLE_LOG_SRC_CUSTOM,
|
||||
&before_marker, sizeof(before_marker)));
|
||||
ble_log_lbm_flush_open_transports();
|
||||
TEST_ASSERT_TRUE(ble_log_rt_drain());
|
||||
sequence_capture_t before = {
|
||||
.src = BLE_LOG_SRC_CUSTOM,
|
||||
.marker = before_marker,
|
||||
};
|
||||
read_sequence_frames(&before, 1);
|
||||
TEST_ASSERT_TRUE(before.found);
|
||||
|
||||
/* The test peripheral normally recycles only when read. Auto-recycle lets
|
||||
* synchronous flush observe completion without a second reader task. */
|
||||
ble_log_prph_test_set_auto_recycle_hook(auto_recycle_noop, NULL);
|
||||
ble_log_flush();
|
||||
ble_log_prph_test_set_auto_recycle_hook(NULL, NULL);
|
||||
|
||||
TEST_ASSERT_TRUE(ble_log_write_hex(BLE_LOG_SRC_CUSTOM,
|
||||
&after_marker, sizeof(after_marker)));
|
||||
ble_log_lbm_flush_open_transports();
|
||||
TEST_ASSERT_TRUE(ble_log_rt_drain());
|
||||
sequence_capture_t after = {
|
||||
.src = BLE_LOG_SRC_CUSTOM,
|
||||
.marker = after_marker,
|
||||
};
|
||||
read_sequence_frames(&after, 1);
|
||||
TEST_ASSERT_TRUE(after.found);
|
||||
TEST_ASSERT_EQUAL_HEX32((before.sn + 1) & 0x00ffffffU, after.sn);
|
||||
}
|
||||
|
||||
#define SNAPSHOT_CAPTURE_MAX 8
|
||||
|
||||
typedef struct {
|
||||
uint32_t sn[SNAPSHOT_CAPTURE_MAX];
|
||||
int count;
|
||||
} snapshot_capture_t;
|
||||
|
||||
static void capture_snapshot_loss(const test_ble_log_frame_t *frame, void *ctx)
|
||||
{
|
||||
snapshot_capture_t *capture = ctx;
|
||||
if (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));
|
||||
if (snapshot.int_src_code == BLE_LOG_INT_SRC_SNAPSHOT &&
|
||||
(snapshot.reason_flags & BLE_LOG_SNAPSHOT_REASON_PERIODIC) &&
|
||||
capture->count < SNAPSHOT_CAPTURE_MAX) {
|
||||
capture->sn[capture->count++] = frame->sn;
|
||||
}
|
||||
}
|
||||
|
||||
TEST_CASE("BLE Log periodic snapshot fails fast while its transport is busy",
|
||||
"[ble_log][lbm]")
|
||||
{
|
||||
TEST_ASSERT_TRUE(ble_log_enable(true));
|
||||
ble_log_lbm_flush_open_transports();
|
||||
for (int round = 0; round < 2; round++) {
|
||||
TEST_ASSERT_TRUE(ble_log_rt_drain());
|
||||
while (ble_log_prph_test_read(s_read_buf, sizeof(s_read_buf),
|
||||
0, 0, NULL) > 0) {
|
||||
}
|
||||
}
|
||||
|
||||
TEST_ASSERT_TRUE(ble_log_enable(false));
|
||||
TEST_ASSERT_FALSE(ble_log_internal_snapshot(
|
||||
BLE_LOG_SNAPSHOT_REASON_PERIODIC, NULL, false));
|
||||
TEST_ASSERT_TRUE(ble_log_enable(true));
|
||||
|
||||
TEST_ASSERT_TRUE(ble_log_internal_snapshot(
|
||||
BLE_LOG_SNAPSHOT_REASON_PERIODIC, NULL, false));
|
||||
TEST_ASSERT_FALSE(ble_log_internal_snapshot(
|
||||
BLE_LOG_SNAPSHOT_REASON_PERIODIC, NULL, false));
|
||||
TEST_ASSERT_TRUE(ble_log_rt_drain());
|
||||
TEST_ASSERT_GREATER_THAN_size_t(
|
||||
0, ble_log_prph_test_read(s_read_buf, sizeof(s_read_buf),
|
||||
pdMS_TO_TICKS(TEST_READ_TIMEOUT_MS), 0, NULL));
|
||||
|
||||
TEST_ASSERT_TRUE(ble_log_internal_snapshot(
|
||||
BLE_LOG_SNAPSHOT_REASON_PERIODIC, NULL, false));
|
||||
TEST_ASSERT_TRUE(ble_log_rt_drain());
|
||||
|
||||
snapshot_capture_t capture = {0};
|
||||
for (int i = 0; i < BLE_LOG_TRANS_TOTAL_CNT; i++) {
|
||||
size_t len = ble_log_prph_test_read(
|
||||
s_read_buf, sizeof(s_read_buf), pdMS_TO_TICKS(TEST_READ_TIMEOUT_MS),
|
||||
0, NULL);
|
||||
if (!len) {
|
||||
break;
|
||||
}
|
||||
TEST_ASSERT_TRUE(test_ble_log_walk_frames(
|
||||
s_read_buf, len, capture_snapshot_loss, &capture));
|
||||
}
|
||||
/* The busy periodic attempt burned one snapshot SN: the gap in the
|
||||
* snapshot sequence is the loss signal. */
|
||||
TEST_ASSERT_GREATER_OR_EQUAL_INT(2, capture.count);
|
||||
bool gap_seen = false;
|
||||
for (int i = 1; i < capture.count; i++) {
|
||||
if (((capture.sn[i] - capture.sn[i - 1]) & 0x00ffffffU) >= 2) {
|
||||
gap_seen = true;
|
||||
}
|
||||
}
|
||||
TEST_ASSERT_TRUE(gap_seen);
|
||||
}
|
||||
|
||||
#if CONFIG_BLE_LOG_LL_ENABLED
|
||||
typedef struct {
|
||||
SemaphoreHandle_t started;
|
||||
SemaphoreHandle_t done;
|
||||
} waiter_ctx_t;
|
||||
|
||||
typedef struct {
|
||||
SemaphoreHandle_t done;
|
||||
bool result;
|
||||
} enable_ctx_t;
|
||||
|
||||
typedef struct {
|
||||
SemaphoreHandle_t started;
|
||||
SemaphoreHandle_t done;
|
||||
} deinit_ctx_t;
|
||||
|
||||
static void blocked_ll_writer_task(void *arg)
|
||||
{
|
||||
waiter_ctx_t *ctx = arg;
|
||||
static const uint8_t marker = 0x55;
|
||||
xSemaphoreGive(ctx->started);
|
||||
ble_log_write_hex_ll(sizeof(marker), &marker, 0, NULL,
|
||||
BIT(BLE_LOG_LL_FLAG_TASK));
|
||||
xSemaphoreGive(ctx->done);
|
||||
vTaskDelete(NULL);
|
||||
}
|
||||
|
||||
static void racing_enable_task(void *arg)
|
||||
{
|
||||
enable_ctx_t *ctx = arg;
|
||||
ctx->result = ble_log_enable(true);
|
||||
xSemaphoreGive(ctx->done);
|
||||
vTaskDelete(NULL);
|
||||
}
|
||||
|
||||
static void racing_disable_task(void *arg)
|
||||
{
|
||||
enable_ctx_t *ctx = arg;
|
||||
ctx->result = ble_log_enable(false);
|
||||
xSemaphoreGive(ctx->done);
|
||||
vTaskDelete(NULL);
|
||||
}
|
||||
|
||||
static void lifecycle_deinit_task(void *arg)
|
||||
{
|
||||
deinit_ctx_t *ctx = arg;
|
||||
xSemaphoreGive(ctx->started);
|
||||
ble_log_deinit();
|
||||
xSemaphoreGive(ctx->done);
|
||||
vTaskDelete(NULL);
|
||||
}
|
||||
|
||||
TEST_CASE("BLE Log deinit closes a parked LL writer before racing enable",
|
||||
"[ble_log][lbm]")
|
||||
{
|
||||
static const uint8_t full_payload[
|
||||
BLE_LOG_MAX_PAYLOAD_LEN - sizeof(uint32_t)] = {0};
|
||||
|
||||
TEST_ASSERT_TRUE(ble_log_enable(true));
|
||||
ble_log_lbm_flush_open_transports();
|
||||
TEST_ASSERT_TRUE(ble_log_rt_drain());
|
||||
while (ble_log_prph_test_read(s_read_buf, sizeof(s_read_buf), 0, 0, NULL) > 0) {
|
||||
}
|
||||
TEST_ASSERT_TRUE(ble_log_rt_drain());
|
||||
while (ble_log_prph_test_read(s_read_buf, sizeof(s_read_buf), 0, 0, NULL) > 0) {
|
||||
}
|
||||
|
||||
/* Keep every task-usable transport SENDING in the test peripheral. */
|
||||
for (int i = 0; i < BLE_LOG_POOL_SHARED_CNT; i++) {
|
||||
TEST_ASSERT_TRUE(ble_log_write_hex(BLE_LOG_SRC_CUSTOM, full_payload,
|
||||
sizeof(full_payload)));
|
||||
}
|
||||
static const uint8_t reserve_marker = 0x56;
|
||||
TEST_ASSERT_FALSE(ble_log_write_hex(BLE_LOG_SRC_CUSTOM,
|
||||
&reserve_marker,
|
||||
sizeof(reserve_marker)));
|
||||
uint32_t exhausted_handle;
|
||||
TEST_ASSERT_NULL(ble_log_claim(BLE_LOG_SRC_ENCODE, 1,
|
||||
&exhausted_handle));
|
||||
|
||||
portMUX_TYPE reserve_mux = portMUX_INITIALIZER_UNLOCKED;
|
||||
portENTER_CRITICAL(&reserve_mux);
|
||||
bool reserve_written = ble_log_write_hex(BLE_LOG_SRC_CUSTOM,
|
||||
&reserve_marker,
|
||||
sizeof(reserve_marker));
|
||||
portEXIT_CRITICAL(&reserve_mux);
|
||||
TEST_ASSERT_TRUE(reserve_written);
|
||||
|
||||
waiter_ctx_t waiter = {
|
||||
.started = xSemaphoreCreateBinary(),
|
||||
.done = xSemaphoreCreateBinary(),
|
||||
};
|
||||
TEST_ASSERT_NOT_NULL(waiter.started);
|
||||
TEST_ASSERT_NOT_NULL(waiter.done);
|
||||
TEST_ASSERT_EQUAL(pdTRUE,
|
||||
xTaskCreate(blocked_ll_writer_task, "ble_log_wait",
|
||||
TEST_LIFECYCLE_STACK_SIZE, &waiter,
|
||||
TEST_LIFECYCLE_PRIO, NULL));
|
||||
TEST_ASSERT_TRUE(xSemaphoreTake(waiter.started, pdMS_TO_TICKS(1000)));
|
||||
vTaskDelay(1);
|
||||
TEST_ASSERT_EQUAL(pdFALSE, xSemaphoreTake(waiter.done, 0));
|
||||
|
||||
s_enable_hook_entered = xSemaphoreCreateBinary();
|
||||
s_enable_hook_continue = xSemaphoreCreateBinary();
|
||||
TEST_ASSERT_NOT_NULL(s_enable_hook_entered);
|
||||
TEST_ASSERT_NOT_NULL(s_enable_hook_continue);
|
||||
s_enable_hook_armed = true;
|
||||
|
||||
enable_ctx_t enabler = {
|
||||
.done = xSemaphoreCreateBinary(),
|
||||
};
|
||||
TEST_ASSERT_NOT_NULL(enabler.done);
|
||||
TEST_ASSERT_EQUAL(pdTRUE,
|
||||
xTaskCreate(racing_enable_task, "ble_log_enable",
|
||||
TEST_LIFECYCLE_STACK_SIZE, &enabler,
|
||||
TEST_LIFECYCLE_PRIO, NULL));
|
||||
TEST_ASSERT_TRUE(xSemaphoreTake(s_enable_hook_entered,
|
||||
pdMS_TO_TICKS(1000)));
|
||||
|
||||
/* The enable task is paused immediately before the lifecycle lock. Close
|
||||
* and destroy the module, then let enable perform its locked recheck. */
|
||||
ble_log_deinit();
|
||||
TEST_ASSERT_TRUE(xSemaphoreTake(waiter.done, pdMS_TO_TICKS(1000)));
|
||||
xSemaphoreGive(s_enable_hook_continue);
|
||||
TEST_ASSERT_TRUE(xSemaphoreTake(enabler.done, pdMS_TO_TICKS(1000)));
|
||||
s_enable_hook_armed = false;
|
||||
TEST_ASSERT_FALSE(enabler.result);
|
||||
|
||||
vSemaphoreDelete(waiter.started);
|
||||
vSemaphoreDelete(waiter.done);
|
||||
vSemaphoreDelete(enabler.done);
|
||||
vSemaphoreDelete(s_enable_hook_entered);
|
||||
vSemaphoreDelete(s_enable_hook_continue);
|
||||
s_enable_hook_entered = NULL;
|
||||
s_enable_hook_continue = NULL;
|
||||
|
||||
TEST_ASSERT_TRUE(ble_log_init());
|
||||
}
|
||||
|
||||
TEST_CASE("BLE Log disable keeps waiter semaphore alive during deinit",
|
||||
"[ble_log][lbm]")
|
||||
{
|
||||
TEST_ASSERT_TRUE(ble_log_enable(true));
|
||||
s_disable_hook_entered = xSemaphoreCreateBinary();
|
||||
s_disable_hook_continue = xSemaphoreCreateBinary();
|
||||
TEST_ASSERT_NOT_NULL(s_disable_hook_entered);
|
||||
TEST_ASSERT_NOT_NULL(s_disable_hook_continue);
|
||||
s_disable_hook_armed = true;
|
||||
|
||||
enable_ctx_t disabler = {
|
||||
.done = xSemaphoreCreateBinary(),
|
||||
};
|
||||
deinit_ctx_t deinit = {
|
||||
.started = xSemaphoreCreateBinary(),
|
||||
.done = xSemaphoreCreateBinary(),
|
||||
};
|
||||
TEST_ASSERT_NOT_NULL(disabler.done);
|
||||
TEST_ASSERT_NOT_NULL(deinit.started);
|
||||
TEST_ASSERT_NOT_NULL(deinit.done);
|
||||
|
||||
TEST_ASSERT_EQUAL(pdTRUE,
|
||||
xTaskCreate(racing_disable_task, "ble_log_disable",
|
||||
TEST_LIFECYCLE_STACK_SIZE, &disabler,
|
||||
TEST_LIFECYCLE_PRIO, NULL));
|
||||
TEST_ASSERT_TRUE(xSemaphoreTake(s_disable_hook_entered,
|
||||
pdMS_TO_TICKS(1000)));
|
||||
TEST_ASSERT_EQUAL(pdTRUE,
|
||||
xTaskCreate(lifecycle_deinit_task, "ble_log_deinit",
|
||||
TEST_LIFECYCLE_STACK_SIZE, &deinit,
|
||||
TEST_LIFECYCLE_PRIO, NULL));
|
||||
TEST_ASSERT_TRUE(xSemaphoreTake(deinit.started, pdMS_TO_TICKS(1000)));
|
||||
TEST_ASSERT_EQUAL(pdFALSE,
|
||||
xSemaphoreTake(deinit.done, pdMS_TO_TICKS(20)));
|
||||
|
||||
xSemaphoreGive(s_disable_hook_continue);
|
||||
TEST_ASSERT_TRUE(xSemaphoreTake(disabler.done, pdMS_TO_TICKS(1000)));
|
||||
TEST_ASSERT_TRUE(xSemaphoreTake(deinit.done, pdMS_TO_TICKS(1000)));
|
||||
s_disable_hook_armed = false;
|
||||
TEST_ASSERT_TRUE(disabler.result);
|
||||
|
||||
vSemaphoreDelete(disabler.done);
|
||||
vSemaphoreDelete(deinit.started);
|
||||
vSemaphoreDelete(deinit.done);
|
||||
vSemaphoreDelete(s_disable_hook_entered);
|
||||
vSemaphoreDelete(s_disable_hook_continue);
|
||||
s_disable_hook_entered = NULL;
|
||||
s_disable_hook_continue = NULL;
|
||||
|
||||
TEST_ASSERT_TRUE(ble_log_init());
|
||||
}
|
||||
#endif /* CONFIG_BLE_LOG_LL_ENABLED */
|
||||
|
||||
Reference in New Issue
Block a user