From 3801d49391cc6872aca3a4579475d118e8a725bd Mon Sep 17 00:00:00 2001 From: mikecarper Date: Fri, 23 Oct 2026 03:27:00 -0700 Subject: [PATCH] Attribute nRF retune stalls to observed interrupt and scheduler activity --- .github/workflows/run-unit-tests.yml | 1 + src/helpers/radiolib/NrfRadioIrqObserver.cpp | 43 +++++ src/helpers/radiolib/NrfRadioIrqObserver.h | 192 +++++++++++++++++++ src/helpers/radiolib/ProfileSwitchTiming.h | 17 ++ src/helpers/radiolib/RadioLibWrappers.cpp | 6 +- test/test_nrf_radio_irq_observer.py | 149 ++++++++++++++ 6 files changed, 405 insertions(+), 3 deletions(-) create mode 100644 src/helpers/radiolib/NrfRadioIrqObserver.cpp create mode 100644 src/helpers/radiolib/NrfRadioIrqObserver.h create mode 100644 test/test_nrf_radio_irq_observer.py diff --git a/.github/workflows/run-unit-tests.yml b/.github/workflows/run-unit-tests.yml index 99108ad99..443b9f41f 100644 --- a/.github/workflows/run-unit-tests.yml +++ b/.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 diff --git a/src/helpers/radiolib/NrfRadioIrqObserver.cpp b/src/helpers/radiolib/NrfRadioIrqObserver.cpp new file mode 100644 index 000000000..895638302 --- /dev/null +++ b/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 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 diff --git a/src/helpers/radiolib/NrfRadioIrqObserver.h b/src/helpers/radiolib/NrfRadioIrqObserver.h new file mode 100644 index 000000000..5369366a8 --- /dev/null +++ b/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 +#include +#include + +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 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(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(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 diff --git a/src/helpers/radiolib/ProfileSwitchTiming.h b/src/helpers/radiolib/ProfileSwitchTiming.h index a53870e1b..47436620b 100644 --- a/src/helpers/radiolib/ProfileSwitchTiming.h +++ b/src/helpers/radiolib/ProfileSwitchTiming.h @@ -8,6 +8,7 @@ #if MESH_HIL_PROFILE_TIMING #include +#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; diff --git a/src/helpers/radiolib/RadioLibWrappers.cpp b/src/helpers/radiolib/RadioLibWrappers.cpp index 533a788b6..93451b3f6 100644 --- a/src/helpers/radiolib/RadioLibWrappers.cpp +++ b/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 diff --git a/test/test_nrf_radio_irq_observer.py b/test/test_nrf_radio_irq_observer.py new file mode 100644 index 000000000..9ce3cd5ec --- /dev/null +++ b/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 +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 +#include +#include +@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 \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()