Separate profile admission and standby costs in hardware timing captures

src/helpers/radiolib/ProfileSwitchTiming.h

@@ -13,12 +13,12 @@ namespace mesh {
 namespace profiletiming {
 
 enum Stage : uint32_t {
-  BeginReconfigure = 0, Frequency, Modulation, Preamble, GuardMath,
+  Admission = 0, Standby, PostStandby, 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 = 2;
+static constexpr uint32_t Version = 3;
 static constexpr uint32_t HistogramCount = 16;
 static constexpr uint32_t HistogramWidthUs = 64;
 #if defined(NRF52_PLATFORM)
@@ -109,6 +109,32 @@ inline void mark(Stage stage, uint32_t now_ticks) {
   work.mask |= uint32_t(1) << stage;
 }
 
+// Instrument beginReconfigure's existing operations without adding radio I/O.
+// Every exit records the admission and post-standby bookkeeping. If admission
+// defers or the receiver was idle, Standby is present with duration zero.
+class ReconfigureScope {
+  bool admission_marked_ = false;
+  bool standby_marked_ = false;
+ public:
+  void admissionComplete() {
+    mark(Admission, readClock());
+    admission_marked_ = true;
+  }
+  int16_t standbyResult(int16_t result) {
+    mark(Standby, readClock());
+    standby_marked_ = true;
+    return result;
+  }
+  ~ReconfigureScope() {
+    auto& work = mesh_hil_profile_timing_work;
+    if (!work.active) return;
+    const uint32_t now_ticks = readClock();
+    if (!admission_marked_) mark(Admission, now_ticks);
+    if (!standby_marked_) mark(Standby, work.previous_ticks);
+    mark(PostStandby, now_ticks);
+  }
+};
+
 inline void finish(Result result, uint32_t now_ticks) {
   auto& work = mesh_hil_profile_timing_work;
   if (!work.active) return;
@@ -149,6 +175,8 @@ inline void finish(Result result, uint32_t now_ticks) {
 
 static_assert(sizeof(Capture) == 40 + 2 * (20 + StageCount * (8 + 88)),
               "Unexpected profile timing ABI");
+static_assert(StageCount == 11 && sizeof(Capture) == 2192,
+              "Profile timing version 3 requires eleven stages and 2192 bytes");
 
 } // namespace profiletiming
 } // namespace mesh

src/helpers/radiolib/RadioLibWrappers.cpp

@@ -368,6 +368,9 @@ bool RadioLibWrapper::setTxPower(int8_t dbm) {
 }
 
 uint8_t RadioLibWrapper::beginReconfigure() {
+#if MESH_HIL_PROFILE_TIMING
+  mesh::profiletiming::ReconfigureScope profile_timing;
+#endif
 #if MESH_RADIO_TRACE_ENABLED
   mesh::radiotrace::trace().context(_radio, _active_profile, _profile_generation);
 #endif
@@ -382,7 +385,16 @@ uint8_t RadioLibWrapper::beginReconfigure() {
     if (base_state == STATE_TX_WAIT || isChipBusy()) return 2;
     claimRadioInterrupt();
     _rx_hold_continuous = false;
-    if (_radio->standby() != RADIOLIB_ERR_NONE) {
+#if MESH_HIL_PROFILE_TIMING
+    profile_timing.admissionComplete();
+#endif
+    if (
+#if MESH_HIL_PROFILE_TIMING
+        profile_timing.standbyResult(_radio->standby())
+#else
+        _radio->standby()
+#endif
+        != RADIOLIB_ERR_NONE) {
       state = STATE_IDLE;
       return 3;
     }
@@ -399,9 +411,18 @@ uint8_t RadioLibWrapper::beginReconfigure() {
     return 2;
   }
 
+#if MESH_HIL_PROFILE_TIMING
+  profile_timing.admissionComplete();
+#endif
   const bool resume_rx = base_state == STATE_RX;
   if (_rx_ps_armed || resume_rx) {
-    if (_radio->standby() != RADIOLIB_ERR_NONE) {
+    if (
+#if MESH_HIL_PROFILE_TIMING
+        profile_timing.standbyResult(_radio->standby())
+#else
+        _radio->standby()
+#endif
+        != RADIOLIB_ERR_NONE) {
       state = STATE_IDLE;
       _profile_refresh_required = _profile_repair_required = true;
       return 3;
@@ -617,9 +638,6 @@ mesh::RadioParamApplyResult RadioLibWrapper::tuneProfile(uint8_t profile) {
 #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

test/test_profile_switch_timing.py

@@ -48,7 +48,7 @@ void dwt_enable() { clockEnabled=true; ++enableCalls; }
 int main() {
   using namespace mesh::profiletiming;
   auto& capture=mesh_hil_profile_timing;
-  assert(capture.magic==Magic && capture.version==2 && capture.size_bytes==1808);
+  assert(capture.magic==Magic && capture.version==3 && capture.size_bytes==2192);
   assert(capture.clock_hz==64000000 && capture.sequence==0);
   initializeClock();
   assert(enableCalls==1 && capture.clock_state==2);
@@ -67,16 +67,16 @@ int main() {
   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.worst_us[Whole]==600 && forward.worst_us[Frequency]==50);
-  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);
+  assert(forward.last_mask==2047 && forward.last_us[Whole]==850);
+  assert(forward.worst_us[Whole]==850 && forward.worst_us[Frequency]==70);
+  assert(forward.stage[Whole].sum_low_us==850 && forward.stage[Whole].sum_high_us==0);
+  assert(forward.stage[Whole].min_us==850 && forward.stage[Whole].max_us==850);
+  assert(forward.stage[Whole].histogram[13]==1);
   for(uint32_t stage=0;stage<Whole;++stage)
     assert(forward.stage[stage].last_us==40+10*stage);
 
   // Aborts keep partial evidence but never inflate successful timing stats.
-  begin(1,0,100); mark(BeginReconfigure,100+1000*64); finish(Busy,100+1000*64);
+  begin(1,0,100); mark(Admission,100+1000*64); finish(Busy,100+1000*64);
   assert(capture.direction[1].busy==1 && capture.direction[1].successes==0);
   assert(capture.direction[1].stage[Whole].count==0);
   assert(capture.direction[1].last_us[Whole]==1000);
@@ -94,8 +94,8 @@ int main() {
   sum.sum_low_us=0xfffffff5U; sum.sum_high_us=3;
   begin(0,1,0); mark(Frequency,20*64); finish(Success,20*64);
   assert(sum.sum_low_us==9 && sum.sum_high_us==4);
-  assert(sum.min_us==20 && sum.max_us==50 && sum.count==2);
-  assert(forward.worst_us[Whole]==600 && forward.worst_us[Frequency]==50);
+  assert(sum.min_us==20 && sum.max_us==70 && sum.count==2);
+  assert(forward.worst_us[Whole]==850 && forward.worst_us[Frequency]==70);
   begin(1,0,0); mark(Frequency,960*64); finish(Success,960*64);
   assert(capture.direction[1].stage[Frequency].histogram[15]==1);
   begin(1,0,0); mark(Frequency,10000*64); finish(Success,10000*64);
@@ -124,6 +124,95 @@ int main() {
         fixture = scan.HARNESS.replace('@METHODS@', prefix + methods)
         self.compile_run('#define MESH_HIL_PROFILE_TIMING 1\n' + fixture)
 
+    def test_actual_admission_standby_and_post_guard_stages_cover_every_exit(self):
+        source = (ROOT / "src/helpers/radiolib/RadioLibWrappers.cpp").read_text()
+        implementation = method(source, "uint8_t RadioLibWrapper::beginReconfigure(")
+        fixture = r'''
+#include <cassert>
+#include <cstdint>
+#define MESH_HIL_PROFILE_TIMING 1
+#define MESH_ENABLE_TX_BEACONS 1
+#define RADIOLIB_ERR_NONE 0
+#define STATE_IDLE 0
+#define STATE_RX 1
+#define STATE_TX_WAIT 3
+static uint32_t now_us=0;
+uint32_t micros() { return now_us; }
+#include <helpers/radiolib/ProfileSwitchTiming.h>
+@GLOBALS@
+struct RadioLibWrapper {
+  bool _beacon_owned=false,_beacon_restoring=false,_cw_active=false;
+  bool _profile_repair_required=false,_rx_hold_continuous=true;
+  bool _rx_ps_armed=false,_profile_refresh_required=false;
+  bool pending=false,busy=false,receiving=false,post_irq=false;
+  uint8_t state=STATE_RX;
+  unsigned standby_calls=0;
+  int16_t standby_result=0;
+  struct Chip {
+    RadioLibWrapper* owner;
+    int16_t standby() {
+      ++owner->standby_calls;now_us+=20;
+      if(owner->post_irq) owner->pending=true;
+      return owner->standby_result;
+    }
+  } chip{this};
+  Chip* _radio=&chip;
+  bool hasPendingRadioInterrupt() { now_us+=2;return pending; }
+  bool isChipBusy() { now_us+=3;return busy; }
+  bool isReceivingPacket() { now_us+=5;return receiving; }
+  void claimRadioInterrupt() { now_us+=4;pending=false; }
+  uint8_t beginReconfigure();
+};
+@METHOD@
+int main() {
+  using namespace mesh::profiletiming;
+  auto& direction=mesh_hil_profile_timing.direction[0];
+  // Success, already idle, each admission guard, both standby failures,
+  // an IRQ arriving in standby, and the physical-repair branch.
+  for(unsigned scenario=0;scenario<13;++scenario) {
+    RadioLibWrapper radio;
+    uint8_t expected_result=2;
+    unsigned admission=0,standby=0,post=0,calls=0;
+    switch(scenario) {
+      case 0: expected_result=1;admission=10;standby=20;post=2;calls=1;break;
+      case 1: radio.state=STATE_IDLE;expected_result=0;admission=10;post=2;break;
+      case 2: radio.pending=true;admission=2;break;
+      case 3: radio.state=STATE_TX_WAIT;admission=2;break;
+      case 4: radio.busy=true;admission=5;break;
+      case 5: radio.receiving=true;admission=10;break;
+      case 6: radio._cw_active=true;break;
+      case 7: radio.standby_result=-1;expected_result=3;admission=10;standby=20;calls=1;break;
+      case 8: radio.post_irq=true;admission=10;standby=20;post=2;calls=1;break;
+      case 9: radio._profile_repair_required=true;expected_result=1;admission=7;standby=20;post=4;calls=1;break;
+      case 10: radio._profile_repair_required=true;radio.busy=true;admission=3;break;
+      case 11: radio._profile_repair_required=true;radio.standby_result=-1;
+        expected_result=3;admission=7;standby=20;calls=1;break;
+      case 12: radio._beacon_owned=true;break;
+    }
+    now_us=0;begin(0,1,now_us);
+    const uint32_t samples=direction.stage[Admission].count;
+    assert(radio.beginReconfigure()==expected_result);
+    assert(radio.standby_calls==calls);
+    const Result result=expected_result<2 ? Success : expected_result==2 ? Busy : Failure;
+    finish(result,now_us);
+    assert(direction.last_mask==((1U<<Admission)|(1U<<Standby)|(1U<<PostStandby)|(1U<<Whole)));
+    assert(direction.last_us[Admission]==admission);
+    assert(direction.last_us[Standby]==standby);
+    assert(direction.last_us[PostStandby]==post);
+    assert(direction.last_us[Whole]==admission+standby+post);
+    // Even absent standby has a zero sample on successful transactions;
+    // partial/failing operations cannot contaminate successful aggregates.
+    assert(direction.stage[Admission].count==samples+unsigned(result==Success));
+    assert(direction.stage[Standby].count==direction.stage[Admission].count);
+    assert(direction.stage[PostStandby].count==direction.stage[Admission].count);
+  }
+  assert(direction.successes==3 && direction.busy==8 && direction.failures==2);
+  assert(direction.stage[Standby].min_us==0 && direction.stage[Standby].max_us==20);
+  assert(direction.worst_us[Whole]==32 && direction.worst_us[Admission]==10);
+}
+'''.replace("@GLOBALS@", self.production_globals()).replace("@METHOD@", implementation)
+        self.compile_run(fixture)
+
     def test_disabled_header_has_no_instrumentation_or_ram_definition(self):
         source = '#include <helpers/radiolib/ProfileSwitchTiming.h>\nint main() {}\n'
         preprocessed = subprocess.run([os.environ.get('CXX', 'g++'), '-E', '-P',