Attribute nRF retune stalls to observed interrupt and scheduler activity

.github/workflows/run-unit-tests.yml

@@ -819,6 +819,7 @@ jobs:
           python3 -B test/test_nrf_radio_priority_lease.py -v
           python3 -B test/test_nrf_radio_priority_integration.py -v
           python3 -B test/test_nrf_radio_usb_irq_guard.py -v
+          python3 -B test/test_nrf_radio_irq_observer.py -v
           python3 -B test/test_nrf_radio_spi_startup_diag.py -v
           python3 -B test/test_sx126x_nrf_rp_constructors.py -v
           python3 -B test/test_esp32_buffered_radio_targets.py -v

src/helpers/radiolib/NrfRadioIrqObserver.cpp

@@ -0,0 +1,43 @@
+#include "NrfRadioIrqObserver.h"
+
+#if MESH_HIL_IRQ_TIMING
+namespace mesh { namespace irqobserver {
+extern "C" {
+volatile Counter mesh_hil_irq_counters[SourceCount] = {};
+volatile uint32_t mesh_hil_irq_selected[TaskKindCount + 2] = {};
+volatile Capture mesh_hil_radio_irqs = {
+    0x4d434952, 1, sizeof(Capture), 0, SourceCount, 0, 0, 0, 0, 0, {}};
+}
+std::atomic<uint32_t> revision{0};
+Work work;
+} }
+
+// These are ordinary C handlers. Do not wrap SVC/PendSV: their naked
+// context-switch assembly requires the original exception LR/PSP contract.
+// Final ELF vectors/calls must be checked; weak aliases or LTO can bypass
+// a linker wrapper. No priority, masking, task, USB or device policy changes.
+#define MESH_OBSERVE_IRQ(symbol, source) \
+extern "C" void __real_##symbol(void); \
+extern "C" void __wrap_##symbol(void) { \
+  const uint32_t started = mesh::irqobserver::clock(); \
+  __real_##symbol(); \
+  mesh::irqobserver::record(mesh::irqobserver::source, mesh::irqobserver::clock() - started); \
+}
+MESH_OBSERVE_IRQ(RTC1_IRQHandler, Rtc1)
+MESH_OBSERVE_IRQ(GPIOTE_IRQHandler, Gpiote)
+MESH_OBSERVE_IRQ(UARTE0_UART0_IRQHandler, Uart0)
+MESH_OBSERVE_IRQ(UARTE1_IRQHandler, Uart1)
+MESH_OBSERVE_IRQ(POWER_CLOCK_IRQHandler, PowerClock)
+MESH_OBSERVE_IRQ(USBD_IRQHandler, Usb)
+#undef MESH_OBSERVE_IRQ
+
+extern "C" void __real_vTaskSwitchContext(void);
+extern "C" void __wrap_vTaskSwitchContext(void) {
+  const uint32_t started = mesh::irqobserver::clock();
+  __real_vTaskSwitchContext();
+  const uint32_t cycles = mesh::irqobserver::clock() - started;
+  // In the pinned SDK this is a non-blocking name lookup from the newly
+  // selected TCB. It uses no critical section or RTOS state mutation.
+  mesh::irqobserver::record(mesh::irqobserver::Scheduler, cycles, pcTaskGetName(nullptr));
+}
+#endif

src/helpers/radiolib/NrfRadioIrqObserver.h

