diff --git a/.github/workflows/run-unit-tests.yml b/.github/workflows/run-unit-tests.yml index 4b2b545ee..e1866f233 100644 --- a/.github/workflows/run-unit-tests.yml +++ b/.github/workflows/run-unit-tests.yml @@ -814,6 +814,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_profile_switch_timing.py -v python3 -B test/test_sx126x_nrf_rp_constructors.py -v python3 -B test/test_esp32_buffered_radio_targets.py -v python3 -B test/test_xiao_battery_safety.py -v diff --git a/src/helpers/radiolib/CustomSX1262Wrapper.h b/src/helpers/radiolib/CustomSX1262Wrapper.h index 7bbca4c80..135d460cc 100644 --- a/src/helpers/radiolib/CustomSX1262Wrapper.h +++ b/src/helpers/radiolib/CustomSX1262Wrapper.h @@ -3,6 +3,7 @@ #include "CustomSX1262.h" #include "RadioLibWrappers.h" +#include "ProfileSwitchTiming.h" #include "SX126xReset.h" #include "SX126xMorseRamp.h" #include "SX126xMorseReceiver.h" @@ -120,14 +121,30 @@ protected: bool applyParams(float freq, float bw, uint8_t sf, uint8_t cr) override { if (static_cast(_radio)->profileSwitchFailed()) return false; +#if MESH_HIL_PROFILE_TIMING + bool success = ((CustomSX1262 *)_radio)->setFrequency(freq) == RADIOLIB_ERR_NONE; + mesh::profiletiming::mark(mesh::profiletiming::Frequency, mesh::profiletiming::readClock()); + if (success) { + success = ((CustomSX1262 *)_radio)->setLoRaModulationParams(bw, sf, cr) == RADIOLIB_ERR_NONE; + mesh::profiletiming::mark(mesh::profiletiming::Modulation, mesh::profiletiming::readClock()); + } + if (success) { + success = updatePreamble(sf, bw); + mesh::profiletiming::mark(mesh::profiletiming::Preamble, mesh::profiletiming::readClock()); + } +#else bool success = ((CustomSX1262 *)_radio)->setFrequency(freq) == RADIOLIB_ERR_NONE && ((CustomSX1262 *)_radio)->setLoRaModulationParams(bw, sf, cr) == RADIOLIB_ERR_NONE && updatePreamble(sf, bw); +#endif if (!success) return false; PacketMillis pm = calcMaxPacketMillis(sf, bw, cr, preambleLengthForParams(sf, bw)); ((CustomSX1262 *)_radio)->setPreambleMillis(pm.preambleMillis); ((CustomSX1262 *)_radio)->setMaxPayloadMillis(pm.payloadMillis); +#if MESH_HIL_PROFILE_TIMING + mesh::profiletiming::mark(mesh::profiletiming::GuardMath, mesh::profiletiming::readClock()); +#endif return true; } diff --git a/src/helpers/radiolib/ProfileSwitchTiming.h b/src/helpers/radiolib/ProfileSwitchTiming.h new file mode 100644 index 000000000..887af47f2 --- /dev/null +++ b/src/helpers/radiolib/ProfileSwitchTiming.h @@ -0,0 +1,145 @@ +#pragma once + +// Private HIL instrumentation. Release builds contain neither its RAM state +// nor its timestamp/statistics calls. This does not alter radio commands. +#ifndef MESH_HIL_PROFILE_TIMING +#define MESH_HIL_PROFILE_TIMING 0 +#endif + +#if MESH_HIL_PROFILE_TIMING +#include + +namespace mesh { +namespace profiletiming { + +enum Stage : uint32_t { + BeginReconfigure = 0, Frequency, Modulation, Preamble, GuardMath, + ProtocolAndCache, RxResume, Tail, Whole, StageCount +}; +enum Result : uint32_t { Success = 0, Busy = 1, Failure = 2 }; +static constexpr uint32_t Magic = 0x4d435054; // MCPT +static constexpr uint32_t Version = 1; +static constexpr uint32_t HistogramCount = 16; +static constexpr uint32_t HistogramWidthUs = 64; +#if defined(NRF52_PLATFORM) +static constexpr uint32_t ClockDivisor = 64; +#else +static constexpr uint32_t ClockDivisor = 1; +#endif +static constexpr uint32_t ClockHz = ClockDivisor * 1000000; + +// All fields are uint32_t so the exact ELF has the same offsets on host and +// MCU; sums are split low/high words rather than ABI-dependent uint64_t. +struct StageStats { + uint32_t count, sum_low_us, sum_high_us, min_us, max_us, last_us; + uint32_t histogram[HistogramCount]; // final bucket includes >= 960 us +}; +struct DirectionStats { + uint32_t successes, busy, failures, last_result, last_mask; + uint32_t last_us[StageCount]; + StageStats stage[StageCount]; +}; +struct Capture { + uint32_t magic, version, size_bytes, sequence, clock_hz; + uint32_t stage_count, histogram_count, histogram_width_us; + uint32_t clock_state, clock_initializations; // bit0=already on, bit1=on now + DirectionStats direction[2]; // index is originating profile: 0->1, 1->0 +}; +struct Work { + uint32_t active, direction, start_ticks, previous_ticks, mask; + uint32_t duration_us[StageCount]; +}; + +// Read sequence, then the entire struct, then sequence again. Accept only +// equal even sequences and the expected magic/version/size. Never write it +// through SWD. Statistics publish after the measured switch has completed. +extern "C" { +extern volatile Capture mesh_hil_profile_timing; +extern Work mesh_hil_profile_timing_work; +} + +inline void barrier() { __asm__ __volatile__("" ::: "memory"); } + +// Call once during wrapper initialization, outside the measured switch. +// The nRF core enables trace and CYCCNT only; it does not enable debug/halt. +inline void initializeClock() { +#if defined(NRF52_PLATFORM) + const bool was_enabled = dwt_enabled(); + if (!was_enabled) dwt_enable(); + mesh_hil_profile_timing.clock_state = (was_enabled ? 1U : 0U) + | (dwt_enabled() ? 2U : 0U); +#else + mesh_hil_profile_timing.clock_state = 2; +#endif + ++mesh_hil_profile_timing.clock_initializations; +} + +inline uint32_t readClock() { +#if defined(NRF52_PLATFORM) + return DWT->CYCCNT; +#else + return static_cast(micros()); +#endif +} + +inline void begin(uint8_t from, uint8_t to, uint32_t now_ticks) { + auto& work = mesh_hil_profile_timing_work; + work.active = from < 2 && to < 2 && from != to; + if (!work.active) return; + work.direction = from; + work.start_ticks = work.previous_ticks = now_ticks; + work.mask = 0; + for (uint32_t i = 0; i < StageCount; ++i) work.duration_us[i] = 0; +} + +inline void mark(Stage stage, uint32_t now_ticks) { + auto& work = mesh_hil_profile_timing_work; + if (!work.active || stage >= Whole) return; + // Subtract raw cycles BEFORE converting to microseconds. Arduino's nRF + // micros() divides CYCCNT first and therefore wraps at about 67 seconds. + work.duration_us[stage] = (now_ticks - work.previous_ticks) / ClockDivisor; + work.previous_ticks = now_ticks; + work.mask |= uint32_t(1) << stage; +} + +inline void finish(Result result, uint32_t now_ticks) { + auto& work = mesh_hil_profile_timing_work; + if (!work.active) return; + work.active = 0; // restoration or other applyParams calls cannot append + work.duration_us[Whole] = (now_ticks - work.start_ticks) / ClockDivisor; + work.mask |= uint32_t(1) << Whole; + + auto& capture = mesh_hil_profile_timing; + ++capture.sequence; + barrier(); + auto& direction = capture.direction[work.direction]; + direction.last_result = result; + direction.last_mask = work.mask; + if (result == Success) ++direction.successes; + else if (result == Busy) ++direction.busy; + else ++direction.failures; + for (uint32_t i = 0; i < StageCount; ++i) { + const uint32_t duration = work.duration_us[i]; + direction.last_us[i] = duration; + if (result != Success || !(work.mask & (uint32_t(1) << i))) continue; + auto& stats = direction.stage[i]; + const uint32_t previous_low = stats.sum_low_us; + stats.sum_low_us = previous_low + duration; + if (stats.sum_low_us < previous_low) ++stats.sum_high_us; + if (stats.count == 0 || duration < stats.min_us) stats.min_us = duration; + if (duration > stats.max_us) stats.max_us = duration; + ++stats.count; + stats.last_us = duration; + const uint32_t bucket = duration / HistogramWidthUs; + ++stats.histogram[bucket < HistogramCount ? bucket : HistogramCount - 1]; + } + barrier(); + ++capture.sequence; +} + +static_assert(sizeof(Capture) == 40 + 2 * (20 + StageCount * (4 + 88)), + "Unexpected profile timing ABI"); + +} // namespace profiletiming +} // namespace mesh +#endif diff --git a/src/helpers/radiolib/RadioLibWrappers.cpp b/src/helpers/radiolib/RadioLibWrappers.cpp index d1cd24283..917195a78 100644 --- a/src/helpers/radiolib/RadioLibWrappers.cpp +++ b/src/helpers/radiolib/RadioLibWrappers.cpp @@ -3,6 +3,17 @@ #include "RadioLibWrappers.h" #include "RadioInterruptEvents.h" #include "RadioProfileChip.h" +#include "ProfileSwitchTiming.h" +#if MESH_HIL_PROFILE_TIMING +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 = {}; +} +} } +#endif #if MESH_ENABLE_TX_BEACONS #include "RadioPowerLimits.h" #endif @@ -225,6 +236,9 @@ void RadioLibWrapper::begin() { #endif #if MESH_ENABLE_TX_BEACONS if (_beacon_owned) return; +#endif +#if MESH_HIL_PROFILE_TIMING + mesh::profiletiming::initializeClock(); #endif (void)profileTimestamp(_profiles.enabled()); #ifdef USE_CC310_HW_CRYPTO @@ -598,10 +612,20 @@ mesh::RadioParamApplyResult RadioLibWrapper::tuneProfile(uint8_t profile) { if (!validateProfile(p)) return mesh::RadioParamApplyResult::FAILED; const bool dual_profile = _profiles.enabled(); const uint32_t started = profileTimestamp(dual_profile); +#if MESH_HIL_PROFILE_TIMING + mesh::profiletiming::begin(_active_profile, profile, mesh::profiletiming::readClock()); +#endif beginProfileRetune(isInRecvMode() && !_rx_ps_armed && !_rx_ps_enabled); const uint8_t resume = beginReconfigure(); +#if MESH_HIL_PROFILE_TIMING + mesh::profiletiming::mark(mesh::profiletiming::BeginReconfigure, mesh::profiletiming::readClock()); +#endif if (resume > 1) { endProfileRetune(resume == 2); // Only a BUSY guard deferred before changing hardware. +#if MESH_HIL_PROFILE_TIMING + mesh::profiletiming::finish(resume == 2 ? mesh::profiletiming::Busy + : mesh::profiletiming::Failure, mesh::profiletiming::readClock()); +#endif return resume == 2 ? mesh::RadioParamApplyResult::BUSY : mesh::RadioParamApplyResult::FAILED; } const float old_freq = _cur_freq, old_bw = _cur_bw; @@ -632,13 +656,24 @@ mesh::RadioParamApplyResult RadioLibWrapper::tuneProfile(uint8_t profile) { #endif _profile_refresh_required = false; _profile_repair_required = false; +#if MESH_HIL_PROFILE_TIMING + mesh::profiletiming::mark(mesh::profiletiming::ProtocolAndCache, mesh::profiletiming::readClock()); +#endif endReconfigure(resume); +#if MESH_HIL_PROFILE_TIMING + mesh::profiletiming::mark(mesh::profiletiming::RxResume, mesh::profiletiming::readClock()); +#endif applied = !resume || isInRecvMode(); } endProfileRetune(applied); if (applied) { ++_profiles.switches; } else { +#if MESH_HIL_PROFILE_TIMING + // Finish before rollback: restoration is a different operation and must + // not overwrite the failed hop's partial stage evidence. + mesh::profiletiming::finish(mesh::profiletiming::Failure, mesh::profiletiming::readClock()); +#endif ++_profiles.switch_failures; // RX restart is part of the transaction, not merely a best-effort tail. // Revoke any fast-RX capability and restore both the physical tuple and @@ -684,6 +719,10 @@ mesh::RadioParamApplyResult RadioLibWrapper::tuneProfile(uint8_t profile) { if (applied && resume && old_profile != profile) { _profiles.sampleSwitch(old_profile, profile, elapsed, millis()); } +#if MESH_HIL_PROFILE_TIMING + mesh::profiletiming::mark(mesh::profiletiming::Tail, mesh::profiletiming::readClock()); + mesh::profiletiming::finish(mesh::profiletiming::Success, mesh::profiletiming::readClock()); +#endif return applied ? mesh::RadioParamApplyResult::APPLIED : mesh::RadioParamApplyResult::FAILED; } diff --git a/test/test_profile_switch_timing.py b/test/test_profile_switch_timing.py new file mode 100644 index 000000000..91d099ddc --- /dev/null +++ b/test/test_profile_switch_timing.py @@ -0,0 +1,133 @@ +"""Execute optional RAM timing aggregation without radio hardware.""" +from pathlib import Path +import os +import subprocess +import tempfile +import unittest + +from test_radio_receive_contract import method +import test_radio_profile_scan as scan + +ROOT = Path(__file__).resolve().parents[1] + + +class ProfileSwitchTimingTest(unittest.TestCase): + def compile_run(self, source): + with tempfile.TemporaryDirectory() as directory: + folder = Path(directory) + (folder / "Arduino.h").write_text( + "#pragma once\n#include \n#include \n") + cpp, binary = folder / "test.cpp", folder / "test.exe" + cpp.write_text(source, encoding="ascii") + built = subprocess.run([os.environ.get("CXX", "g++"), "-std=c++17", + "-Wall", "-Wextra", "-I", str(folder), "-I", str(ROOT / "src"), + str(cpp), "-o", str(binary)], capture_output=True, text=True) + self.assertEqual(built.returncode, 0, built.stderr) + ran = subprocess.run([str(binary)], capture_output=True, text=True) + self.assertEqual(ran.returncode, 0, ran.stderr) + + @staticmethod + def production_globals(): + source = (ROOT / "src/helpers/radiolib/RadioLibWrappers.cpp").read_text() + return source.split("#if MESH_HIL_PROFILE_TIMING\n", 1)[1].split("#endif", 1)[0] + + def test_direction_histogram_clock_wrap_failures_and_split_sum(self): + self.compile_run(r''' +#include +#include +#define MESH_HIL_PROFILE_TIMING 1 +#define NRF52_PLATFORM 1 +struct FakeDwt { uint32_t CYCCNT=0; } fakeDwt; +#define DWT (&fakeDwt) +static bool clockEnabled=false; +static unsigned enableCalls=0; +bool dwt_enabled() { return clockEnabled; } +void dwt_enable() { clockEnabled=true; ++enableCalls; } +#include +@GLOBALS@ +int main() { + using namespace mesh::profiletiming; + auto& capture=mesh_hil_profile_timing; + assert(capture.magic==Magic && capture.size_bytes==1736); + assert(capture.clock_hz==64000000 && capture.sequence==0); + initializeClock(); + assert(enableCalls==1 && capture.clock_state==2); + initializeClock(); + assert(enableCalls==1 && capture.clock_state==3 && capture.clock_initializations==2); + fakeDwt.CYCCNT=1234; assert(readClock()==1234); + + // Raw counter wrap inside an awake hop is handled before /64 conversion. + uint32_t ticks=0xfffff000U; + begin(0,1,ticks); + for(uint32_t stage=0;stage(stage),ticks); + } + finish(Success,ticks); + assert(capture.sequence==2 && !(capture.sequence&1)); + const auto& forward=capture.direction[0]; + assert(forward.successes==1 && forward.busy==0 && forward.failures==0); + assert(forward.last_mask==511 && forward.last_us[Whole]==600); + assert(forward.stage[Whole].sum_low_us==600 && forward.stage[Whole].sum_high_us==0); + assert(forward.stage[Whole].min_us==600 && forward.stage[Whole].max_us==600); + assert(forward.stage[Whole].histogram[9]==1); + for(uint32_t stage=0;stage