Mirrors/esp-idf
1
0
Fork 0
mirror of https://github.com/espressif/esp-idf.git synced 2026-10-02 03:00:34 +03:00
Code Issues Packages Projects Releases Wiki Activity

test(ble_log): add dedicated runtime dispatch test app

Browse Source 
Extend the test peripheral with receipt timestamps and an auto-recycle
hook so runtime tests can observe handoff latency and sustain arrivals from
dispatch completion.

Add a standalone Unity app covering fixed first-submission deadlines,
callback-entry batch drain, shared ESP timer task fairness, periodic
timestamp light-sleep behavior, synchronous flush, dispatch latency,
deinit races, bounded inflight peaks, and timeout conversion at both
supported tick rates. Verify FIFO delivery and reject delayed-consumer and
extra-marker false positives.

Render BLE_LOG_RT_PERF lines in the performance log parser and
cross-reference the runtime and performance apps from their READMEs.
This commit is contained in:
Zhou Xiao
2026-08-27 16:16:38 +08:00
parent 620a3c90a9
commit 327016d1a3
16 changed files with 1175 additions and 13 deletions
Download Patch File Download Diff File Expand all files Collapse all files
components/bt/common/ble_log/src/internal_include/prph/ble_log_prph_test.h
+12 -2
View File
@@ -16,12 +16,22 @@
/* TYPEDEF */
typedef struct {
uint8_t *trans_buf;
int64_t received_at_us;
} ble_log_prph_trans_ctx_t;
/* Reads and releases one pending transport, returning the bytes copied.
typedef void (*ble_log_prph_test_auto_recycle_hook_t)(void *ctx);
/* Recycles transports immediately and calls hook instead of queueing them.
* This lets tests model a producer that refills the runtime queue while its
* dispatch callback is still running. */
void ble_log_prph_test_set_auto_recycle_hook(ble_log_prph_test_auto_recycle_hook_t hook,
void *ctx);
/* Reads and releases one pending transport, returning the bytes copied and
* optionally the time when the test peripheral received ownership.
* When bytes_per_second is non-zero the call blocks until the simulated
* link has transmitted the whole transport at that rate. */
size_t ble_log_prph_test_read(uint8_t *data, size_t len, TickType_t timeout,
uint32_t bytes_per_second);
uint32_t bytes_per_second, int64_t *received_at_us);
#endif /* __BLE_LOG_PRPH_TEST_H__ */
components/bt/common/ble_log/src/prph/ble_log_prph_test.c
+54 -2
View File
@@ -13,6 +13,7 @@
#include "esp_timer.h"
#include "freertos/queue.h"
#include "freertos/semphr.h"
#include "freertos/task.h"
/* VARIABLE */
static QueueHandle_t s_pending_trans;
@@ -21,6 +22,15 @@ static esp_timer_handle_t s_tx_timer;
static int64_t s_tx_deadline_us;
static uint32_t s_tx_rate;
typedef struct {
ble_log_prph_test_auto_recycle_hook_t hook;
void *ctx;
} ble_log_prph_test_hook_reg_t;
static ble_log_prph_test_hook_reg_t s_auto_recycle_slots[2];
static volatile uint32_t s_auto_recycle_idx;
static volatile uint32_t s_auto_recycle_busy;
static void test_tx_done(void *arg)
{
(void)arg;
@@ -50,6 +60,7 @@ bool ble_log_prph_init(size_t trans_cnt)
void ble_log_prph_deinit(void)
{
ble_log_prph_test_set_auto_recycle_hook(NULL, NULL);
s_tx_deadline_us = 0;
s_tx_rate = 0;
if (s_tx_timer) {
@@ -137,6 +148,21 @@ void ble_log_prph_trans_deinit(ble_log_prph_trans_t **trans)
* equivalent to a real peripheral's asynchronous tx_done callback. */
void ble_log_prph_send_trans(ble_log_prph_trans_t *trans)
{
ble_log_prph_trans_ctx_t *ctx = trans->ctx;
ctx->received_at_us = esp_timer_get_time();
__atomic_fetch_add(&s_auto_recycle_busy, 1, __ATOMIC_ACQUIRE);
uint32_t idx = __atomic_load_n(&s_auto_recycle_idx, __ATOMIC_ACQUIRE);
ble_log_prph_test_hook_reg_t reg = s_auto_recycle_slots[idx & 1];
if (reg.hook) {
trans->pos = 0;
ble_log_lbm_recycle_trans(trans);
reg.hook(reg.ctx);
__atomic_fetch_sub(&s_auto_recycle_busy, 1, __ATOMIC_RELEASE);
return;
}
__atomic_fetch_sub(&s_auto_recycle_busy, 1, __ATOMIC_RELEASE);
if (xQueueSend(s_pending_trans, &trans, 0) != pdTRUE) {
trans->pos = 0;
ble_log_lbm_recycle_trans(trans);
@@ -144,9 +170,31 @@ void ble_log_prph_send_trans(ble_log_prph_trans_t *trans)
}
}
size_t ble_log_prph_test_read(uint8_t *data, size_t len, TickType_t timeout,
uint32_t bytes_per_second)
void ble_log_prph_test_set_auto_recycle_hook(ble_log_prph_test_auto_recycle_hook_t hook,
void *ctx)
{
while (__atomic_load_n(&s_auto_recycle_busy, __ATOMIC_ACQUIRE) != 0) {
vTaskDelay(1);
}
uint32_t next = !__atomic_load_n(&s_auto_recycle_idx, __ATOMIC_RELAXED);
s_auto_recycle_slots[next].hook = hook;
s_auto_recycle_slots[next].ctx = ctx;
__atomic_store_n(&s_auto_recycle_idx, next, __ATOMIC_RELEASE);
if (!hook) {
while (__atomic_load_n(&s_auto_recycle_busy, __ATOMIC_ACQUIRE) != 0) {
vTaskDelay(1);
}
}
}
size_t ble_log_prph_test_read(uint8_t *data, size_t len, TickType_t timeout,
uint32_t bytes_per_second, int64_t *received_at_us)
{
if (received_at_us) {
*received_at_us = 0;
}
if (!data) {
return 0;
}
@@ -179,6 +227,10 @@ size_t ble_log_prph_test_read(uint8_t *data, size_t len, TickType_t timeout,
s_tx_rate = 0;
}
if (received_at_us) {
ble_log_prph_trans_ctx_t *ctx = trans->ctx;
*received_at_us = ctx->received_at_us;
}
size_t copied = len < trans->pos ? len : trans->pos;
BLE_LOG_MEMCPY(data, trans->buf, copied);
trans->pos = 0;
components/bt/common/ble_log/test_apps/.build-test-rules.yml
+8
View File
@@ -8,6 +8,14 @@ components/bt/common/ble_log/test_apps/ble_log_perf_test:
depends_components:
- bt
components/bt/common/ble_log/test_apps/ble_log_rt_test:
disable:
- if: IDF_TARGET != "none"
temporary: true
reason: No BLE Log test runners are available yet
depends_components:
- bt
components/bt/common/ble_log/test_apps/ble_log_test:
disable:
- if: IDF_TARGET != "none"
components/bt/common/ble_log/test_apps/ble_log_perf_test/README.md
+6
View File
@@ -11,6 +11,9 @@ ESP32-C6). The transport is replaced by a software model
(`CONFIG_BLE_LOG_PRPH_TEST=y`) that mimics DMA ownership transfer and link
bandwidth, so the measurements isolate the LBM layer itself.
Runtime dispatch behavior and latency are covered by the sibling
`ble_log_rt_test` app.
## What Is Measured
| Dimension | Metrics |
@@ -57,6 +60,9 @@ python3 tools/parse_perf_log.py capture.log --csv out.csv
Run the same capture twice (old vs new LBM) and diff the CSV.
The parser also renders the `BLE_LOG_RT_PERF` latency lines printed by the
sibling `ble_log_rt_test` app.
## Supported Targets
| Supported Targets | ESP32 | ESP32-C2 | ESP32-C3 | ESP32-C5 | ESP32-C6 | ESP32-C61 | ESP32-H2 | ESP32-H21 | ESP32-H4 | ESP32-P4 | ESP32-S2 | ESP32-S3 | ESP32-S31 |
components/bt/common/ble_log/test_apps/ble_log_perf_test/main/test_ble_log_perf.c
+2 -2
View File
@@ -511,7 +511,7 @@ static void perf_sink_task(void *arg)
while (!sink->stop) {
size_t len = ble_log_prph_test_read(data, sizeof(data),
pdMS_TO_TICKS(PERF_READ_TIMEOUT_MS),
sink->bytes_per_second);
sink->bytes_per_second, NULL);
if (!len) {
sink->drained = true;
continue;
@@ -746,7 +746,7 @@ static void run_perf_case(const perf_run_cfg_t *cfg)
TEST_ASSERT_EQUAL(pdTRUE, xSemaphoreTake(sink.done, pdMS_TO_TICKS(1000)));
uint8_t discard[BLE_LOG_TRANS_SIZE];
while (ble_log_prph_test_read(discard, sizeof(discard), 0, 0)) {
while (ble_log_prph_test_read(discard, sizeof(discard), 0, 0, NULL)) {
}
uint64_t elapsed_us = run_end_us - run_start_us;
components/bt/common/ble_log/test_apps/ble_log_perf_test/tools/parse_perf_log.py
+60 -3
View File
@@ -17,6 +17,7 @@ from typing import TypedDict
KV = re.compile(r'(\w+)=(\S+)')
WRITER_COLS = ('frames', 'failed', 'avg', 'avg_failed', 'p50', 'p95', 'p99', 'max')
RT_COLS = ('mode', 'samples', 'batch', 'payload', 'min', 'avg', 'p50', 'p95', 'max')
class Run(TypedDict):
@@ -42,8 +43,12 @@ def main() -> int:
lines = f.read().splitlines()
runs: list[Run] = []
rt_rows: list[dict[str, str]] = []
cur: Run | None = None
for line in lines:
if line.startswith('BLE_LOG_RT_PERF '):
rt_rows.append(fields(line))
continue
if not line.startswith('BLE_LOG_PERF '):
continue
kv = fields(line)
@@ -62,8 +67,8 @@ def main() -> int:
else:
cur['other'].append(line[len('BLE_LOG_PERF ') :])
if not runs:
print(f'no BLE_LOG_PERF lines found in {path}')
if not runs and not rt_rows:
print(f'no BLE_LOG_PERF or BLE_LOG_RT_PERF lines found in {path}')
return 1
for i, run in enumerate(runs, 1):
@@ -85,15 +90,39 @@ def main() -> int:
print(f'- `{o}`')
print()
if rt_rows:
print('## Runtime dispatch')
print('| ' + ' | '.join(RT_COLS) + ' |')
print('|' + '---|' * len(RT_COLS))
for rt_row in rt_rows:
print('| ' + ' | '.join(rt_row.get(c, '-') for c in RT_COLS) + ' |')
print()
if csv_path:
with open(csv_path, 'w', newline='', encoding='utf-8') as f:
wcsv = csv.writer(f)
wcsv.writerow(['run', 'mode', 'profile', 'link', 'isolate', 'writer', *WRITER_COLS])
wcsv.writerow(
[
'kind',
'run',
'mode',
'profile',
'link',
'isolate',
'writer',
*WRITER_COLS,
'samples',
'batch',
'payload',
'min',
]
)
for i, run in enumerate(runs, 1):
h = run['head']
for w in run['writers']:
wcsv.writerow(
[
'perf',
i,
h.get('mode', ''),
h.get('profile', ''),
@@ -101,8 +130,36 @@ def main() -> int:
h.get('isolate', ''),
w.get('writer', ''),
*(w.get(c, '') for c in WRITER_COLS),
'',
'',
'',
'',
]
)
for rt_row in rt_rows:
wcsv.writerow(
[
'rt_perf',
'',
rt_row.get('mode', ''),
'',
'',
'',
'runtime',
'',
'',
rt_row.get('avg', ''),
'',
rt_row.get('p50', ''),
rt_row.get('p95', ''),
'',
rt_row.get('max', ''),
rt_row.get('samples', ''),
rt_row.get('batch', ''),
rt_row.get('payload', ''),
rt_row.get('min', ''),
]
)
print(f'CSV written to {csv_path}')
return 0
components/bt/common/ble_log/test_apps/ble_log_rt_test/CMakeLists.txt
+13
View File
@@ -0,0 +1,13 @@
# SPDX-FileCopyrightText: 2026 Espressif Systems (Shanghai) CO LTD
#
# SPDX-License-Identifier: CC0-1.0
cmake_minimum_required(VERSION 3.22)
list(PREPEND SDKCONFIG_DEFAULTS
"$ENV{IDF_PATH}/tools/test_apps/configs/sdkconfig.debug_helpers"
"sdkconfig.defaults")
set(COMPONENTS main)
include($ENV{IDF_PATH}/tools/cmake/project.cmake)
project(ble_log_rt_test)
components/bt/common/ble_log/test_apps/ble_log_rt_test/README.md
+67
View File
@@ -0,0 +1,67 @@
# BLE Log Runtime Test App
## Overview
On-target regression and latency suite for the BLE Log runtime dispatch layer:
the esp_timer deferred batch dispatch and the submission ownership gate.
The app runs on real hardware (any BLE-capable chip, currently tested on
ESP32-C6 and ESP32-C5). The transport is replaced by a software model
(`CONFIG_BLE_LOG_PRPH_TEST=y`) that mimics DMA ownership transfer and stamps
the hand-over time, so dispatch latency is measured without a real link.
## Test Cases
- `runtime dispatch latency`: 32 single submissions and 32 four-transport
bursts. Verifies exact delivery order/count and prints enqueue-to-receipt
min/avg/p50/p95/max latency (`BLE_LOG_RT_PERF` lines) for the single,
first-in-burst, and last-in-burst paths.
- `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
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
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.
## Build, Flash, Run
```bash
cd components/bt/common/ble_log/test_apps/ble_log_rt_test
idf.py set-target <chip>
idf.py -p <PORT> build flash monitor
```
Timeout regressions are verified at both supported tick rates: the default
build uses the production 100 Hz; the 1000 Hz variant has a dedicated overlay:
```bash
idf.py -B build_1000 -p <PORT> -D SDKCONFIG=sdkconfig.1000 \
-D SDKCONFIG_DEFAULTS="sdkconfig.defaults;sdkconfig.defaults.tick_1000" \
set-target <chip> build flash monitor
```
The app boots into the Unity menu; enter a test number to run it.
## Parsing Results
The latency lines can be rendered into tables/CSV with the parser shipped in
the perf test app:
```bash
idf.py -p <PORT> monitor | tee capture.log
python3 ../ble_log_perf_test/tools/parse_perf_log.py capture.log
python3 ../ble_log_perf_test/tools/parse_perf_log.py capture.log --csv out.csv
```
## Supported Targets
| Supported Targets | ESP32 | ESP32-C2 | ESP32-C3 | ESP32-C5 | ESP32-C6 | ESP32-C61 | ESP32-H2 | ESP32-H21 | ESP32-H4 | ESP32-P4 | ESP32-S2 | ESP32-S3 | ESP32-S31 |
| ----------------- | ----- | -------- | -------- | -------- | -------- | --------- | -------- | --------- | -------- | -------- | -------- | -------- | --------- |
CI builds are temporarily disabled until BLE Log test runners are available.
components/bt/common/ble_log/test_apps/ble_log_rt_test/main/CMakeLists.txt
+17
View File
@@ -0,0 +1,17 @@
# SPDX-FileCopyrightText: 2026 Espressif Systems (Shanghai) CO LTD
#
# SPDX-License-Identifier: Apache-2.0
idf_component_register(
SRCS "test_ble_log_main.c" "test_ble_log_runtime.c"
INCLUDE_DIRS "."
PRIV_REQUIRES unity bt esp_hw_support esp_timer
WHOLE_ARCHIVE
)
idf_component_get_property(bt_dir bt COMPONENT_DIR)
target_include_directories(${COMPONENT_LIB} PRIVATE
"${bt_dir}/common/ble_log/include"
"${bt_dir}/common/ble_log/src/internal_include"
"${bt_dir}/common/ble_log/src/internal_include/prph"
)
components/bt/common/ble_log/test_apps/ble_log_rt_test/main/test_ble_log_main.c
+70
View File
@@ -0,0 +1,70 @@
/*
* SPDX-FileCopyrightText: 2026 Espressif Systems (Shanghai) CO LTD
*
* SPDX-License-Identifier: Apache-2.0
*/
#include <string.h>
#include "unity.h"
#include "unity_test_runner.h"
#include "ble_log.h"
#include "ble_log_lbm.h"
#include "ble_log_prph_test.h"
#include "test_ble_log_main.h"
bool test_ble_log_walk_frames(const uint8_t *data, size_t len,
test_ble_log_frame_observer_t observer, void *ctx)
{
size_t offset = 0;
while (len - offset >= BLE_LOG_FRAME_OVERHEAD) {
ble_log_frame_head_t head;
memcpy(&head, data + offset, sizeof(head));
size_t frame_len = BLE_LOG_FRAME_OVERHEAD + head.length;
if (frame_len > len - offset) {
return false;
}
uint32_t checksum;
memcpy(&checksum, data + offset + BLE_LOG_FRAME_HEAD_LEN + head.length,
sizeof(checksum));
if (checksum != ble_log_fast_checksum(data + offset,
BLE_LOG_FRAME_HEAD_LEN + head.length)) {
return false;
}
if (observer) {
test_ble_log_frame_t frame = {
.src = head.frame_meta & 0xff,
.sn = head.frame_meta >> 8,
.payload = data + offset + BLE_LOG_FRAME_HEAD_LEN,
.payload_len = head.length,
};
observer(&frame, ctx);
}
offset += frame_len;
}
return offset == len;
}
void setUp(void)
{
}
void tearDown(void)
{
ble_log_prph_test_set_auto_recycle_hook(NULL, NULL);
#if CONFIG_BLE_LOG_TS_ENABLED
(void)ble_log_sync_enable(false);
#endif
}
void app_main(void)
{
/* The BLE Log module has no automatic system init on this branch; the
* controller normally calls ble_log_init(). Initialize it explicitly. */
TEST_ASSERT_TRUE_MESSAGE(ble_log_init(), "BLE Log init failed");
unity_run_menu();
}
components/bt/common/ble_log/test_apps/ble_log_rt_test/main/test_ble_log_main.h
+27
View File
@@ -0,0 +1,27 @@
/*
* SPDX-FileCopyrightText: 2026 Espressif Systems (Shanghai) CO LTD
*
* SPDX-License-Identifier: Apache-2.0
*/
#pragma once
#include <stdbool.h>
#include <stddef.h>
#include <stdint.h>
#include "ble_log.h"
typedef struct {
ble_log_src_t src;
uint32_t sn;
const uint8_t *payload;
size_t payload_len;
} test_ble_log_frame_t;
typedef void (*test_ble_log_frame_observer_t)(const test_ble_log_frame_t *frame, void *ctx);
/* Walks a captured transport buffer, validating frame headers and checksums.
* Returns true when the whole buffer consists of valid frames. */
bool test_ble_log_walk_frames(const uint8_t *data, size_t len,
test_ble_log_frame_observer_t observer, void *ctx);
components/bt/common/ble_log/test_apps/ble_log_rt_test/main/test_ble_log_runtime.c
+817
View File
@@ -0,0 +1,817 @@
/*
* SPDX-FileCopyrightText: 2026 Espressif Systems (Shanghai) CO LTD
*
* SPDX-License-Identifier: Apache-2.0
*/
#include <inttypes.h>
#include <stdbool.h>
#include <stdint.h>
#include <stdio.h>
#include <stdlib.h>
#include <string.h>
#include "ble_log.h"
#include "ble_log_lbm.h"
#include "ble_log_prph_test.h"
#include "ble_log_rt.h"
#include "esp_timer.h"
#include "freertos/FreeRTOS.h"
#include "freertos/semphr.h"
#include "freertos/task.h"
#include "test_ble_log_main.h"
#include "unity.h"
#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)
#define RT_EXPECTED_DEFER_US (1000)
#define RT_MARKER_MAGIC UINT32_C(0x52545046)
#define RT_USER_PAYLOAD_LEN (BLE_LOG_TRANS_SIZE - sizeof(uint32_t) - BLE_LOG_FRAME_OVERHEAD)
#define RT_STARVATION_FEEDBACK (16384)
#define RT_HEARTBEAT_DELAY_US (2000)
#define RT_HEARTBEAT_MAX_ELAPSED_US (10000)
#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_DEINIT_ROUNDS (200)
#define RT_JOIN_TIMEOUT_MS (5000)
typedef struct {
uint32_t magic;
uint32_t seq;
} rt_marker_t;
typedef struct {
bool found;
uint32_t seq;
uint32_t ts_count;
} rt_marker_observer_t;
typedef struct {
SemaphoreHandle_t done;
uint32_t remaining;
bool stop;
bool write_failed;
int64_t fired_us;
} rt_starvation_ctx_t;
typedef struct {
uint32_t stop;
uint32_t exited;
uint32_t attempts;
} rt_deinit_writer_ctx_t;
typedef struct {
uint32_t buf_util_frames;
uint32_t max_inflight_peak;
bool over_limit;
} rt_peak_observer_t;
_Static_assert(RT_USER_PAYLOAD_LEN >= sizeof(rt_marker_t),
"BLE Log transport is too small for the runtime test marker");
static uint8_t s_payload[RT_USER_PAYLOAD_LEN];
static uint8_t s_capture[BLE_LOG_TRANS_SIZE];
static uint32_t s_single_latency_us[RT_SAMPLE_COUNT];
static uint32_t s_burst_first_latency_us[RT_SAMPLE_COUNT];
static uint32_t s_burst_last_latency_us[RT_SAMPLE_COUNT];
static rt_starvation_ctx_t s_starvation;
/* File-scope so a writer that outlives the test never references a dead
* stack frame (same pattern as s_starvation). */
static rt_deinit_writer_ctx_t s_deinit_race;
static void prepare_payload(uint32_t seq)
{
rt_marker_t marker = {
.magic = RT_MARKER_MAGIC,
.seq = seq,
};
memset(s_payload, (uint8_t)seq, sizeof(s_payload));
memcpy(s_payload, &marker, sizeof(marker));
}
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++;
}
if (frame->src != BLE_LOG_SRC_CUSTOM ||
frame->payload_len < sizeof(uint32_t) + sizeof(rt_marker_t)) {
return;
}
rt_marker_t marker;
memcpy(&marker, frame->payload + sizeof(uint32_t), sizeof(marker));
if (marker.magic == RT_MARKER_MAGIC) {
observer->found = true;
observer->seq = marker.seq;
}
}
static TickType_t runtime_timeout_ticks(uint32_t timeout_ms)
{
uint64_t ticks = ((uint64_t)timeout_ms * configTICK_RATE_HZ + 999) / 1000;
if (ticks == 0) {
ticks = 1;
}
return ticks > portMAX_DELAY ? portMAX_DELAY : (TickType_t)ticks;
}
static bool runtime_deadline_ticks(int64_t deadline_us, TickType_t *ticks)
{
int64_t now_us = esp_timer_get_time();
if (now_us >= deadline_us) {
return false;
}
uint32_t remain_ms = (uint32_t)((deadline_us - now_us + 999) / 1000);
if (remain_ms == 0) {
remain_ms = 1;
}
*ticks = runtime_timeout_ticks(remain_ms);
return true;
}
static bool write_runtime_marker(uint32_t seq, int64_t *enqueued_at_us)
{
prepare_payload(seq);
/* Include LBM packing and queueing in the measured runtime latency. */
int64_t before_us = esp_timer_get_time();
if (!ble_log_write_hex(BLE_LOG_SRC_CUSTOM, s_payload, sizeof(s_payload))) {
return false;
}
if (enqueued_at_us) {
*enqueued_at_us = before_us;
}
return true;
}
static bool read_runtime_marker(uint32_t *seq, uint32_t *ts_count,
int64_t *received_at_us)
{
const int64_t deadline_us = esp_timer_get_time() +
(int64_t)RT_READ_TIMEOUT_MS * 1000;
uint32_t observed_ts = 0;
while (true) {
TickType_t remaining;
if (!runtime_deadline_ticks(deadline_us, &remaining)) {
return false;
}
int64_t transport_received_at_us;
size_t len = ble_log_prph_test_read(s_capture, sizeof(s_capture), remaining, 0,
&transport_received_at_us);
if (!len) {
continue;
}
rt_marker_observer_t observer = {0};
TEST_ASSERT_TRUE_MESSAGE(test_ble_log_walk_frames(s_capture, len,
observe_runtime_marker,
&observer),
"Runtime dispatch produced an invalid transport");
observed_ts += observer.ts_count;
if (observer.found) {
*seq = observer.seq;
if (ts_count) {
*ts_count = observed_ts;
}
if (received_at_us) {
*received_at_us = transport_received_at_us;
}
return true;
}
}
}
static bool runtime_stream_is_quiet(void)
{
const int64_t drain_deadline_us = esp_timer_get_time() +
(int64_t)RT_QUIET_DRAIN_DEADLINE_MS * 1000;
while (esp_timer_get_time() < drain_deadline_us) {
const int64_t gap_deadline_us = esp_timer_get_time() +
(int64_t)RT_QUIET_TIMEOUT_MS * 1000;
size_t len = 0;
while (esp_timer_get_time() < gap_deadline_us) {
TickType_t remaining;
if (!runtime_deadline_ticks(gap_deadline_us, &remaining)) {
break;
}
len = ble_log_prph_test_read(s_capture, sizeof(s_capture), remaining, 0, NULL);
if (len) {
break;
}
}
if (!len) {
return true;
}
rt_marker_observer_t observer = {0};
if (!test_ble_log_walk_frames(s_capture, len, observe_runtime_marker, &observer) ||
observer.found) {
return false;
}
}
return false;
}
static void refill_runtime_queue(void *arg)
{
rt_starvation_ctx_t *ctx = arg;
if (ctx->stop || !ctx->remaining) {
return;
}
ctx->remaining--;
if (!ble_log_write_hex(BLE_LOG_SRC_CUSTOM, s_payload, sizeof(s_payload))) {
ctx->write_failed = true;
}
}
static void heartbeat_cb(void *arg)
{
rt_starvation_ctx_t *ctx = arg;
ctx->fired_us = esp_timer_get_time();
ctx->stop = true;
xSemaphoreGive(ctx->done);
}
#if CONFIG_ESP_TIMER_SUPPORTS_ISR_DISPATCH_METHOD
static void BLE_LOG_IRAM_ATTR isr_write_cb(void *arg)
{
(void)arg;
(void)ble_log_write_hex(BLE_LOG_SRC_CUSTOM, s_payload, sizeof(s_payload));
}
#endif
static void noop_callback(void *arg)
{
(void)arg;
}
static void deinit_writer_task(void *arg)
{
rt_deinit_writer_ctx_t *ctx = arg;
while (!__atomic_load_n(&ctx->stop, __ATOMIC_ACQUIRE)) {
ctx->attempts++;
(void)ble_log_write_hex(BLE_LOG_SRC_CUSTOM, s_payload, sizeof(s_payload));
taskYIELD();
}
__atomic_store_n(&ctx->exited, true, __ATOMIC_RELEASE);
vTaskDelete(NULL);
}
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) {
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;
}
if (util.inflight_peak > util.trans_cnt) {
observer->over_limit = true;
}
}
static int compare_u32(const void *lhs, const void *rhs)
{
uint32_t a = *(const uint32_t *)lhs;
uint32_t b = *(const uint32_t *)rhs;
return (a > b) - (a < b);
}
static uint32_t percentile(const uint32_t *sorted, size_t count, uint32_t percent)
{
size_t rank = (count * percent + 99) / 100;
return sorted[rank - 1];
}
static void print_latency_stats(const char *mode, uint32_t batch, uint32_t *samples)
{
uint64_t total = 0;
for (size_t i = 0; i < RT_SAMPLE_COUNT; i++) {
total += samples[i];
}
qsort(samples, RT_SAMPLE_COUNT, sizeof(samples[0]), compare_u32);
printf("BLE_LOG_RT_PERF mode=%s samples=%u batch=%u payload=%uB "
"min=%" PRIu32 "us avg=%" PRIu64 "us p50=%" PRIu32
"us p95=%" PRIu32 "us max=%" PRIu32 "us\n",
mode, (unsigned)RT_SAMPLE_COUNT, (unsigned)batch,
(unsigned)sizeof(s_payload), samples[0], total / RT_SAMPLE_COUNT,
percentile(samples, RT_SAMPLE_COUNT, 50),
percentile(samples, RT_SAMPLE_COUNT, 95),
samples[RT_SAMPLE_COUNT - 1]);
}
static void warm_up_runtime(void)
{
uint32_t received_seq;
prepare_payload(0);
TEST_ASSERT_TRUE(ble_log_write_hex(BLE_LOG_SRC_CUSTOM,
s_payload, sizeof(s_payload)));
TEST_ASSERT_TRUE_MESSAGE(read_runtime_marker(&received_seq, NULL, NULL),
"Timed out waiting for runtime warm-up dispatch");
TEST_ASSERT_EQUAL_UINT32(0, received_seq);
TEST_ASSERT_TRUE(runtime_stream_is_quiet());
}
TEST_CASE("BLE Log runtime millisecond waits remain nonzero",
"[ble_log][runtime][ignore]")
{
TEST_ASSERT_GREATER_THAN_UINT32(0, runtime_timeout_ticks(1));
TEST_ASSERT_GREATER_THAN_UINT32(
0, runtime_timeout_ticks(RT_QUIET_TIMEOUT_MS));
TEST_ASSERT_GREATER_THAN_UINT32(
0, runtime_timeout_ticks(RT_READ_TIMEOUT_MS));
const int64_t start_us = esp_timer_get_time();
const int64_t deadline_us = start_us + (int64_t)RT_READ_TIMEOUT_MS * 1000;
TickType_t ticks;
while (runtime_deadline_ticks(deadline_us, &ticks)) {
vTaskDelay(ticks);
}
TEST_ASSERT_TRUE_MESSAGE(
esp_timer_get_time() - start_us >= (int64_t)RT_READ_TIMEOUT_MS * 1000,
"Millisecond timeout returned before the requested deadline");
}
TEST_CASE("BLE Log runtime quiet check rejects an extra marker",
"[ble_log][runtime][ignore]")
{
const uint32_t first_seq = UINT32_C(0x35000);
uint32_t received_seq;
TEST_ASSERT_TRUE(ble_log_enable(true));
(void)runtime_stream_is_quiet();
prepare_payload(first_seq);
TEST_ASSERT_TRUE(ble_log_write_hex(BLE_LOG_SRC_CUSTOM,
s_payload, sizeof(s_payload)));
prepare_payload(first_seq + 1);
TEST_ASSERT_TRUE(ble_log_write_hex(BLE_LOG_SRC_CUSTOM,
s_payload, sizeof(s_payload)));
TEST_ASSERT_TRUE(read_runtime_marker(&received_seq, NULL, NULL));
TEST_ASSERT_EQUAL_UINT32(first_seq, received_seq);
bool quiet = runtime_stream_is_quiet();
TEST_ASSERT_FALSE_MESSAGE(quiet,
"Quiet check silently discarded an extra runtime marker");
}
TEST_CASE("BLE Log runtime latency excludes consumer delay",
"[ble_log][runtime][ignore]")
{
const uint32_t seq = UINT32_C(0x36000);
uint32_t received_seq;
int64_t received_at_us;
TEST_ASSERT_TRUE(ble_log_enable(true));
warm_up_runtime();
int64_t start_us;
TEST_ASSERT_TRUE(write_runtime_marker(seq, &start_us));
const int64_t delay_deadline_us = esp_timer_get_time() +
(int64_t)RT_CONSUMER_DELAY_MS * 1000;
TickType_t delay_ticks;
while (runtime_deadline_ticks(delay_deadline_us, &delay_ticks)) {
vTaskDelay(delay_ticks);
}
TEST_ASSERT_TRUE(read_runtime_marker(&received_seq, NULL, &received_at_us));
uint32_t measured_latency_us = (uint32_t)(received_at_us - start_us);
TEST_ASSERT_TRUE(runtime_stream_is_quiet());
TEST_ASSERT_EQUAL_UINT32(seq, received_seq);
TEST_ASSERT_TRUE(received_at_us >= start_us);
TEST_ASSERT_LESS_THAN_UINT32_MESSAGE(
RT_RECEIVE_MAX_LATENCY_US, measured_latency_us,
"Runtime latency included time spent waiting for the consumer");
}
TEST_CASE("BLE Log ISR-only submission arms runtime dispatch",
"[ble_log][runtime][ignore]")
{
#if !CONFIG_ESP_TIMER_SUPPORTS_ISR_DISPATCH_METHOD
TEST_IGNORE_MESSAGE("Requires ESP Timer ISR dispatch support");
#else
const uint32_t seq = UINT32_C(0x28000);
uint32_t received_seq = 0;
TEST_ASSERT_TRUE(ble_log_enable(true));
warm_up_runtime();
prepare_payload(seq);
esp_timer_handle_t isr_timer = NULL;
const esp_timer_create_args_t timer_args = {
.callback = isr_write_cb,
.dispatch_method = ESP_TIMER_ISR,
.name = "ble_log_isr_write",
};
TEST_ASSERT_EQUAL(ESP_OK, esp_timer_create(&timer_args, &isr_timer));
esp_err_t start_err = esp_timer_start_once(isr_timer, 1);
bool received = start_err == ESP_OK &&
read_runtime_marker(&received_seq, NULL, NULL);
TEST_ASSERT_EQUAL(ESP_OK,
esp_timer_stop_blocking(isr_timer, portMAX_DELAY));
TEST_ASSERT_EQUAL(ESP_OK, esp_timer_delete(isr_timer));
TEST_ASSERT_EQUAL(ESP_OK, start_err);
TEST_ASSERT_TRUE_MESSAGE(received,
"ISR submission did not arm runtime dispatch");
TEST_ASSERT_EQUAL_UINT32(seq, received_seq);
TEST_ASSERT_TRUE(runtime_stream_is_quiet());
#endif
}
#if CONFIG_BLE_LOG_TS_ENABLED
TEST_CASE("BLE Log periodic timestamp skips light sleep wakeups",
"[ble_log][runtime][timestamp][ignore]")
{
const uint32_t seq = UINT32_C(0x40000);
uint32_t received_seq;
uint32_t ts_count = 0;
esp_timer_handle_t wake_probe_timer = NULL;
const esp_timer_create_args_t wake_probe_args = {
.callback = noop_callback,
.dispatch_method = ESP_TIMER_TASK,
.name = "ble_log_wake_probe",
};
TEST_ESP_OK(esp_timer_create(&wake_probe_args, &wake_probe_timer));
int64_t probe_start_us = esp_timer_get_time();
TEST_ESP_OK(esp_timer_start_once(
wake_probe_timer, BLE_LOG_TS_TRIGGER_TIMEOUT_US * 3 / 2));
int64_t next_wake_us = esp_timer_get_next_alarm_for_wake_up();
TEST_ESP_OK(esp_timer_stop(wake_probe_timer));
TEST_ESP_OK(esp_timer_delete(wake_probe_timer));
TEST_ASSERT_TRUE_MESSAGE(next_wake_us != INT64_MAX,
"Wake-capable probe timer was not scheduled");
TEST_ASSERT_GREATER_THAN_INT64_MESSAGE(
BLE_LOG_TS_TRIGGER_TIMEOUT_US * 5 / 4,
next_wake_us - probe_start_us,
"Periodic timestamp timer was selected to wake light sleep");
TEST_ASSERT_TRUE(ble_log_enable(true));
TEST_ASSERT_TRUE(runtime_stream_is_quiet());
TEST_ASSERT_TRUE(ble_log_sync_enable(true));
for (int i = 0; i < 3; i++) {
vTaskDelay(runtime_timeout_ticks(CONFIG_BLE_LOG_TS_TRIGGER_TIMEOUT_MS));
}
TEST_ASSERT_TRUE(ble_log_sync_enable(false));
/* A full marker rolls the partial timestamp transport through the normal
* LBM submission path without making runtime dispatch the TS trigger. */
TEST_ASSERT_TRUE(write_runtime_marker(seq, NULL));
TEST_ASSERT_TRUE_MESSAGE(read_runtime_marker(&received_seq, &ts_count, NULL),
"Timed out waiting for the periodic timestamp probe");
TEST_ASSERT_EQUAL_UINT32(seq, received_seq);
TEST_ASSERT_TRUE(runtime_stream_is_quiet());
TEST_ASSERT_GREATER_THAN_UINT32_MESSAGE(
0, ts_count,
"Periodic ESP timer did not emit a timestamp frame");
}
#endif
TEST_CASE("BLE Log runtime dispatch yields to other timer callbacks",
"[ble_log][runtime][ignore]")
{
TEST_ASSERT_TRUE(ble_log_enable(true));
warm_up_runtime();
memset(&s_starvation, 0, sizeof(s_starvation));
s_starvation.done = xSemaphoreCreateBinary();
s_starvation.remaining = RT_STARVATION_FEEDBACK;
TEST_ASSERT_NOT_NULL(s_starvation.done);
esp_timer_handle_t heartbeat_timer = NULL;
const esp_timer_create_args_t timer_args = {
.callback = heartbeat_cb,
.arg = &s_starvation,
.dispatch_method = ESP_TIMER_TASK,
.name = "ble_log_heartbeat",
.skip_unhandled_events = true,
};
TEST_ASSERT_EQUAL(ESP_OK, esp_timer_create(&timer_args, &heartbeat_timer));
prepare_payload(UINT32_C(0x30000));
ble_log_prph_test_set_auto_recycle_hook(refill_runtime_queue, &s_starvation);
int64_t start_us = esp_timer_get_time();
esp_err_t start_err = esp_timer_start_once(heartbeat_timer,
RT_HEARTBEAT_DELAY_US);
bool wrote = start_err == ESP_OK &&
ble_log_write_hex(BLE_LOG_SRC_CUSTOM, s_payload,
sizeof(s_payload));
bool heartbeat_fired = false;
if (wrote) {
heartbeat_fired =
xSemaphoreTake(s_starvation.done, runtime_timeout_ticks(1000)) == pdTRUE;
}
ble_log_prph_test_set_auto_recycle_hook(NULL, NULL);
esp_timer_stop_blocking(heartbeat_timer, portMAX_DELAY);
TEST_ASSERT_EQUAL(ESP_OK, esp_timer_delete(heartbeat_timer));
vSemaphoreDelete(s_starvation.done);
(void)runtime_stream_is_quiet();
TEST_ASSERT_EQUAL(ESP_OK, start_err);
TEST_ASSERT_TRUE_MESSAGE(wrote, "Feedback seed write failed");
TEST_ASSERT_TRUE_MESSAGE(heartbeat_fired,
"Shared ESP timer callback never got CPU time");
TEST_ASSERT_TRUE_MESSAGE(
s_starvation.remaining < RT_STARVATION_FEEDBACK,
"Fairness test did not create feedback load");
TEST_ASSERT_FALSE_MESSAGE(s_starvation.write_failed,
"Feedback write unexpectedly failed");
TEST_ASSERT_TRUE_MESSAGE(s_starvation.fired_us >= start_us,
"Heartbeat fired before feedback load started");
TEST_ASSERT_TRUE_MESSAGE(
s_starvation.fired_us - start_us < RT_HEARTBEAT_MAX_ELAPSED_US,
"Runtime dispatch monopolized the shared ESP timer task");
}
TEST_CASE("BLE Log runtime defer timer keeps its first deadline and wakes light sleep",
"[ble_log][runtime][ignore]")
{
#if !CONFIG_FREERTOS_UNICORE
TEST_IGNORE_MESSAGE("Requires single-core scheduler suspension");
#else
const uint32_t base_seq = UINT32_C(0x38000);
TEST_ASSERT_TRUE(ble_log_enable(true));
warm_up_runtime();
bool wrote = true;
vTaskSuspendAll();
int64_t wake_before = esp_timer_get_next_alarm_for_wake_up();
prepare_payload(base_seq);
int64_t first_write_entry_us = esp_timer_get_time();
wrote = ble_log_write_hex(BLE_LOG_SRC_CUSTOM, s_payload, sizeof(s_payload));
int64_t first_write_return_us = esp_timer_get_time();
int64_t first_defer_wake_us = esp_timer_get_next_alarm_for_wake_up();
for (uint32_t i = 1; i < RT_BURST_SIZE; i++) {
wrote = wrote && write_runtime_marker(base_seq + i, NULL);
}
int64_t burst_defer_wake_us = esp_timer_get_next_alarm_for_wake_up();
(void)xTaskResumeAll();
TEST_ASSERT_TRUE(wrote);
for (uint32_t i = 0; i < RT_BURST_SIZE; i++) {
uint32_t received_seq;
TEST_ASSERT_TRUE_MESSAGE(read_runtime_marker(&received_seq, NULL, NULL),
"Timed out waiting for defer-wake probe");
TEST_ASSERT_EQUAL_UINT32(base_seq + i, received_seq);
}
TEST_ASSERT_TRUE(runtime_stream_is_quiet());
TEST_ASSERT_TRUE_MESSAGE(first_defer_wake_us != INT64_MAX,
"Defer timer was not scheduled as a light-sleep wake source");
TEST_ASSERT_TRUE_MESSAGE(first_defer_wake_us < wake_before,
"Defer timer was not the newly scheduled wake alarm");
TEST_ASSERT_GREATER_OR_EQUAL_INT64_MESSAGE(
first_write_entry_us + RT_EXPECTED_DEFER_US, first_defer_wake_us,
"Defer timer was armed earlier than the fixed 1 ms delay");
TEST_ASSERT_LESS_OR_EQUAL_INT64_MESSAGE(
first_write_return_us + RT_EXPECTED_DEFER_US, first_defer_wake_us,
"Defer timer was armed later than the fixed 1 ms delay");
TEST_ASSERT_EQUAL_INT64_MESSAGE(
first_defer_wake_us, burst_defer_wake_us,
"Burst submissions moved the first defer deadline");
#endif
}
TEST_CASE("BLE Log runtime dispatch latency", "[ble_log][runtime][perf][ignore]")
{
TEST_ASSERT_TRUE(ble_log_enable(true));
warm_up_runtime();
for (uint32_t sample = 0; sample < RT_SAMPLE_COUNT; sample++) {
uint32_t seq = UINT32_C(0x10000) + sample;
uint32_t received_seq;
int64_t received_at_us;
int64_t start_us;
TEST_ASSERT_TRUE(write_runtime_marker(seq, &start_us));
TEST_ASSERT_TRUE_MESSAGE(read_runtime_marker(&received_seq, NULL,
&received_at_us),
"Timed out waiting for a single runtime dispatch");
TEST_ASSERT_EQUAL_UINT32(seq, received_seq);
TEST_ASSERT_TRUE(received_at_us >= start_us);
s_single_latency_us[sample] = (uint32_t)(received_at_us - start_us);
}
TEST_ASSERT_TRUE_MESSAGE(runtime_stream_is_quiet(),
"Unexpected runtime marker after single samples");
for (uint32_t sample = 0; sample < RT_SAMPLE_COUNT; sample++) {
uint32_t base_seq = UINT32_C(0x20000) + sample * RT_BURST_SIZE;
int64_t start_us[RT_BURST_SIZE];
for (uint32_t i = 0; i < RT_BURST_SIZE; i++) {
TEST_ASSERT_TRUE(write_runtime_marker(base_seq + i, &start_us[i]));
}
for (uint32_t i = 0; i < RT_BURST_SIZE; i++) {
uint32_t received_seq;
int64_t received_at_us;
TEST_ASSERT_TRUE_MESSAGE(read_runtime_marker(&received_seq, NULL,
&received_at_us),
"Timed out waiting for a burst runtime dispatch");
TEST_ASSERT_TRUE(received_at_us >= start_us[i]);
if (i == 0) {
s_burst_first_latency_us[sample] =
(uint32_t)(received_at_us - start_us[i]);
}
if (i == RT_BURST_SIZE - 1) {
s_burst_last_latency_us[sample] =
(uint32_t)(received_at_us - start_us[i]);
}
TEST_ASSERT_EQUAL_UINT32(base_seq + i, received_seq);
}
TEST_ASSERT_TRUE_MESSAGE(runtime_stream_is_quiet(),
"Unexpected runtime marker after burst sample");
}
print_latency_stats("single", 1, s_single_latency_us);
print_latency_stats("burst_first", RT_BURST_SIZE, s_burst_first_latency_us);
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",
"[ble_log][runtime][ignore]")
{
#if !CONFIG_FREERTOS_UNICORE
TEST_IGNORE_MESSAGE("Requires dispatch exclusion during enqueue (single core)");
#else
const uint32_t base_seq = UINT32_C(0x50000);
int64_t first_received_us = 0;
int64_t last_received_us = 0;
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. */
ble_log_prph_test_set_auto_recycle_hook(noop_callback, NULL);
ble_log_flush();
ble_log_prph_test_set_auto_recycle_hook(NULL, NULL);
TEST_ASSERT_TRUE(runtime_stream_is_quiet());
/* Fill every transport reachable from ordinary task context before the
* first callback. The callback must drain the complete entry snapshot
* without an artificial item cap. */
bool wrote = true;
vTaskSuspendAll();
for (uint32_t i = 0; i < RT_TASK_POOL_TRANS_COUNT; 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");
for (uint32_t i = 0; i < RT_TASK_POOL_TRANS_COUNT; i++) {
uint32_t received_seq;
int64_t received_at_us;
TEST_ASSERT_TRUE_MESSAGE(read_runtime_marker(&received_seq, NULL,
&received_at_us),
"Timed out waiting for a batched burst dispatch");
TEST_ASSERT_EQUAL_UINT32(base_seq + i, received_seq);
if (i == 0) {
first_received_us = received_at_us;
}
last_received_us = received_at_us;
}
TEST_ASSERT_TRUE(runtime_stream_is_quiet());
TEST_ASSERT_LESS_THAN_INT64_MESSAGE(
RT_BURST_SPAN_MAX_US, last_received_us - first_received_us,
"Burst was split across multiple dispatch callbacks "
"(per-item re-defer instead of one batch)");
#endif
}
TEST_CASE("BLE Log LBM inflight peak stays bounded under bursts",
"[ble_log][runtime][ignore]")
{
rt_peak_observer_t observer = {0};
TEST_ASSERT_TRUE(ble_log_enable(true));
TEST_ASSERT_TRUE(runtime_stream_is_quiet());
/* Queue several transports without consuming them so LBM transports are
* submitted while earlier ones are still in flight. */
for (uint32_t i = 0; i < RT_PEAK_WRITES; i++) {
uint32_t seq = UINT32_C(0x80000) + i;
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));
TEST_ASSERT_TRUE(ble_log_rt_drain());
const int64_t deadline_us = esp_timer_get_time() +
(int64_t)RT_READ_TIMEOUT_MS * 1000;
while (true) {
TickType_t remaining;
if (!runtime_deadline_ticks(deadline_us, &remaining)) {
break;
}
size_t len = ble_log_prph_test_read(s_capture, sizeof(s_capture),
remaining, 0, NULL);
if (!len) {
break;
}
TEST_ASSERT_TRUE(test_ble_log_walk_frames(s_capture, len,
observe_buf_util, &observer));
}
TEST_ASSERT_TRUE(runtime_stream_is_quiet());
TEST_ASSERT_GREATER_THAN_UINT32_MESSAGE(
0, observer.buf_util_frames,
"No BUF_UTIL snapshots observed after flush");
TEST_ASSERT_FALSE_MESSAGE(observer.over_limit,
"inflight_peak exceeded the LBM transport count");
TEST_ASSERT_GREATER_THAN_UINT32_MESSAGE(
1, observer.max_inflight_peak,
"Burst did not record concurrent inflight transports");
/* ponytail: a single sequential writer cannot make this fail on the old
* plain-volatile code; it checks presence and bounds of the recorded
* peaks. Failing on the data race itself needs concurrent submitters or
* TSan, which this on-target suite does not provide. */
}
TEST_CASE("BLE Log runtime survives deinit racing submissions",
"[ble_log][runtime][ignore]")
{
rt_deinit_writer_ctx_t *ctx = &s_deinit_race;
bool reinit_ok = true;
memset(ctx, 0, sizeof(*ctx));
prepare_payload(UINT32_C(0x70000));
#if CONFIG_FREERTOS_UNICORE
BaseType_t task_created = xTaskCreate(
deinit_writer_task, "ble_log_deinit_wr", 4096, ctx,
uxTaskPriorityGet(NULL), NULL);
#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);
#endif
TEST_ASSERT_EQUAL_MESSAGE(pdPASS, task_created, "Writer task create failed");
for (int i = 0; i < RT_DEINIT_ROUNDS; i++) {
ble_log_deinit();
reinit_ok = reinit_ok && ble_log_init();
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. */
__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;
while (!__atomic_load_n(&ctx->exited, __ATOMIC_ACQUIRE)) {
TickType_t join_ticks;
if (!runtime_deadline_ticks(join_deadline_us, &join_ticks)) {
break;
}
vTaskDelay(join_ticks);
}
/* Recover module state before any assertion can abort the test: a
* failed re-init leaves the module deinit-ed and tearDown does not
* restore it, which would cascade into every later test. */
ble_log_deinit();
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(reinit_ok, "BLE Log re-init failed during the race");
TEST_ASSERT_GREATER_THAN_UINT32_MESSAGE(
RT_DEINIT_ROUNDS, ctx->attempts,
"Writer task did not run during the deinit race");
warm_up_runtime();
}
components/bt/common/ble_log/test_apps/ble_log_rt_test/sdkconfig.defaults
+14
View File
@@ -0,0 +1,14 @@
CONFIG_BT_ENABLED=y
CONFIG_BLE_LOG_ENABLED=y
CONFIG_BLE_LOG_PRPH_TEST=y
# Exercise the ISR-only runtime submission path.
CONFIG_ESP_TIMER_SUPPORTS_ISR_DISPATCH_METHOD=y
# Production tick rate; the 1000 Hz regression variant is built from
# sdkconfig.defaults.tick_1000.
CONFIG_FREERTOS_HZ=100
CONFIG_BLE_LOG_TS_ENABLED=y
# Keep the production TS/hook cadence (Kconfig default 1000 ms) so the
# regressions see the production info/stat/buf-util cadence.
CONFIG_ESP_TASK_WDT_CHECK_IDLE_TASK_CPU0=n
# 64-bit assertions used by the runtime latency checks
CONFIG_UNITY_ENABLE_64BIT=y
components/bt/common/ble_log/test_apps/ble_log_rt_test/sdkconfig.defaults.tick_1000
+3
View File
@@ -0,0 +1,3 @@
# 1000 Hz tick regression. Use with sdkconfig.defaults:
# -D SDKCONFIG_DEFAULTS="sdkconfig.defaults;sdkconfig.defaults.tick_1000"
CONFIG_FREERTOS_HZ=1000
components/bt/common/ble_log/test_apps/ble_log_test/README.md
+1 -1
View File
@@ -9,7 +9,7 @@
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 task hook.
transport stream written by the runtime dispatch hook.
Currently covered:
components/bt/common/ble_log/test_apps/ble_log_test/main/test_ble_log_rt.c
+4 -3
View File
@@ -24,7 +24,7 @@
#error "BLE Log test app requires CONFIG_BLE_LOG_PRPH_TEST"
#endif
/* The runtime task hook is throttled to one pass per
/* The runtime dispatch hook is throttled to one pass per
* BLE_LOG_TS_TRIGGER_TIMEOUT_MS; let the window elapse between write bursts
* so a hook pass is guaranteed to run after the settle delay. */
#define TEST_HOOK_SETTLE_MS (BLE_LOG_TS_TRIGGER_TIMEOUT_MS + 100)
@@ -102,7 +102,8 @@ static void test_reader_task(void *arg)
reader_ctx_t *ctx = arg;
while (!ctx->stop) {
size_t len = ble_log_prph_test_read(s_read_buf, sizeof(s_read_buf),
pdMS_TO_TICKS(TEST_READ_TIMEOUT_MS), 0);
pdMS_TO_TICKS(TEST_READ_TIMEOUT_MS), 0,
NULL);
if (len > 0 &&
!test_ble_log_walk_frames(s_read_buf, len, capture_version_info_frame,
&ctx->capture)) {
@@ -127,7 +128,7 @@ 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 wakes the runtime task;
/* 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