@@ -0,0 +1,192 @@
+#pragma once
+
+#ifndef MESH_HIL_IRQ_TIMING
+#define MESH_HIL_IRQ_TIMING 0
+#endif
+#if MESH_HIL_IRQ_TIMING != 0 && MESH_HIL_IRQ_TIMING != 1
+#error "IRQ timing observer flag must be 0 or 1"
+#endif
+#if MESH_HIL_IRQ_TIMING
+#if !defined(NRF52_PLATFORM) || !defined(MESH_HIL_PROFILE_TIMING) || !MESH_HIL_PROFILE_TIMING
+#error "IRQ timing observer requires nRF52 HIL profile timing"
+#endif
+#include <Arduino.h>
+#include <atomic>
+#include <stdint.h>
+
+namespace mesh { namespace irqobserver {
+enum Source : uint32_t { Rtc1, Gpiote, Uart0, Uart1, PowerClock, Usb, Scheduler, SourceCount };
+enum TaskKind : uint32_t { LoopTask, TimerTask, UsbTask, OtherTask, TaskKindCount };
+struct Counter { uint32_t sequence, calls, cycles; };
+struct Sample {
+  uint32_t calls[SourceCount], cycles[SourceCount];
+  uint32_t selected[TaskKindCount], selected_name[2];
+};
+struct Direction {
+  uint32_t last_valid, worst_valid, last_ticks, worst_ticks;
+  Sample last, worst;
+};
+struct Capture {
+  uint32_t magic, version, size_bytes, sequence, source_count;
+  uint32_t snapshots, retries, snapshot_failures;
+  uint32_t last_result, last_direction;
+  Direction direction[2];
+};
+struct Work {
+  Sample begin{}, end{};
+  uint32_t start_ticks = 0, end_ticks = 0;
+  bool active = false, begin_valid = false, end_valid = false;
+};
+extern "C" {
+extern volatile Counter mesh_hil_irq_counters[SourceCount];
+extern volatile uint32_t mesh_hil_irq_selected[TaskKindCount + 2];
+extern volatile Capture mesh_hil_radio_irqs;
+}
+extern std::atomic<uint32_t> revision;
+extern Work work;
+
+inline void barrier() {
+#if defined(__arm__) || defined(__thumb__)
+  __asm__ __volatile__("dmb" ::: "memory");
+#else
+  __asm__ __volatile__("" ::: "memory");
+#endif
+}
+inline uint32_t clock() { return DWT->CYCCNT; }
+
+// A source cannot interrupt itself. Other sources may nest; their own
+// counters remain independent. Cycles are inclusive handler BODY time, so
+// nested source totals must not be added as disjoint CPU time. Hardware
+// exception entry/exit and the observer's bookkeeping are not in this sum.
+inline void record(Source source, uint32_t cycles, const char* selected_name = nullptr) {
+  auto& counter = mesh_hil_irq_counters[source];
+  ++counter.sequence;
+  barrier();
+  ++counter.calls;
+  counter.cycles += cycles;
+  if (source == Scheduler) {
+    uint32_t words[2] = {};
+    if (selected_name) {
+      for (unsigned i = 0; i < 8; ++i) {
+        const uint8_t byte = static_cast<uint8_t>(selected_name[i]);
+        if (!byte) break;
+        words[i / 4] |= uint32_t(byte) << (8 * (i % 4));
+      }
+    }
+    const TaskKind kind = words[0] == 0x706f6f6c ? LoopTask
+        : (words[0] & 0x00ffffff) == 0x00726d54 ? TimerTask
+        : words[0] == 0x64627375 ? UsbTask : OtherTask;
+    ++mesh_hil_irq_selected[kind];
+    mesh_hil_irq_selected[TaskKindCount] = words[0];
+    mesh_hil_irq_selected[TaskKindCount + 1] = words[1];
+  }
+  barrier();
+  ++counter.sequence;
+  revision.fetch_add(1, std::memory_order_release);
+}
+
+inline bool readCounter(Source source, Sample& sample) {
+  const auto& counter = mesh_hil_irq_counters[source];
+  for (unsigned attempt = 0; attempt < 8; ++attempt) {
+    const uint32_t before = counter.sequence;
+    if (before & 1) continue;
+    barrier();
+    const uint32_t candidate_calls = counter.calls;
+    const uint32_t candidate_cycles = counter.cycles;
+    uint32_t selected[TaskKindCount + 2] = {};
+    if (source == Scheduler) {
+      for (unsigned i = 0; i < TaskKindCount + 2; ++i) selected[i] = mesh_hil_irq_selected[i];
+    }
+    barrier();
+    if (before == counter.sequence) {
+      sample.calls[source] = candidate_calls;
+      sample.cycles[source] = candidate_cycles;
+      if (source == Scheduler) {
+        for (unsigned i = 0; i < TaskKindCount; ++i) sample.selected[i] = selected[i];
+        sample.selected_name[0] = selected[TaskKindCount];
+        sample.selected_name[1] = selected[TaskKindCount + 1];
+      }
+      return true;
+    }
+  }
+  return false;
+}
+
+// Retry rather than mask any IRQ. The revision proves there was no completed
+// observed handler between the first counter read and the clock endpoint.
+// A bounded failure invalidates attribution while retaining ordinary timing.
+inline bool snapshot(Sample& sample, uint32_t& ticks) {
+  ++mesh_hil_radio_irqs.snapshots;
+  for (unsigned attempt = 0; attempt < 8; ++attempt) {
+    const uint32_t before = revision.load(std::memory_order_acquire);
+    bool valid = true;
+    for (uint32_t i = 0; i < SourceCount; ++i)
+      valid = readCounter(static_cast<Source>(i), sample) && valid;
+    const uint32_t candidate_ticks = clock();
+    if (valid && before == revision.load(std::memory_order_acquire)) {
+      ticks = candidate_ticks;
+      return true;
+    }
+    ++mesh_hil_radio_irqs.retries;
+  }
+  ++mesh_hil_radio_irqs.snapshot_failures;
+  ticks = clock();
+  return false;
+}
+
+inline uint32_t begin() {
+  work.active = true;
+  work.end_valid = false;
+  work.begin_valid = snapshot(work.begin, work.start_ticks);
+  return work.start_ticks;
+}
+inline uint32_t endpoint() {
+  if (!work.active) return clock();
+  work.end_valid = snapshot(work.end, work.end_ticks);
+  return work.end_ticks;
+}
+inline void finish(uint32_t direction_index, uint32_t result, bool worst) {
+  if (!work.active || direction_index > 1) return;
+  work.active = false;
+  auto& capture = mesh_hil_radio_irqs;
+  ++capture.sequence;
+  barrier();
+  capture.last_result = result;
+  capture.last_direction = direction_index;
+  auto& direction = capture.direction[direction_index];
+  direction.last_valid = work.begin_valid && work.end_valid;
+  direction.last_ticks = work.end_ticks - work.start_ticks;
+  if (worst) {
+    direction.worst_valid = direction.last_valid;
+    direction.worst_ticks = direction.last_ticks;
+  }
+  for (uint32_t i = 0; i < SourceCount; ++i) {
+    const uint32_t calls = direction.last_valid ? work.end.calls[i] - work.begin.calls[i] : 0;
+    const uint32_t cycles = direction.last_valid ? work.end.cycles[i] - work.begin.cycles[i] : 0;
+    direction.last.calls[i] = calls;
+    direction.last.cycles[i] = cycles;
+    if (worst) {
+      direction.worst.calls[i] = calls;
+      direction.worst.cycles[i] = cycles;
+    }
+  }
+  for (uint32_t i = 0; i < TaskKindCount; ++i) {
+    const uint32_t selected = direction.last_valid ? work.end.selected[i] - work.begin.selected[i] : 0;
+    direction.last.selected[i] = selected;
+    if (worst) direction.worst.selected[i] = selected;
+  }
+  for (unsigned i = 0; i < 2; ++i) {
+    // Names only describe an actual selection within this hop, never a stale
+    // last selection from a previous hop with no scheduling activity.
+    const uint32_t name = direction.last_valid && direction.last.calls[Scheduler]
+        ? work.end.selected_name[i] : 0;
+    direction.last.selected_name[i] = name;
+    if (worst) direction.worst.selected_name[i] = name;
+  }
+  barrier();
+  ++capture.sequence;
+}
+static_assert(sizeof(Capture) == 392 && sizeof(Counter) == 12,
+              "Unexpected IRQ observer ABI");
+} } // namespace mesh::irqobserver
+#endif

