diff --git a/.github/workflows/esp32p4-smv-injector.yml b/.github/workflows/esp32p4-smv-injector.yml index d73731207..b43450b0c 100644 --- a/.github/workflows/esp32p4-smv-injector.yml +++ b/.github/workflows/esp32p4-smv-injector.yml @@ -55,6 +55,28 @@ jobs: grep -qx 'CONFIG_ESP32P4_SELECTS_REV_LESS_V3=y' sdkconfig echo 'ESP32-P4 pre-v3 build policy: PASS' + - name: Verify realtime START and telemetry boundary policy + run: | + set -euo pipefail + python3 - <<'PY' + from pathlib import Path + + source = Path('main/app_main.cpp').read_text(encoding='utf-8') + start_begin = source.index('if (take_start_request())') + start_end = source.index('if (!live_tx_running())', start_begin) + start_block = source[start_begin:start_end] + clock_start = start_block.rindex( + 'sample_clock = start_sample_clock(task_handle, active_profile.publisher_rate_hz);' + ) + assert start_block.rindex('ESP_LOGI') < clock_start + assert 'ESP_LOG' not in start_block[clock_start:] + assert 'static_assert(std::atomic::is_always_lock_free);' in source + assert 'g_sample_tick_total.fetch_add(1U, std::memory_order_relaxed);' in source + assert 'elapsed_ticks) * 1000000ULL' in source + assert 'rate_baseline_valid = true;' in source + print('Realtime boundary policy: PASS - timer starts after formatting and telemetry rate is elapsed-time normalized') + PY + - name: Build firmware run: source /opt/esp/idf/export.sh && idf.py build diff --git a/apps/arstack_studio/release/freeze-manifest.json b/apps/arstack_studio/release/freeze-manifest.json index 74e1fcaae..cd5855d7c 100644 --- a/apps/arstack_studio/release/freeze-manifest.json +++ b/apps/arstack_studio/release/freeze-manifest.json @@ -38,5 +38,20 @@ "autoStartAfterReconnect": false, "physicalAcceptanceRequiredBeforeMergeOrTag": true }, - "exceptions": [] + "exceptions": [ + { + "path": "embedded/esp32p4_smv_injector/main/app_main.cpp", + "blockerIssue": "#83 physical RC2 retained-run telemetry failure", + "risk": "The 250 us sample clock starts before synchronous profile logging completes, causing deterministic missed slots at every START; asynchronous telemetry buckets are also mislabeled as one-second fps windows.", + "rationale": "Physical board evidence showed the first stream counter starting after skipped slots and fail-closed RC2 telemetry outside 3999..4001 despite a stable 3999.94 fps wire segment. The minimum production fix moves timer enable after preparation and reports elapsed-time-normalized fps from a bounded lock-free tick counter.", + "verification": "ESP32-P4 build and realtime boundary policy gate; real-board 10x Start/Stop; first transmitted smpCnt begins at 0 with missed=0; retained 4000-fps telemetry has missed=0 and TX fail=0; independent capture proves continuous counters and 3999..4001 fps; full exact-head release gates." + }, + { + "path": ".github/workflows/esp32p4-smv-injector.yml", + "blockerIssue": "#83 physical RC2 retained-run telemetry failure", + "risk": "The timer/log ordering and normalized telemetry invariant could regress without a deterministic source-policy gate.", + "rationale": "Add the smallest CI assertion at the existing ESP32-P4 firmware boundary instead of introducing a second test framework or weakening the physical evaluator.", + "verification": "The workflow must reject timer enable before START-path formatting, missing lock-free sample tick accounting, or removal of elapsed-time telemetry normalization; the complete ESP32-P4 firmware build must still pass." + } + ] } diff --git a/embedded/esp32p4_smv_injector/main/app_main.cpp b/embedded/esp32p4_smv_injector/main/app_main.cpp index 9fae74595..ee41f223d 100644 --- a/embedded/esp32p4_smv_injector/main/app_main.cpp +++ b/embedded/esp32p4_smv_injector/main/app_main.cpp @@ -22,6 +22,7 @@ #include #include +#include #include #include #include @@ -77,6 +78,8 @@ struct TimingStats final { }; TimingStats g_interval_stats{}; +static_assert(std::atomic::is_always_lock_free); +std::atomic g_sample_tick_total{0U}; struct PacketTemplate final { std::vector bytes; @@ -296,6 +299,21 @@ void merge_stats(TimingStats& local) noexcept { local = TimingStats{}; } +void accumulate_stats(TimingStats& target, const TimingStats& source) noexcept { + if (source.samples == 0U) return; + target.samples += source.samples; + target.canonical_ok += source.canonical_ok; + target.canonical_fail += source.canonical_fail; + target.mirror_ok += source.mirror_ok; + target.mirror_fail += source.mirror_fail; + target.missed_slots += source.missed_slots; + target.lateness_sum_us += source.lateness_sum_us; + target.lateness_min_us = std::min(target.lateness_min_us, source.lateness_min_us); + target.lateness_max_us = std::max(target.lateness_max_us, source.lateness_max_us); + target.last_sample_count = source.last_sample_count; + target.last_signal_generation = source.last_signal_generation; +} + void reset_interval_stats() noexcept { portENTER_CRITICAL(&g_stats_mux); g_interval_stats = TimingStats{}; @@ -450,8 +468,6 @@ void publisher_task(void* argument) { schedule_anchored = false; expected_schedule.reset(active_profile.publisher_rate_hz); static_cast(expected_schedule.next_ticks()); // first alarm interval - sample_clock = start_sample_clock(task_handle, active_profile.publisher_rate_hz); - ESP_LOGI(kTag, "PROFILE armed generation=%llu svID=%s APPID=0x%04X rate=%lu wrap=%u confRev=%lu VLAN=%u/%u/%u frameLen=%u", static_cast(active_profile.generation), @@ -464,6 +480,12 @@ void publisher_task(void* argument) { static_cast(active_profile.vlan_id), static_cast(active_profile.vlan_priority), static_cast(canonical.bytes.size())); + + // Starting the 250 us clock is the final operation in this branch. + // Formatting the profile log after timer enable previously queued + // dozens of ISR notifications before the publisher could consume + // its first tick, so every START falsely began with missed slots. + sample_clock = start_sample_clock(task_handle, active_profile.publisher_rate_hz); continue; } @@ -537,6 +559,7 @@ void publisher_task(void* argument) { update_local_timing( local, lateness_us, missed_slots, canonical_sample_count, signal_state.generation); + g_sample_tick_total.fetch_add(1U, std::memory_order_relaxed); canonical_sample_count = static_cast( (canonical_sample_count + 1U) % active_profile.sample_counter_modulus); mirror_sample_count = static_cast(mirror_sample_count + 1U); @@ -550,6 +573,11 @@ void publisher_task(void* argument) { } void telemetry_task(void*) { + std::uint32_t previous_tick_total = 0U; + std::int64_t previous_tick_time_us = 0; + bool rate_baseline_valid = false; + TimingStats baseline_stats{}; + while (true) { vTaskDelay(pdMS_TO_TICKS(1000)); TimingStats snapshot{}; @@ -557,14 +585,47 @@ void telemetry_task(void*) { snapshot = g_interval_stats; g_interval_stats = TimingStats{}; portEXIT_CRITICAL(&g_stats_mux); - if (snapshot.samples == 0U) continue; + + const std::int64_t now_us = esp_timer_get_time(); + const std::uint32_t tick_total = g_sample_tick_total.load(std::memory_order_relaxed); + if (!live_tx_running() || snapshot.samples == 0U) { + rate_baseline_valid = false; + baseline_stats = {}; + previous_tick_total = tick_total; + previous_tick_time_us = now_us; + continue; + } + + // The telemetry task is independent from START and can first wake in + // the middle of a publisher second. Use that partial bucket only as a + // baseline, while carrying its failures into the first complete report. + if (!rate_baseline_valid) { + rate_baseline_valid = true; + baseline_stats = snapshot; + previous_tick_total = tick_total; + previous_tick_time_us = now_us; + continue; + } + + const std::uint32_t elapsed_ticks = tick_total - previous_tick_total; + const std::int64_t elapsed_us = now_us - previous_tick_time_us; + previous_tick_total = tick_total; + previous_tick_time_us = now_us; + if (elapsed_ticks == 0U || elapsed_us <= 0) continue; + + accumulate_stats(snapshot, baseline_stats); + baseline_stats = {}; + const std::uint64_t normalized_fps = + (static_cast(elapsed_ticks) * 1000000ULL + + static_cast(elapsed_us / 2)) / + static_cast(elapsed_us); const std::int64_t mean_lateness_us = snapshot.lateness_sum_us / static_cast(snapshot.samples); ESP_LOGI(kTag, "timing: samples=%llu (~%llu fps) MC ok=%llu fail=%llu mirror ok=%llu fail=%llu missed=%llu wake_late_us[min/mean/max]=%ld/%lld/%ld smpCnt=%u signal_gen=%llu", static_cast(snapshot.samples), - static_cast(snapshot.samples), + static_cast(normalized_fps), static_cast(snapshot.canonical_ok), static_cast(snapshot.canonical_fail), static_cast(snapshot.mirror_ok),