From fd2c99b89093108709ecd3b638d17df46c3f4e9f Mon Sep 17 00:00:00 2001 From: mikecarper Date: Fri, 23 Oct 2026 11:57:24 -0700 Subject: [PATCH] Add isolated ESP32 SPI clock and retune timing instrumentation --- .github/workflows/run-unit-tests.yml | 1 + src/helpers/RadioProfileCLI.cpp | 6 + src/helpers/radiolib/ESP32BufferedRadioHal.h | 20 +++ src/helpers/radiolib/ESP32SpiABDiagnostics.h | 91 +++++++++++ test/test_esp32_spi_ab_diagnostics.py | 163 +++++++++++++++++++ 5 files changed, 281 insertions(+) create mode 100644 src/helpers/radiolib/ESP32SpiABDiagnostics.h create mode 100644 test/test_esp32_spi_ab_diagnostics.py diff --git a/.github/workflows/run-unit-tests.yml b/.github/workflows/run-unit-tests.yml index 1b2db2a34..32ad9823d 100644 --- a/.github/workflows/run-unit-tests.yml +++ b/.github/workflows/run-unit-tests.yml @@ -817,6 +817,7 @@ jobs: python3 -B test/test_rak3401_onboard_radio.py -v python3 -B test/test_rak3401_buffered_radio_hal.py -v python3 -B test/test_sx126x_buffered_radio_hal.py -v + python3 -B test/test_esp32_spi_ab_diagnostics.py -v python3 -B test/test_profile_switch_timing.py -v python3 -B test/test_nrf_radio_yield_budget.py -v python3 -B test/test_nrf_radio_priority_lease.py -v diff --git a/src/helpers/RadioProfileCLI.cpp b/src/helpers/RadioProfileCLI.cpp index 562de844b..fc80397da 100644 --- a/src/helpers/RadioProfileCLI.cpp +++ b/src/helpers/RadioProfileCLI.cpp @@ -9,6 +9,9 @@ #include "PersistentStoreFormat.h" #include "radiolib/RXPowerSaving.h" #include "radiolib/HilTxFrequencyGuard.h" +#if defined(MESH_HIL_ESP_SPI_AB) && MESH_HIL_ESP_SPI_AB +#include "radiolib/ESP32SpiABDiagnostics.h" +#endif #include #include #include @@ -306,6 +309,9 @@ __attribute__((noinline)) bool RadioProfileCLI::handleFastSettings(const char* k const auto caps = radio_->switchTuningCapabilities(); const auto current = radio_->switchTuning(); const char* suffix = key + (key[10] ? 11 : 10); +#if defined(MESH_HIL_ESP_SPI_AB) && MESH_HIL_ESP_SPI_AB + if (esp_spiab::handle(suffix, args, verb, reply, capacity)) return true; +#endif static const char names[] = "warm\0fs\0packet\0iq\0modem\0batch\0buffer"; const char* name = names; unsigned feature = 0; diff --git a/src/helpers/radiolib/ESP32BufferedRadioHal.h b/src/helpers/radiolib/ESP32BufferedRadioHal.h index 6ee29cdf3..c8d19638d 100644 --- a/src/helpers/radiolib/ESP32BufferedRadioHal.h +++ b/src/helpers/radiolib/ESP32BufferedRadioHal.h @@ -1,5 +1,8 @@ #pragma once #include "TunableRadioHal.h" +#if defined(MESH_HIL_ESP_SPI_AB) && MESH_HIL_ESP_SPI_AB +#include "ESP32SpiABDiagnostics.h" +#endif #ifndef MC_SX1262_SPI_HZ #define MC_SX1262_SPI_HZ 8000000 @@ -9,10 +12,27 @@ // status parsing unchanged; send each full-duplex buffer in one SPI operation. // SX1262 boards retain their configured default; LR1110 boards pass 16 MHz. class ESP32BufferedRadioHal : public TunableRadioHal { +#if defined(MESH_HIL_ESP_SPI_AB) && MESH_HIL_ESP_SPI_AB + uint32_t _hilClockDivider = 0; + bool _hilClockSeen = false; +#endif public: explicit ESP32BufferedRadioHal(SPIClass& bus, uint32_t hz = MC_SX1262_SPI_HZ) : TunableRadioHal(bus, hz, false, true, hz >= 16000000 ? 16000000 : 8000000) {} +#if defined(MESH_HIL_ESP_SPI_AB) && MESH_HIL_ESP_SPI_AB + void spiBeginTransaction() override { + ArduinoHal::spiBeginTransaction(); + // The base call owns the transaction locks and has installed the radio's + // divider. This SDK getter reads the live register without taking a lock. + const uint32_t divider = spi->getClockDivider(); + if (!_hilClockSeen || divider != _hilClockDivider) { + _hilClockSeen = true; + _hilClockDivider = divider; + mesh::esp_spiab::recordClock(divider, spiClockDivToFrequency(divider)); + } + } +#endif void spiTransfer(uint8_t* out, size_t len, uint8_t* in) override { if (!bufferedTransfersEnabled()) ArduinoHal::spiTransfer(out, len, in); else if (len) spi->transferBytes(out, in, len); diff --git a/src/helpers/radiolib/ESP32SpiABDiagnostics.h b/src/helpers/radiolib/ESP32SpiABDiagnostics.h new file mode 100644 index 000000000..4754a883d --- /dev/null +++ b/src/helpers/radiolib/ESP32SpiABDiagnostics.h @@ -0,0 +1,91 @@ +#pragma once + +// Private, read-only instrumentation for same-image SPI clock comparisons. +// Normal firmware omits both the capture and these CLI commands. +#if defined(MESH_HIL_ESP_SPI_AB) && MESH_HIL_ESP_SPI_AB +#if !defined(ESP32_PLATFORM) || !defined(MESH_HIL_PROFILE_TIMING) || !MESH_HIL_PROFILE_TIMING +#error "ESP SPI A/B diagnostics require ESP32 and profile timing" +#endif + +#include +#include "ProfileSwitchTiming.h" +#include +#include + +namespace mesh { namespace esp_spiab { + +struct ClockCapture { + uint32_t divider = 0, hz = 0, changes = 0; +}; + +inline ClockCapture& clockCapture() { + static ClockCapture capture; + return capture; +} + +inline void recordClock(uint32_t divider, uint32_t hz) { + auto& capture = clockCapture(); + capture.divider = divider; + capture.hz = hz; + ++capture.changes; +} + +// All callers and profile retunes run in the application thread. Copy each +// bounded page before formatting; there is no ISR writer and no extra radio +// transaction, lock, reset, or statistics mutation here. +inline bool handle(const char* suffix, const char* args, int verb, + char* reply, size_t capacity) { + const bool hw = !strcmp(suffix, "hw"), info = !strcmp(suffix, "hil"); + const bool timing = !strcmp(suffix, "time"), hist = !strcmp(suffix, "hist"); + if (!hw && !info && !timing && !hist) return false; + if (verb != 0) { + snprintf(reply, capacity, "Error: SPI A/B diagnostics are read-only"); + return true; + } + unsigned direction = 0, stage = 0, page = 0; + char extra; + if (((hw || info) && *args) + || (timing && (sscanf(args, "%u %u %c", &direction, &stage, &extra) != 2 + || direction > 1 || stage >= profiletiming::StageCount)) + || (hist && (sscanf(args, "%u %u %u %c", &direction, &stage, &page, &extra) != 3 + || direction > 1 || stage >= profiletiming::StageCount || page > 1))) { + snprintf(reply, capacity, "Error: get radio.fast.hw|hil; time D S; hist D S P"); + return true; + } + if (hw) { + const ClockCapture snapshot = clockCapture(); + snprintf(reply, capacity, "> divider=0x%08lX hz=%lu changes=%lu", + (unsigned long)snapshot.divider, (unsigned long)snapshot.hz, + (unsigned long)snapshot.changes); + return true; + } + const auto& capture = profiletiming::mesh_hil_profile_timing; + if (info) { + snprintf(reply, capacity, "> magic=0x%08lX ver=%lu bytes=%lu seq=%lu stages=%lu bins=%lu width=%lu", + (unsigned long)capture.magic, (unsigned long)capture.version, + (unsigned long)capture.size_bytes, (unsigned long)capture.sequence, + (unsigned long)capture.stage_count, (unsigned long)capture.histogram_count, + (unsigned long)capture.histogram_width_us); + } else { + const auto& stats = capture.direction[direction].stage[stage]; + if (timing) { + const uint32_t count = stats.count, high = stats.sum_high_us, low = stats.sum_low_us; + const uint32_t minimum = stats.min_us, maximum = stats.max_us, last = stats.last_us; + snprintf(reply, capacity, "> d=%u s=%u count=%lu sum_hi=%lu sum_lo=%lu min=%lu max=%lu last=%lu", + direction, stage, (unsigned long)count, (unsigned long)high, + (unsigned long)low, (unsigned long)minimum, (unsigned long)maximum, + (unsigned long)last); + } else { + uint32_t bins[8]; + for (unsigned i = 0; i < 8; ++i) bins[i] = stats.histogram[page * 8 + i]; + snprintf(reply, capacity, "> d=%u s=%u p=%u bins=%lu,%lu,%lu,%lu,%lu,%lu,%lu,%lu", + direction, stage, page, (unsigned long)bins[0], (unsigned long)bins[1], + (unsigned long)bins[2], (unsigned long)bins[3], (unsigned long)bins[4], + (unsigned long)bins[5], (unsigned long)bins[6], (unsigned long)bins[7]); + } + } + return true; +} + +} } // namespace mesh::esp_spiab +#endif diff --git a/test/test_esp32_spi_ab_diagnostics.py b/test/test_esp32_spi_ab_diagnostics.py new file mode 100644 index 000000000..1820b04f5 --- /dev/null +++ b/test/test_esp32_spi_ab_diagnostics.py @@ -0,0 +1,163 @@ +"""Execute the private clock proof and bounded timing snapshot interface.""" +from pathlib import Path +import os +import subprocess +import tempfile +import unittest + +from test_sx126x_buffered_radio_hal import MOCK + + +ROOT = Path(__file__).resolve().parents[1] + + +class Esp32SpiABDiagnosticsTests(unittest.TestCase): + def test_commands_reach_diagnostics_through_production_cli(self): + fixture = (ROOT / 'test/fixtures/radio_profiles/switch_tuning_test.cpp').read_text() + fixture = fixture.rsplit('\nint main() {', 1)[0] + fixture += r''' +#include +namespace mesh { namespace profiletiming { +extern "C" { +volatile Capture mesh_hil_profile_timing = { + Magic,Version,sizeof(Capture),0,ClockHz,StageCount,HistogramCount,HistogramWidthUs,0,0,{}}; +Work mesh_hil_profile_timing_work = {}; +} +} } +int main() { + TuningFixture f; + mesh::esp_spiab::recordClock(0x1000,8888888); + assert(!strcmp(f.cmd("get radio.fast.hw"),"> divider=0x00001000 hz=8888888 changes=1")); + assert(strstr(f.cmd("get radio.fast.time 1 10"),"d=1 s=10 count=0")); + assert(strstr(f.cmd("get radio.fast.hist 0 10 1"),"p=1 bins=0,0,0,0,0,0,0,0")); + assert(strstr(f.cmd("get radio.fast.hil"),"bytes=2192")); + assert(strstr(f.cmd("set radio.fast.hw 8",false),"read-only")); + assert(strstr(f.cmd("get radio.fast.time 2 10"),"Error:")); + assert(!strcmp(f.cmd("get radio.fast.buffer"),"> on")); + assert(f.radio.attempts==0 && f.fs.files.empty()); +} +''' + with tempfile.TemporaryDirectory() as directory: + work = Path(directory) + prelude = work / 'prelude.h' + prelude.write_text('#include \ninline uint32_t micros() { return 0; }\n', + encoding='ascii') + cpp, binary = work / 'cli.cpp', work / 'cli' + cpp.write_text(fixture, encoding='ascii') + built = subprocess.run([os.environ.get('CXX', 'g++'), '-std=c++17', + '-Wall', '-Wextra', '-DESP32_PLATFORM=1', '-DMESH_HIL_PROFILE_TIMING=1', + '-DMESH_HIL_ESP_SPI_AB=1', '-include', str(prelude), + '-I', str(ROOT / 'test/fixtures/radio_profiles'), + '-I', str(ROOT / 'test/fixtures/radio_profiles/mocks'), + '-I', str(ROOT / 'test/mocks'), '-I', str(ROOT / 'src'), + str(ROOT / 'src/helpers/RadioProfileCLI.cpp'), str(cpp), '-o', str(binary)], + capture_output=True, text=True) + self.assertEqual(built.returncode, 0, built.stdout + built.stderr) + subprocess.run([str(binary)], check=True) + + def test_live_divider_after_transaction_and_read_only_bounded_snapshots(self): + fixture = r''' +#include +#include +#include +#include +namespace mesh { namespace profiletiming { +extern "C" { +volatile Capture mesh_hil_profile_timing = { + Magic,Version,sizeof(Capture),0,ClockHz,StageCount,HistogramCount,HistogramWidthUs,0,0,{}}; +Work mesh_hil_profile_timing_work = {}; +} +} } +int main() { + SPIClass bus; + ESP32BufferedRadioHal hal(bus,8888888); + auto& clock=mesh::esp_spiab::clockCapture(); + assert(clock.changes==0); + hal.spiBeginTransaction(); + assert(bus.transactions==1 && clock.changes==1); + assert(clock.hz==8888888 && clock.divider==9); + hal.spiBeginTransaction(); + assert(bus.transactions==2 && clock.changes==1); + mesh::RadioSwitchTuning policy=hal.getTuning(); + policy.spi_mhz=8; + assert(hal.setTuning(policy)); + hal.spiBeginTransaction(); + assert(clock.hz==8000000 && clock.divider==10 && clock.changes==2); + assert(bus.bursts==0 && bus.bytes==0); + // The clock capture and timing statistics are never changed by getters. + auto& capture=mesh::profiletiming::mesh_hil_profile_timing; + auto& stats=capture.direction[1].stage[10]; + stats.count=0xffffffffU; stats.sum_high_us=7; stats.sum_low_us=42; + stats.min_us=199; stats.max_us=612; stats.last_us=201; + for(unsigned i=0;i<16;++i) stats.histogram[i]=0xffffffffU-i; + char reply[160]; + auto get=[&](const char* suffix,const char* args="") { + assert(mesh::esp_spiab::handle(suffix,args,0,reply,sizeof(reply))); + }; + get("hw"); assert(!strcmp(reply,"> divider=0x0000000A hz=8000000 changes=2")); + get("hil"); assert(strstr(reply,"magic=0x4D435054 ver=3 bytes=2192 seq=0")); + get("time","1 10"); + assert(!strcmp(reply,"> d=1 s=10 count=4294967295 sum_hi=7 sum_lo=42 min=199 max=612 last=201")); + get("hist","1 10 0"); + assert(strstr(reply,"p=0 bins=4294967295,4294967294")); + get("hist","1 10 1"); + assert(strstr(reply,"p=1 bins=4294967287,4294967286")); + assert(strstr(reply,"4294967280")); + for(const char* args:{"", "2 0", "0 11", "-1 0", "0 1 garbage"}) { + get("time",args); assert(!strncmp(reply,"Error:",6)); + } + get("hist","0 0 2"); assert(!strncmp(reply,"Error:",6)); + get("hw","extra"); assert(!strncmp(reply,"Error:",6)); + assert(mesh::esp_spiab::handle("hw","8",1,reply,sizeof(reply))); + assert(strstr(reply,"read-only")); + assert(!mesh::esp_spiab::handle("warm","",0,reply,sizeof(reply))); + for(unsigned size=0;size<=160;++size) { + char guarded[162]; memset(guarded,0x55,sizeof(guarded)); + assert(mesh::esp_spiab::handle("hist","1 10 0",0,guarded+1,size)); + assert(guarded[0]==0x55 && guarded[size+1]==0x55); + if(size) assert(memchr(guarded+1,0,size)); + } + assert(clock.changes==2 && stats.count==0xffffffffU && capture.sequence==0); + assert(bus.bursts==0 && bus.bytes==0); +} +''' + with tempfile.TemporaryDirectory() as directory: + work = Path(directory) + (work / 'hal/Arduino').mkdir(parents=True) + mock = MOCK.replace(' unsigned bursts=0, bytes=0, begins=0, ends=0;', + ' unsigned bursts=0, bytes=0, begins=0, ends=0, transactions=0, divider=0;\n' + ' uint32_t getClockDivider() { return divider; }') + mock = mock.replace(' virtual void init()', + ' virtual void spiBeginTransaction() { ++spi->transactions; ' + 'spi->divider=spiSettings.hz==8888888 ? 9 : 10; }\n' + ' virtual void init()') + mock += '\ninline uint32_t spiClockDivToFrequency(uint32_t d) { return 80000000/d; }\n' + (work / 'hal/Arduino/ArduinoHal.h').write_text(mock, encoding='ascii') + (work / 'Arduino.h').write_text('#pragma once\n#include \n' + 'inline uint32_t micros() { return 0; }\n', encoding='ascii') + cpp, binary = work / 'test.cpp', work / 'test' + cpp.write_text('#include \n' + fixture, encoding='ascii') + flags = [os.environ.get('CXX', 'g++'), '-std=c++11', '-Wall', '-Wextra', + '-Werror', '-DESP32_PLATFORM=1', '-DMESH_HIL_PROFILE_TIMING=1', + '-DMESH_HIL_ESP_SPI_AB=1', '-I', str(work), '-I', str(ROOT / 'src')] + built = subprocess.run(flags + [str(cpp), '-o', str(binary)], + capture_output=True, text=True) + self.assertEqual(built.returncode, 0, built.stdout + built.stderr) + subprocess.run([str(binary)], check=True) + + def test_flag_off_omits_capture_and_invalid_platforms_reject_opt_in(self): + source = '#include \nint main() {}\n' + for flags, succeeds in (([], True), (['-DMESH_HIL_ESP_SPI_AB=0'], True), + (['-DMESH_HIL_ESP_SPI_AB=1'], False), + (['-DMESH_HIL_ESP_SPI_AB=1', '-DESP32_PLATFORM=1'], False)): + with self.subTest(flags=flags): + built = subprocess.run([os.environ.get('CXX', 'g++'), '-std=c++11', + '-x', 'c++', '-fsyntax-only', '-I', str(ROOT / 'src'), *flags, '-'], + input=source, capture_output=True, text=True) + self.assertEqual(built.returncode == 0, succeeds, built.stderr) + if not succeeds: + self.assertIn('require ESP32 and profile timing', built.stderr) + + +if __name__ == '__main__': + unittest.main()