src/helpers/radiolib/ProfileSwitchTiming.h

@@ -8,6 +8,7 @@
 
 #if MESH_HIL_PROFILE_TIMING
 #include <stdint.h>
+#include "NrfRadioIrqObserver.h"
 
 namespace mesh {
 namespace profiletiming {
@@ -89,11 +90,24 @@ inline uint32_t readClock() {
 #endif
 }
 
+inline uint32_t readEndpointClock() {
+#if MESH_HIL_IRQ_TIMING
+  return mesh::irqobserver::endpoint();
+#else
+  return readClock();
+#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;
+#if MESH_HIL_IRQ_TIMING
+  // Establish a coherent IRQ counter/time baseline before radio work. This
+  // excludes the observer's snapshot setup from its own timing window.
+  now_ticks = mesh::irqobserver::begin();
+#endif
   work.start_ticks = work.previous_ticks = now_ticks;
   work.mask = 0;
   for (uint32_t i = 0; i < StageCount; ++i) work.duration_us[i] = 0;
@@ -148,6 +162,9 @@ inline void finish(Result result, uint32_t now_ticks) {
   auto& direction = capture.direction[work.direction];
   const bool worst = result == Success && (direction.stage[Whole].count == 0
       || work.duration_us[Whole] > direction.stage[Whole].max_us);
+#if MESH_HIL_IRQ_TIMING
+  mesh::irqobserver::finish(work.direction, result, worst);
+#endif
   direction.last_result = result;
   direction.last_mask = work.mask;
   if (result == Success) ++direction.successes;

src/helpers/radiolib/RadioLibWrappers.cpp

@@ -657,7 +657,7 @@ mesh::RadioParamApplyResult RadioLibWrapper::tuneProfile(uint8_t profile) {
   if (resume > 1) {
     endProfileRetune(resume == 2);  // Only a BUSY guard deferred before changing hardware.
 #if MESH_HIL_PROFILE_TIMING
-    const uint32_t finished_ticks = mesh::profiletiming::readClock();
+    const uint32_t finished_ticks = mesh::profiletiming::readEndpointClock();
 #if MC_NRF_RADIO_PROFILE_USB_IRQ_GUARD
     profile_usb_irq.release();
 #endif
@@ -713,7 +713,7 @@ mesh::RadioParamApplyResult RadioLibWrapper::tuneProfile(uint8_t profile) {
 #if MESH_HIL_PROFILE_TIMING
     // Finish before rollback: restoration is a different operation and must
     // not overwrite the failed hop's partial stage evidence.
-    const uint32_t finished_ticks = mesh::profiletiming::readClock();
+    const uint32_t finished_ticks = mesh::profiletiming::readEndpointClock();
 #if MC_NRF_RADIO_PROFILE_USB_IRQ_GUARD
     profile_usb_irq.release();
 #endif
@@ -769,7 +769,7 @@ mesh::RadioParamApplyResult RadioLibWrapper::tuneProfile(uint8_t profile) {
   }
 #if MESH_HIL_PROFILE_TIMING
   mesh::profiletiming::mark(mesh::profiletiming::Tail, mesh::profiletiming::readClock());
-  const uint32_t finished_ticks = mesh::profiletiming::readClock();
+  const uint32_t finished_ticks = mesh::profiletiming::readEndpointClock();
 #if MC_NRF_RADIO_PROFILE_USB_IRQ_GUARD
   profile_usb_irq.release();
 #endif

test/test_nrf_radio_irq_observer.py

@@ -0,0 +1,149 @@
+"""Execute default-off IRQ body observation and correlated worst-hop deltas."""
+from pathlib import Path
+import os
+import subprocess
+import tempfile
+import unittest
+
+import test_profile_switch_timing as timing
+
+ROOT=Path(__file__).resolve().parents[1]
+SOURCE=ROOT/'src/helpers/radiolib/NrfRadioIrqObserver.cpp'
+
+ARDUINO=r'''
+#pragma once
+#include <cstdint>
+struct DwtMock { uint32_t CYCCNT=0; };
+extern DwtMock dwt;
+#define DWT (&dwt)
+inline bool dwt_enabled() { return true; }
+inline void dwt_enable() {}
+const char* pcTaskGetName(void* task);
+'''
+
+FIXTURE=r'''
+#include <cassert>
+#include <Arduino.h>
+#include <helpers/radiolib/ProfileSwitchTiming.h>
+@TIMING_GLOBALS@
+DwtMock dwt;
+unsigned real_calls[7]{},durations[7]={640,128,192,256,320,384,448};
+bool nested=false;
+const char* selected_task_name="loop";
+const char* pcTaskGetName(void* task) { assert(task==nullptr);return selected_task_name; }
+extern "C" void __wrap_RTC1_IRQHandler();
+extern "C" void __wrap_GPIOTE_IRQHandler();
+extern "C" void __wrap_UARTE0_UART0_IRQHandler();
+extern "C" void __wrap_UARTE1_IRQHandler();
+extern "C" void __wrap_POWER_CLOCK_IRQHandler();
+extern "C" void __wrap_USBD_IRQHandler();
+extern "C" void __wrap_vTaskSwitchContext();
+extern "C" void __real_RTC1_IRQHandler() {
+  ++real_calls[0];dwt.CYCCNT+=durations[0];
+  if(nested) __wrap_GPIOTE_IRQHandler();
+}
+#define REAL_HANDLER(symbol,index) extern "C" void __real_##symbol() { ++real_calls[index];dwt.CYCCNT+=durations[index]; }
+REAL_HANDLER(GPIOTE_IRQHandler,1)
+REAL_HANDLER(UARTE0_UART0_IRQHandler,2)
+REAL_HANDLER(UARTE1_IRQHandler,3)
+REAL_HANDLER(POWER_CLOCK_IRQHandler,4)
+REAL_HANDLER(USBD_IRQHandler,5)
+REAL_HANDLER(vTaskSwitchContext,6)
+int main() {
+  namespace obs=mesh::irqobserver;
+  namespace timing=mesh::profiletiming;
+  auto& capture=obs::mesh_hil_radio_irqs;
+  assert(capture.magic==0x4d434952 && capture.version==1 && capture.size_bytes==392 && capture.source_count==7);
+  // Actual wrappers forward every source exactly once, with no active hop.
+  __wrap_UARTE0_UART0_IRQHandler();__wrap_UARTE1_IRQHandler();
+  __wrap_POWER_CLOCK_IRQHandler();__wrap_USBD_IRQHandler();__wrap_vTaskSwitchContext();
+  for(unsigned i=2;i<7;++i) assert(real_calls[i]==1);
+  // Nested source time is explicitly inclusive in its parent; deltas remain
+  // per source and are attached to the same worst successful physical hop.
+  dwt.CYCCNT=100;durations[0]=640;durations[1]=128;nested=true;
+  timing::begin(0,1,timing::readClock());
+  __wrap_RTC1_IRQHandler();
+  const auto endpoint=timing::readEndpointClock();
+  assert(endpoint==868);
+  __wrap_USBD_IRQHandler(); // Scheduling after endpoint must not enter deltas.
+  timing::finish(timing::Success,endpoint);
+  auto& direction=capture.direction[0];
+  assert(direction.last_valid && direction.worst_valid && direction.last_ticks==768);
+  assert(direction.last.calls[obs::Rtc1]==1 && direction.last.cycles[obs::Rtc1]==768);
+  assert(direction.last.calls[obs::Gpiote]==1 && direction.last.cycles[obs::Gpiote]==128);
+  assert(direction.last.calls[obs::Usb]==0 && direction.last.cycles[obs::Usb]==0);
+  assert(direction.worst.cycles[obs::Rtc1]==768);
+  assert(timing::mesh_hil_profile_timing.direction[0].stage[timing::Whole].max_us==12);
+  // A smaller successful hop updates last but preserves correlated worst.
+  nested=false;durations[0]=64;
+  timing::begin(0,1,timing::readClock());__wrap_RTC1_IRQHandler();
+  timing::finish(timing::Success,timing::readEndpointClock());
+  assert(direction.last.cycles[obs::Rtc1]==64 && direction.worst.cycles[obs::Rtc1]==768);
+  assert(direction.worst_ticks==768);
+  // Failure records its own IRQ evidence without replacing successful worst.
+  selected_task_name="Tmr Svc";
+  timing::begin(0,1,timing::readClock());__wrap_vTaskSwitchContext();
+  timing::finish(timing::Failure,timing::readEndpointClock());
+  assert(capture.last_result==timing::Failure && direction.last.calls[obs::Scheduler]==1);
+  assert(direction.last.selected[obs::TimerTask]==1 && direction.last.selected[obs::LoopTask]==0);
+  assert(direction.last.selected_name[0]==0x20726d54 && direction.last.selected_name[1]==0x00637653);
+  assert(direction.worst.cycles[obs::Rtc1]==768 && direction.worst.calls[obs::Scheduler]==0);
+  assert(direction.worst.selected_name[0]==0);
+  // Both DWT and per-source 32-bit counters use modular hop deltas.
+  obs::mesh_hil_irq_counters[obs::Uart1].calls=UINT32_MAX;
+  obs::mesh_hil_irq_counters[obs::Uart1].cycles=UINT32_MAX-10;
+  dwt.CYCCNT=UINT32_MAX-31;durations[3]=64;
+  timing::begin(1,0,timing::readClock());__wrap_UARTE1_IRQHandler();
+  timing::finish(timing::Success,timing::readEndpointClock());
+  assert(capture.direction[1].last_ticks==64 && capture.direction[1].last.calls[obs::Uart1]==1);
+  assert(capture.direction[1].last.cycles[obs::Uart1]==64);
+  // A permanently odd writer sequence cannot hang the application or publish
+  // stale counter data as valid attribution. Timing itself remains available.
+  obs::mesh_hil_irq_counters[obs::Gpiote].sequence=1;
+  const auto failures=capture.snapshot_failures;
+  timing::begin(1,0,timing::readClock());
+  obs::mesh_hil_irq_counters[obs::Gpiote].sequence=2;
+  dwt.CYCCNT+=128;
+  timing::finish(timing::Success,timing::readEndpointClock());
+  assert(capture.snapshot_failures==failures+1 && !capture.direction[1].last_valid);
+  for(unsigned i=0;i<7;++i) {
+    assert(capture.direction[1].last.calls[i]==0 && capture.direction[1].last.cycles[i]==0);
+  }
+  assert(capture.sequence%2==0 && capture.snapshots==10 && capture.retries>=8);
+}
+'''
+
+
+class NrfRadioIrqObserverTests(unittest.TestCase):
+    def test_actual_wrappers_and_profile_timing_keep_correlated_stable_irq_deltas(self):
+        with tempfile.TemporaryDirectory() as directory:
+            folder=Path(directory)
+            (folder/'Arduino.h').write_text(ARDUINO,encoding='ascii')
+            source=folder/'test.cpp'
+            source.write_text(FIXTURE.replace('@TIMING_GLOBALS@',
+                timing.ProfileSwitchTimingTest.production_globals()),encoding='ascii')
+            binary=folder/'test'
+            built=subprocess.run([os.environ.get('CXX','c++'),'-std=c++17','-Wall','-Wextra','-Werror',
+                '-fsanitize=address,undefined','-fno-sanitize-recover=all','-fno-pie','-no-pie',
+                '-DNRF52_PLATFORM','-DMESH_HIL_PROFILE_TIMING=1','-DMESH_HIL_IRQ_TIMING=1',
+                '-I',str(folder),'-I',str(ROOT/'src'),str(source),str(SOURCE),'-o',str(binary)],
+                capture_output=True,text=True,env={**os.environ,'TMPDIR':str(folder)})
+            self.assertEqual(built.returncode,0,built.stderr)
+            ran=subprocess.run([str(binary)],capture_output=True,text=True)
+            self.assertEqual(ran.returncode,0,ran.stdout+ran.stderr)
+
+    def test_disabled_observer_has_no_code_ram_or_sdk_dependency(self):
+        result=subprocess.run([os.environ.get('CXX','c++'),'-E','-P',str(SOURCE)],capture_output=True,text=True)
+        self.assertEqual(result.returncode,0,result.stderr)
+        self.assertFalse(result.stdout.strip())
+
+    def test_observer_requires_hil_nrf(self):
+        for flags in ([],['-DNRF52_PLATFORM'],['-DMESH_HIL_PROFILE_TIMING=1']):
+            result=subprocess.run([os.environ.get('CXX','c++'),'-E','-x','c++',
+                '-DMESH_HIL_IRQ_TIMING=1',*flags,'-I',str(ROOT/'src'),'-'],
+                input='#include <helpers/radiolib/NrfRadioIrqObserver.h>\n',capture_output=True,text=True)
+            self.assertNotEqual(result.returncode,0)
+            self.assertIn('requires nRF52 HIL profile timing',result.stderr)
+
+
+if __name__=='__main__':unittest.main()