From a53b9d980e6eaff7fffe84b5dc2c7692ef809146 Mon Sep 17 00:00:00 2001 From: Ilia Baranov <90713890+iliabaranov@users.noreply.github.com> Date: Sat, 19 Sep 2026 09:10:37 -0700 Subject: [PATCH 1/5] diag(safety): attribute lockstep mismatches; time NVS flushes pstop_mismatch counted two different things with one counter: a core missing the 80 ms publish deadline, and both cores publishing different bytes. A 4 h USB soak on 2026-09-10 had one genuine mismatch coincident with a >80 ms peer-cache NVS flush; the Ethernet pass had 25 such flushes and none. Undecidable with the old counter. Now exported in /state.json: pstop_mm_timeout / pstop_mm_content, the last mismatch (packed late-core mask + verdicts, late-core lateness ms, uptime), the worst notify->publish latency per core, and the start/ duration/max of peer-table and dcs NVS writes (nvs_pf, nvs_dcs). The two semaphore takes still both execute every tick; the first-differing-byte scan is bounded by the failed memcmp. JSON_CAP 4352 -> 4864 (measured headroom ~1.4 KB). Diagnostics only; no safety decision changes. --- .../microlink/include/microlink_internal.h | 4 +- components/microlink/src/ml_config_httpd.c | 2 +- components/microlink/src/ml_peer_nvs.c | 5 +- .../dcs_support/src/dcs_admin_pages.c | 23 ++++++++- .../components/dcs_support/src/dcs_internal.h | 9 ++++ firmware/components/dcs_support/src/dcs_nvs.c | 6 ++- .../components/dcs_support/src/dcs_support.c | 2 + firmware/main/main.c | 49 ++++++++++++++++++- 8 files changed, 91 insertions(+), 9 deletions(-) diff --git a/components/microlink/include/microlink_internal.h b/components/microlink/include/microlink_internal.h index 1a2e6f53..4d8ff6e7 100644 --- a/components/microlink/include/microlink_internal.h +++ b/components/microlink/include/microlink_internal.h @@ -1258,8 +1258,8 @@ extern "C" /* Deferred flash flush of the peer cache (writes are debounced: saves only * update the PSRAM working copy; call this ~once per wg_mgr pass). */ esp_err_t ml_peer_nvs_flush_if_due(uint64_t now_ms, bool ingest_busy); - /* Flush timing diag: out[0]=last ms, out[1]=max ms, out[2]=count. */ - void ml_peer_nvs_get_flush_diag(uint32_t out[3]); + /* Flush timing diag: out[0]=last ms, out[1]=max ms, out[2]=count, out[3]=start uptime ms of the last flush. */ + void ml_peer_nvs_get_flush_diag(uint32_t out[4]); /* Mark a peer (by VPN IP, host order) as never-LRU-evicted from the cache. * Bounded set (priority peer, fleet server, app-pinned operator remotes): * these keys feed the boot-time WG preseed that answers cold inbound diff --git a/components/microlink/src/ml_config_httpd.c b/components/microlink/src/ml_config_httpd.c index c404454c..b76f634a 100644 --- a/components/microlink/src/ml_config_httpd.c +++ b/components/microlink/src/ml_config_httpd.c @@ -1178,7 +1178,7 @@ static esp_err_t handler_monitor(httpd_req_t * req) * 2=vpn_ip 3=disco_key 4=hostname 5=region 6=endpoints */ for (int i = 0; i < 7; i++) cJSON_AddItemToArray(sfa, cJSON_CreateNumber(sf[i])); } - uint32_t fl[3] = {0}; + uint32_t fl[4] = {0}; ml_peer_nvs_get_flush_diag(fl); cJSON_AddNumberToObject(json, "nvs_flush_last_ms", fl[0]); cJSON_AddNumberToObject(json, "nvs_flush_max_ms", fl[1]); diff --git a/components/microlink/src/ml_peer_nvs.c b/components/microlink/src/ml_peer_nvs.c index f8249eb0..ec005e75 100644 --- a/components/microlink/src/ml_peer_nvs.c +++ b/components/microlink/src/ml_peer_nvs.c @@ -255,13 +255,15 @@ void ml_peer_nvs_set_protected(uint32_t vpn_ip) static uint32_t s_diag_flush_last_ms; static uint32_t s_diag_flush_max_ms; static uint32_t s_diag_flush_count; +static uint32_t s_diag_flush_at_ms; /* uptime ms at the START of the last flush (soak item 5: overlap test) */ static uint64_t s_defer_start_ms; /* nonzero while an ingest-busy deferral runs */ -void ml_peer_nvs_get_flush_diag(uint32_t out[3]) +void ml_peer_nvs_get_flush_diag(uint32_t out[4]) { out[0] = s_diag_flush_last_ms; out[1] = s_diag_flush_max_ms; out[2] = s_diag_flush_count; + out[3] = s_diag_flush_at_ms; } esp_err_t ml_peer_nvs_flush_if_due(uint64_t now_ms, bool ingest_busy) @@ -291,6 +293,7 @@ esp_err_t ml_peer_nvs_flush_if_due(uint64_t now_ms, bool ingest_busy) esp_err_t r = flush_table(); uint32_t dur = (uint32_t)((esp_timer_get_time() - t0) / 1000); s_diag_flush_last_ms = dur; + s_diag_flush_at_ms = (uint32_t)(t0 / 1000); if (dur > s_diag_flush_max_ms) s_diag_flush_max_ms = dur; s_diag_flush_count++; s_last_flush_ms = now_ms; diff --git a/firmware/components/dcs_support/src/dcs_admin_pages.c b/firmware/components/dcs_support/src/dcs_admin_pages.c index 67c6e11c..372caf3a 100644 --- a/firmware/components/dcs_support/src/dcs_admin_pages.c +++ b/firmware/components/dcs_support/src/dcs_admin_pages.c @@ -230,14 +230,16 @@ static esp_err_t page_state(httpd_req_t * req) */ enum { - JSON_CAP = 4352 /* + 5 usb_tx_* counters (<= ~120 B). eth-watchdog fields + bonded-remote stop_only + operator list + JSON_CAP = 4864 /* + 5 usb_tx_* counters (<= ~120 B). eth-watchdog fields + bonded-remote stop_only + operator list + instantaneous internal-heap fields (heap_free_int/heap_lfb_int). remote_stop_id + restart_state add <= 47 B worst case against ~940 B live headroom (measured 2026-08-09). derp_region_locked adds <= 27 B. Region auto-negotiation surfacing (source string + auto_applied + counters + mbb_state + switches_1h) adds <= ~160 B worst case — bumped 3776 -> 4096 to keep comfortable - headroom rather than shave the measured margin. */ + headroom rather than shave the measured margin. Lockstep-mismatch + attribution (pstop_mm_timeout/content/last, pstop_core_lat_max_ms, + nvs_pf, nvs_dcs) adds <= ~230 B worst case: 4352 -> 4864. */ }; char * buf = heap_caps_malloc(JSON_CAP, MALLOC_CAP_SPIRAM); @@ -249,6 +251,9 @@ static esp_err_t page_state(httpd_req_t * req) const int cap = JSON_CAP; ml_usb_tx_diag_t usb_tx; ml_usb_tx_get_diag(&usb_tx); /* zeros until the tether has ever started */ + extern void ml_peer_nvs_get_flush_diag(uint32_t out[4]); /* peer-cache flash flush: last/max/count/start ms */ + uint32_t pf[4] = {0}; + ml_peer_nvs_get_flush_diag(pf); int n = snprintf( buf, cap, @@ -279,6 +284,8 @@ static esp_err_t page_state(httpd_req_t * req) "\"derp_mbb_state\":%d,\"derp_switches_1h\":%lu," "\"pstop_peer_ip\":%lu,\"pstop_peer_port\":%lu," "\"pstop_sent\":%lu,\"pstop_replies\":%lu,\"pstop_last_msg\":%lu,\"pstop_mismatch\":%lu," + "\"pstop_mm_timeout\":%lu,\"pstop_mm_content\":%lu,\"pstop_mm_last\":[%lu,%lu,%lu]," + "\"pstop_core_lat_max_ms\":[%lu,%lu],\"nvs_pf\":[%lu,%lu,%lu],\"nvs_dcs\":[%lu,%lu]," "\"pstop_send_fail\":%lu,\"pstop_sf_nomem\":%lu,\"pstop_sf_route\":%lu," "\"pstop_sf_txdrv\":%lu,\"pstop_sf_txdrv_recovered\":%lu,\"pstop_sf_other\":%lu," "\"pstop_sf_enotconn\":%lu,\"pstop_sf_enotconn_kicks\":%lu,\"pstop_sf_errno\":%d,\"pstop_" @@ -371,6 +378,18 @@ static esp_err_t page_state(httpd_req_t * req) (unsigned long)atomic_load(&g_dcs_pstop_replies), (unsigned long)atomic_load(&g_dcs_pstop_last_msg), (unsigned long)atomic_load(&g_dcs_pstop_mismatch), + (unsigned long)atomic_load(&g_dcs_pstop_mm[0]), + (unsigned long)atomic_load(&g_dcs_pstop_mm[1]), + (unsigned long)atomic_load(&g_dcs_pstop_mm[2]), /* packed detail — layout in dcs_internal.h */ + (unsigned long)atomic_load(&g_dcs_pstop_mm[3]), /* late core's actual publish latency ms */ + (unsigned long)atomic_load(&g_dcs_pstop_mm[4]), /* last event uptime ms */ + (unsigned long)atomic_load(&g_dcs_pstop_mm[5]), + (unsigned long)atomic_load(&g_dcs_pstop_mm[6]), + (unsigned long)pf[3], /* nvs_pf: start uptime ms, duration ms, max duration ms */ + (unsigned long)pf[0], + (unsigned long)pf[1], + (unsigned long)atomic_load(&g_dcs_nvs_write[0]), /* nvs_dcs: start uptime ms, duration ms */ + (unsigned long)atomic_load(&g_dcs_nvs_write[1]), (unsigned long)atomic_load(&g_dcs_pstop_send_fail), (unsigned long)atomic_load(&g_dcs_pstop_sf_nomem), (unsigned long)atomic_load(&g_dcs_pstop_sf_route), diff --git a/firmware/components/dcs_support/src/dcs_internal.h b/firmware/components/dcs_support/src/dcs_internal.h index 4dbb0b8e..50956c59 100644 --- a/firmware/components/dcs_support/src/dcs_internal.h +++ b/firmware/components/dcs_support/src/dcs_internal.h @@ -171,6 +171,15 @@ extern "C" extern atomic_uint_fast32_t g_dcs_pstop_replies; /* machine replies received */ extern atomic_uint_fast32_t g_dcs_pstop_last_msg; /* last message TYPE from the machine (PSTOP_MESSAGE_*) */ extern atomic_uint_fast32_t g_dcs_pstop_mismatch; + /* pstop_mismatch attribution (soak item 5; comparator-written; /state.json pstop_mm_*): [0] timeout-class + * count (a core missed CORE_PUBLISH_TIMEOUT), [1] content-class count (both published, frames differed), + * [2] last event packed = kind<<28 (1 timeout, 2 content) | late_core_mask<<26 (bit0 core0, bit1 core1) | + * slot<<24 | first_differing_byte<<16 (0xFF n/a) | verdict0<<8 | verdict1, [3] late core's actual + * notify->publish ms (0 = not by the next tick), [4] last event uptime ms, [5],[6] worst latency ms per core. */ + extern atomic_uint_fast32_t g_dcs_pstop_mm[7]; + /* Last dcs-side NVS write (dcs_nvs.c; both cores stall for the flash op): [0] start uptime ms, [1] duration ms. + * Peer-cache flushes have their own diag (ml_peer_nvs_get_flush_diag). /state.json nvs_dcs / nvs_pf. */ + extern atomic_uint_fast32_t g_dcs_nvs_write[2]; extern atomic_uint_fast32_t g_dcs_pstop_send_fail; /* send_fail split by cause (errno at the failing sendto): ENOMEM = * TX-queue/pbuf pressure (typically DERP relay backpressure), route = diff --git a/firmware/components/dcs_support/src/dcs_nvs.c b/firmware/components/dcs_support/src/dcs_nvs.c index aa07ec46..7a200ec9 100644 --- a/firmware/components/dcs_support/src/dcs_nvs.c +++ b/firmware/components/dcs_support/src/dcs_nvs.c @@ -29,6 +29,7 @@ #include "dcs_internal.h" #include "esp_err.h" #include "esp_log.h" +#include "esp_timer.h" #include "nvs.h" #include "pstop_aux_channel.h" @@ -621,12 +622,15 @@ esp_err_t dcs_nvs_write_health(const dcs_health_counters_t * c) uint8_t blob[DCS_HEALTH_BLOB_LEN]; dcs_health_encode(c, blob); nvs_handle_t h; + const uint32_t t0 = (uint32_t)(esp_timer_get_time() / 1000); /* soak item 5: stamp this flash write */ esp_err_t r = nvs_open(DCS_NVS_NS, NVS_READWRITE, &h); if (r != ESP_OK) return r; - r = nvs_set_blob(h, DCS_NVS_KEY_HEALTH, blob, sizeof(blob)); + r = nvs_set_blob(h, DCS_NVS_KEY_HEALTH, blob, sizeof(blob)); /* flash program/erase happens HERE (commit = no-op) */ if (r == ESP_OK) { r = nvs_commit(h); } nvs_close(h); + atomic_store(&g_dcs_nvs_write[1], (uint32_t)(esp_timer_get_time() / 1000) - t0); + atomic_store(&g_dcs_nvs_write[0], t0); return r; } diff --git a/firmware/components/dcs_support/src/dcs_support.c b/firmware/components/dcs_support/src/dcs_support.c index 3427d3e4..0e1d8581 100644 --- a/firmware/components/dcs_support/src/dcs_support.c +++ b/firmware/components/dcs_support/src/dcs_support.c @@ -96,6 +96,8 @@ atomic_uint_fast32_t g_dcs_pstop_sent; atomic_uint_fast32_t g_dcs_pstop_replies; atomic_uint_fast32_t g_dcs_pstop_last_msg; /* last PSTOP_MESSAGE_* received from the machine */ atomic_uint_fast32_t g_dcs_pstop_mismatch; +atomic_uint_fast32_t g_dcs_pstop_mm[7]; /* mismatch attribution — layout in dcs_internal.h */ +atomic_uint_fast32_t g_dcs_nvs_write[2]; /* last dcs-side NVS write — layout in dcs_internal.h */ atomic_uint_fast32_t g_dcs_pstop_send_fail; atomic_uint_fast32_t g_dcs_pstop_sf_nomem; atomic_uint_fast32_t g_dcs_pstop_sf_route; diff --git a/firmware/main/main.c b/firmware/main/main.c index 0bbd7185..aff5a122 100644 --- a/firmware/main/main.c +++ b/firmware/main/main.c @@ -153,6 +153,7 @@ static const char * TAG = "dcs_main"; extern atomic_uint_fast32_t g_dcs_pstop_last_msg; extern atomic_uint_fast32_t g_dcs_pstop_replies; extern atomic_uint_fast32_t g_dcs_pstop_rebonds; +extern atomic_uint_fast32_t g_dcs_pstop_mm[7]; /* lockstep-mismatch attribution (soak item 5; dcs_internal.h) */ /* ============================================================================ * Lockstep state — one tick's worth of inputs for every active session, @@ -183,6 +184,7 @@ static uint8_t g_encoded[2][PSTOP_MAX_MACHINES][PSTOP_MESSAGE_SIZE]; static uint8_t g_verdict[2]; /* for telemetry */ static SemaphoreHandle_t g_done[2]; /* core_id → comparator */ static TaskHandle_t g_core_h[2]; /* comparator → core_id */ +static atomic_uint_fast64_t g_core_done_us[2]; /* esp_timer stamp of each core's last publish (telemetry) */ /* ============================================================================ * Dual-channel hardware E-stop loops. @@ -590,6 +592,7 @@ static void core_task(void * arg) /* Feed the TWDT — proves THIS core task ran to completion this tick. */ (void)esp_task_wdt_reset(); + atomic_store(&g_core_done_us[core_id], (uint64_t)esp_timer_get_time()); xSemaphoreGive(g_done[core_id]); } } @@ -1092,6 +1095,11 @@ static void comparator_task(void * arg) } uint32_t mismatch = 0; + /* Mismatch attribution (soak item 5) -> /state.json pstop_mm_*; layout documented at g_dcs_pstop_mm in + * dcs_internal.h: [0] timeout count [1] content count [2] last packed [3] late ms [4] at ms [5..6] lat max. */ + uint32_t mm[7] = {0}; + uint32_t mm_late = 0; /* late-core mask of the last timeout, pending attribution at the next tick */ + uint64_t notify_us = 0; uint64_t last_unhealthy_kick_ms = 0; bool xc_announced = false; TickType_t xc_fault_tick = 0; @@ -1228,6 +1236,11 @@ static void comparator_task(void * arg) } } + if (mm_late != 0u) { /* previous tick timed out: when did the late core finally publish? */ + uint64_t done = (uint64_t)atomic_load(&g_core_done_us[(mm_late & 1u) ? 0 : 1]); + mm[3] = (done > notify_us) ? (uint32_t)((done - notify_us) / 1000u) : 0u; + mm_late = 0; + } /* 3. Drain any stale completion signal before notifying. If a core * published just *after* CORE_PUBLISH_TIMEOUT on a previous tick, * its g_done give is still pending and would otherwise satisfy this @@ -1240,30 +1253,59 @@ static void comparator_task(void * arg) /* 4. Notify both cores; they sample their loop, encode every active * slot, and signal back. */ + notify_us = (uint64_t)esp_timer_get_time(); xTaskNotifyGive(g_core_h[0]); xTaskNotifyGive(g_core_h[1]); - bool both_in = (xSemaphoreTake(g_done[0], CORE_PUBLISH_TIMEOUT) == pdTRUE) & - (xSemaphoreTake(g_done[1], CORE_PUBLISH_TIMEOUT) == pdTRUE); + const bool in0 = (xSemaphoreTake(g_done[0], CORE_PUBLISH_TIMEOUT) == pdTRUE); /* sequential -> late core known */ + const bool in1 = (xSemaphoreTake(g_done[1], CORE_PUBLISH_TIMEOUT) == pdTRUE); + bool both_in = in0 && in1; /* 5. Lockstep check across ALL active slots. Any disagreement taints * the DEVICE — send nothing to anyone this tick; every machine * fail-safes independently on its heartbeat timeout. */ bool lockstep_ok = both_in; + int mm_slot = -1; /* first disagreeing frame: slot + first differing byte */ + int mm_off = 0; if (both_in) { for (int i = 0; i < PSTOP_MAX_MACHINES; i++) { if (g_tick[i].active && (memcmp(g_encoded[0][i], g_encoded[1][i], PSTOP_MESSAGE_SIZE) != 0)) { lockstep_ok = false; + if (mm_slot < 0) { /* memcmp != 0 bounds the scan */ + for (mm_off = 0; g_encoded[0][i][mm_off] == g_encoded[1][i][mm_off]; mm_off++) { + } + mm_slot = i; + } } } + for (int c = 0; c < 2; c++) { /* per-core notify->publish latency, worst this boot */ + uint64_t done = (uint64_t)atomic_load(&g_core_done_us[c]); + uint32_t lat = (done > notify_us) ? (uint32_t)((done - notify_us) / 1000u) : 0u; + mm[5 + c] = (lat > mm[5 + c]) ? lat : mm[5 + c]; + } } bool sent_any = false; if (!both_in) { mismatch++; + mm[0]++; + mm_late = 0u; + if (!in0) { + mm_late |= 1u; + } + if (!in1) { + mm_late |= 2u; + } + mm[2] = ((uint32_t)1u << 28) | (mm_late << 26) | ((uint32_t)0xFFu << 16) | ((uint32_t)g_verdict[0] << 8); + mm[2] |= g_verdict[1]; + mm[4] = (uint32_t)now_ms; ESP_LOGW(TAG, "core publish timeout — sending nothing (mismatch=%lu)", (unsigned long)mismatch); } else if (!lockstep_ok) { mismatch++; + mm[1]++; + mm[2] = ((uint32_t)2u << 28) | ((uint32_t)mm_slot << 24) | ((uint32_t)mm_off << 16); + mm[2] |= ((uint32_t)g_verdict[0] << 8) | g_verdict[1]; + mm[4] = (uint32_t)now_ms; ESP_LOGW(TAG, "ENCODING MISMATCH v0=%u v1=%u — sending nothing to any machine", g_verdict[0], g_verdict[1]); } else if (!estop_primed()) { /* Boot-priming hold: both E-stop channels haven't yet been sampled @@ -1497,6 +1539,9 @@ static void comparator_task(void * arg) atomic_store(&g_dcs_pstop_last_msg, agg_msg); atomic_store(&g_dcs_pstop_replies, agg_replies); dcs_publish_comparator(agg_sent, mismatch, agg_fail, agg_last_reply, agg_rtt); + for (int i = 0; i < 7; i++) { + atomic_store(&g_dcs_pstop_mm[i], mm[i]); + } /* Aggregate PRIORITY-peer health (kept alongside the per-slot * notifications above, which cover each machine target individually): From 2f595495edeb6cb7206c21d090ff709786c580e1 Mon Sep 17 00:00:00 2001 From: Ilia Baranov <90713890+iliabaranov@users.noreply.github.com> Date: Sat, 19 Sep 2026 22:19:16 -0700 Subject: [PATCH 2/5] =?UTF-8?q?diag(safety):=20review=20round=202=20?= =?UTF-8?q?=E2=80=94=20shared=20publish=20deadline,=20per-core=20attributi?= =?UTF-8?q?on,=20torn-read-free=20records?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit - comparator: one absolute CORE_PUBLISH_TIMEOUT deadline for both takes — core 1 gets the remainder, not a fresh 80 ms after core 0 timed out (which gave it 160 ms and reported a both-late event as "core 0 late"). Worst-case tick stall is now 80 ms instead of 160 ms. - attribution: the late-core mask stays pending per core until that core has actually published for the timed-out tick; mm[3] = slowest late core's real notify->publish ms (both-late records the max, not core 0 only). A core that never lands is no longer reported as "0 ms late". - g_dcs_pstop_mm: 7-word record published under a seqlock (g_dcs_pstop_mm_seq); /state.json reads it via dcs_pstop_mm_snapshot(), never mixing two events. - g_dcs_nvs_write: start and duration in ONE 64-bit atomic word. - ml_peer_nvs flush diag: same seqlock pattern around the 4-value record. --- components/microlink/src/ml_peer_nvs.c | 26 +++++++++-- .../dcs_support/src/dcs_admin_pages.c | 23 +++++----- .../components/dcs_support/src/dcs_internal.h | 11 +++-- firmware/components/dcs_support/src/dcs_nvs.c | 6 ++- .../components/dcs_support/src/dcs_support.c | 22 +++++++++- firmware/main/main.c | 44 +++++++++++++++---- 6 files changed, 104 insertions(+), 28 deletions(-) diff --git a/components/microlink/src/ml_peer_nvs.c b/components/microlink/src/ml_peer_nvs.c index ec005e75..1310e1aa 100644 --- a/components/microlink/src/ml_peer_nvs.c +++ b/components/microlink/src/ml_peer_nvs.c @@ -16,11 +16,14 @@ * Reference: microlink v1 microlink_peer_registry.c */ +#include #include #include #include "esp_log.h" #include "esp_timer.h" +#include "freertos/FreeRTOS.h" +#include "freertos/task.h" #include "microlink_internal.h" #include "nvs.h" #include "nvs_flash.h" @@ -252,6 +255,10 @@ void ml_peer_nvs_set_protected(uint32_t vpn_ip) /* Flush timing diag (§7 R6): the flash commit suspends flash-resident * execution on BOTH cores — these gauges make that cost measurable and the * fix falsifiable (flush_count flat in steady state = §7a working). */ +/* Flush diag record, published under a seqlock (s_diag_flush_seq odd while the + * writer is mid-update) so ml_peer_nvs_get_flush_diag() never returns e.g. a + * new count with the previous flush's duration. Single writer (ml_wg_mgr). */ +static atomic_uint_fast32_t s_diag_flush_seq; static uint32_t s_diag_flush_last_ms; static uint32_t s_diag_flush_max_ms; static uint32_t s_diag_flush_count; @@ -260,10 +267,19 @@ static uint64_t s_defer_start_ms; /* nonzero while an ingest-busy deferral runs void ml_peer_nvs_get_flush_diag(uint32_t out[4]) { - out[0] = s_diag_flush_last_ms; - out[1] = s_diag_flush_max_ms; - out[2] = s_diag_flush_count; - out[3] = s_diag_flush_at_ms; + for (int attempt = 0; attempt < 8; attempt++) { + uint32_t s1 = (uint32_t)atomic_load(&s_diag_flush_seq); + if ((s1 & 1u) != 0u) { + taskYIELD(); + continue; + } + out[0] = s_diag_flush_last_ms; + out[1] = s_diag_flush_max_ms; + out[2] = s_diag_flush_count; + out[3] = s_diag_flush_at_ms; + if ((uint32_t)atomic_load(&s_diag_flush_seq) == s1) return; + } + /* 8 collisions (flushes are >= 5 s apart, so effectively never): last read stands — diagnostics only */ } esp_err_t ml_peer_nvs_flush_if_due(uint64_t now_ms, bool ingest_busy) @@ -292,10 +308,12 @@ esp_err_t ml_peer_nvs_flush_if_due(uint64_t now_ms, bool ingest_busy) int64_t t0 = esp_timer_get_time(); esp_err_t r = flush_table(); uint32_t dur = (uint32_t)((esp_timer_get_time() - t0) / 1000); + (void)atomic_fetch_add(&s_diag_flush_seq, 1u); /* odd: record in flux */ s_diag_flush_last_ms = dur; s_diag_flush_at_ms = (uint32_t)(t0 / 1000); if (dur > s_diag_flush_max_ms) s_diag_flush_max_ms = dur; s_diag_flush_count++; + (void)atomic_fetch_add(&s_diag_flush_seq, 1u); /* even: consistent */ s_last_flush_ms = now_ms; if (r == ESP_OK) { s_dirty = false; /* keep the dirt on a failed flush */ diff --git a/firmware/components/dcs_support/src/dcs_admin_pages.c b/firmware/components/dcs_support/src/dcs_admin_pages.c index 372caf3a..f9bdf180 100644 --- a/firmware/components/dcs_support/src/dcs_admin_pages.c +++ b/firmware/components/dcs_support/src/dcs_admin_pages.c @@ -253,7 +253,10 @@ static esp_err_t page_state(httpd_req_t * req) ml_usb_tx_get_diag(&usb_tx); /* zeros until the tether has ever started */ extern void ml_peer_nvs_get_flush_diag(uint32_t out[4]); /* peer-cache flash flush: last/max/count/start ms */ uint32_t pf[4] = {0}; - ml_peer_nvs_get_flush_diag(pf); + ml_peer_nvs_get_flush_diag(pf); /* seqlock-consistent copy (ml_peer_nvs.c) */ + uint32_t mm[7] = {0}; + dcs_pstop_mm_snapshot(mm); /* seqlock-consistent copy of the comparator's record */ + const uint64_t nvs_w = (uint64_t)atomic_load(&g_dcs_nvs_write); int n = snprintf( buf, cap, @@ -378,18 +381,18 @@ static esp_err_t page_state(httpd_req_t * req) (unsigned long)atomic_load(&g_dcs_pstop_replies), (unsigned long)atomic_load(&g_dcs_pstop_last_msg), (unsigned long)atomic_load(&g_dcs_pstop_mismatch), - (unsigned long)atomic_load(&g_dcs_pstop_mm[0]), - (unsigned long)atomic_load(&g_dcs_pstop_mm[1]), - (unsigned long)atomic_load(&g_dcs_pstop_mm[2]), /* packed detail — layout in dcs_internal.h */ - (unsigned long)atomic_load(&g_dcs_pstop_mm[3]), /* late core's actual publish latency ms */ - (unsigned long)atomic_load(&g_dcs_pstop_mm[4]), /* last event uptime ms */ - (unsigned long)atomic_load(&g_dcs_pstop_mm[5]), - (unsigned long)atomic_load(&g_dcs_pstop_mm[6]), + (unsigned long)mm[0], + (unsigned long)mm[1], + (unsigned long)mm[2], /* packed detail — layout in dcs_internal.h */ + (unsigned long)mm[3], /* late core's actual publish latency ms */ + (unsigned long)mm[4], /* last event uptime ms */ + (unsigned long)mm[5], + (unsigned long)mm[6], (unsigned long)pf[3], /* nvs_pf: start uptime ms, duration ms, max duration ms */ (unsigned long)pf[0], (unsigned long)pf[1], - (unsigned long)atomic_load(&g_dcs_nvs_write[0]), /* nvs_dcs: start uptime ms, duration ms */ - (unsigned long)atomic_load(&g_dcs_nvs_write[1]), + (unsigned long)(uint32_t)(nvs_w >> 32), /* nvs_dcs: start uptime ms, duration ms (one 64-bit word) */ + (unsigned long)(uint32_t)(nvs_w & 0xFFFFFFFFu), (unsigned long)atomic_load(&g_dcs_pstop_send_fail), (unsigned long)atomic_load(&g_dcs_pstop_sf_nomem), (unsigned long)atomic_load(&g_dcs_pstop_sf_route), diff --git a/firmware/components/dcs_support/src/dcs_internal.h b/firmware/components/dcs_support/src/dcs_internal.h index 50956c59..448cc0dd 100644 --- a/firmware/components/dcs_support/src/dcs_internal.h +++ b/firmware/components/dcs_support/src/dcs_internal.h @@ -177,9 +177,14 @@ extern "C" * slot<<24 | first_differing_byte<<16 (0xFF n/a) | verdict0<<8 | verdict1, [3] late core's actual * notify->publish ms (0 = not by the next tick), [4] last event uptime ms, [5],[6] worst latency ms per core. */ extern atomic_uint_fast32_t g_dcs_pstop_mm[7]; - /* Last dcs-side NVS write (dcs_nvs.c; both cores stall for the flash op): [0] start uptime ms, [1] duration ms. - * Peer-cache flushes have their own diag (ml_peer_nvs_get_flush_diag). /state.json nvs_dcs / nvs_pf. */ - extern atomic_uint_fast32_t g_dcs_nvs_write[2]; + /* Seqlock for g_dcs_pstop_mm: the comparator (single writer) bumps it before and after the 7 stores, so it is + * odd while the record is in flux. Readers use dcs_pstop_mm_snapshot() and never see two events mixed. */ + extern atomic_uint_fast32_t g_dcs_pstop_mm_seq; + void dcs_pstop_mm_snapshot(uint32_t out[7]); + /* Last dcs-side NVS write (dcs_nvs.c; both cores stall for the flash op), ONE 64-bit word so start and + * duration are always from the same write: start uptime ms << 32 | duration ms. Peer-cache flushes have + * their own diag (ml_peer_nvs_get_flush_diag). /state.json nvs_dcs / nvs_pf. */ + extern atomic_uint_fast64_t g_dcs_nvs_write; extern atomic_uint_fast32_t g_dcs_pstop_send_fail; /* send_fail split by cause (errno at the failing sendto): ENOMEM = * TX-queue/pbuf pressure (typically DERP relay backpressure), route = diff --git a/firmware/components/dcs_support/src/dcs_nvs.c b/firmware/components/dcs_support/src/dcs_nvs.c index 7a200ec9..61aa3d54 100644 --- a/firmware/components/dcs_support/src/dcs_nvs.c +++ b/firmware/components/dcs_support/src/dcs_nvs.c @@ -630,7 +630,9 @@ esp_err_t dcs_nvs_write_health(const dcs_health_counters_t * c) r = nvs_commit(h); } nvs_close(h); - atomic_store(&g_dcs_nvs_write[1], (uint32_t)(esp_timer_get_time() / 1000) - t0); - atomic_store(&g_dcs_nvs_write[0], t0); + /* start and duration in ONE atomic word: a reader never pairs this write's + * duration with the previous write's start (or vice versa). */ + const uint32_t dur = (uint32_t)(esp_timer_get_time() / 1000) - t0; + atomic_store(&g_dcs_nvs_write, ((uint64_t)t0 << 32) | (uint64_t)dur); return r; } diff --git a/firmware/components/dcs_support/src/dcs_support.c b/firmware/components/dcs_support/src/dcs_support.c index 0e1d8581..121cecdd 100644 --- a/firmware/components/dcs_support/src/dcs_support.c +++ b/firmware/components/dcs_support/src/dcs_support.c @@ -97,7 +97,27 @@ atomic_uint_fast32_t g_dcs_pstop_replies; atomic_uint_fast32_t g_dcs_pstop_last_msg; /* last PSTOP_MESSAGE_* received from the machine */ atomic_uint_fast32_t g_dcs_pstop_mismatch; atomic_uint_fast32_t g_dcs_pstop_mm[7]; /* mismatch attribution — layout in dcs_internal.h */ -atomic_uint_fast32_t g_dcs_nvs_write[2]; /* last dcs-side NVS write — layout in dcs_internal.h */ +atomic_uint_fast32_t g_dcs_pstop_mm_seq; /* seqlock for g_dcs_pstop_mm — see dcs_internal.h */ +atomic_uint_fast64_t g_dcs_nvs_write; /* last dcs-side NVS write, start<<32 | duration — dcs_internal.h */ + +void dcs_pstop_mm_snapshot(uint32_t out[7]) +{ + /* Seqlock read: retry while the comparator is mid-write (odd) or wrote in + * between. The writer runs once per 100 ms tick and the 7 stores take ~1 us, + * so a retry is rare; after 8 tries return the last read (diagnostics only). */ + for (int attempt = 0; attempt < 8; attempt++) { + uint32_t s1 = (uint32_t)atomic_load(&g_dcs_pstop_mm_seq); + if ((s1 & 1u) != 0u) { + taskYIELD(); + continue; + } + for (int i = 0; i < 7; i++) { + out[i] = (uint32_t)atomic_load(&g_dcs_pstop_mm[i]); + } + if ((uint32_t)atomic_load(&g_dcs_pstop_mm_seq) == s1) return; + } +} + atomic_uint_fast32_t g_dcs_pstop_send_fail; atomic_uint_fast32_t g_dcs_pstop_sf_nomem; atomic_uint_fast32_t g_dcs_pstop_sf_route; diff --git a/firmware/main/main.c b/firmware/main/main.c index aff5a122..5e8dc2f5 100644 --- a/firmware/main/main.c +++ b/firmware/main/main.c @@ -154,6 +154,7 @@ extern atomic_uint_fast32_t g_dcs_pstop_last_msg; extern atomic_uint_fast32_t g_dcs_pstop_replies; extern atomic_uint_fast32_t g_dcs_pstop_rebonds; extern atomic_uint_fast32_t g_dcs_pstop_mm[7]; /* lockstep-mismatch attribution (soak item 5; dcs_internal.h) */ +extern atomic_uint_fast32_t g_dcs_pstop_mm_seq; /* seqlock for g_dcs_pstop_mm (odd while being written) */ /* ============================================================================ * Lockstep state — one tick's worth of inputs for every active session, @@ -1098,7 +1099,9 @@ static void comparator_task(void * arg) /* Mismatch attribution (soak item 5) -> /state.json pstop_mm_*; layout documented at g_dcs_pstop_mm in * dcs_internal.h: [0] timeout count [1] content count [2] last packed [3] late ms [4] at ms [5..6] lat max. */ uint32_t mm[7] = {0}; - uint32_t mm_late = 0; /* late-core mask of the last timeout, pending attribution at the next tick */ + uint32_t mm_late = + 0; /* late-core mask of the last timeout: bit c stays set until core c has published for that tick */ + uint64_t mm_late_notify_us = 0; /* notify time of the tick that timed out (attribution reference) */ uint64_t notify_us = 0; uint64_t last_unhealthy_kick_ms = 0; bool xc_announced = false; @@ -1236,10 +1239,21 @@ static void comparator_task(void * arg) } } - if (mm_late != 0u) { /* previous tick timed out: when did the late core finally publish? */ - uint64_t done = (uint64_t)atomic_load(&g_core_done_us[(mm_late & 1u) ? 0 : 1]); - mm[3] = (done > notify_us) ? (uint32_t)((done - notify_us) / 1000u) : 0u; - mm_late = 0; + if (mm_late != 0u) { + /* A previous tick timed out: attribute each late core once it has actually + * published for THAT tick (done > that tick's notify). A core that has not + * landed yet is not "0 ms late" — its bit stays pending (and this tick's own + * take below counts it again). mm[3] = the slowest late core's real + * notify->publish ms for the last event; both-late events record the max. */ + for (int c = 0; c < 2; c++) { + if ((mm_late & (1u << c)) == 0u) continue; + uint64_t done = (uint64_t)atomic_load(&g_core_done_us[c]); + if (done > mm_late_notify_us) { + uint32_t lat = (uint32_t)((done - mm_late_notify_us) / 1000u); + if (lat > mm[3]) mm[3] = lat; + mm_late &= ~(1u << c); + } + } } /* 3. Drain any stale completion signal before notifying. If a core * published just *after* CORE_PUBLISH_TIMEOUT on a previous tick, @@ -1257,8 +1271,16 @@ static void comparator_task(void * arg) xTaskNotifyGive(g_core_h[0]); xTaskNotifyGive(g_core_h[1]); - const bool in0 = (xSemaphoreTake(g_done[0], CORE_PUBLISH_TIMEOUT) == pdTRUE); /* sequential -> late core known */ - const bool in1 = (xSemaphoreTake(g_done[1], CORE_PUBLISH_TIMEOUT) == pdTRUE); + /* Sequential takes so the late core is known, but ONE absolute deadline for + * both: core 1 gets the remainder of CORE_PUBLISH_TIMEOUT, not a fresh budget + * after core 0's timeout (which gave it 160 ms and reported a both-late event + * as "core 0 late"). Worst-case tick stall is CORE_PUBLISH_TIMEOUT. */ + const TickType_t take_t0 = xTaskGetTickCount(); + const bool in0 = (xSemaphoreTake(g_done[0], CORE_PUBLISH_TIMEOUT) == pdTRUE); + const TickType_t take_used = xTaskGetTickCount() - take_t0; + const bool in1 = + (xSemaphoreTake(g_done[1], (take_used < CORE_PUBLISH_TIMEOUT) ? (CORE_PUBLISH_TIMEOUT - take_used) : 0) == + pdTRUE); bool both_in = in0 && in1; /* 5. Lockstep check across ALL active slots. Any disagreement taints @@ -1289,7 +1311,9 @@ static void comparator_task(void * arg) if (!both_in) { mismatch++; mm[0]++; - mm_late = 0u; + mm_late = 0u; /* a new event supersedes a still-pending attribution */ + mm_late_notify_us = notify_us; + mm[3] = 0u; /* filled in by the next ticks as the late core(s) land */ if (!in0) { mm_late |= 1u; } @@ -1539,9 +1563,13 @@ static void comparator_task(void * arg) atomic_store(&g_dcs_pstop_last_msg, agg_msg); atomic_store(&g_dcs_pstop_replies, agg_replies); dcs_publish_comparator(agg_sent, mismatch, agg_fail, agg_last_reply, agg_rtt); + /* 7-word record published under a seqlock (odd = in flux) so a /state.json + * reader (dcs_pstop_mm_snapshot) never mixes two events; single writer. */ + (void)atomic_fetch_add(&g_dcs_pstop_mm_seq, 1u); for (int i = 0; i < 7; i++) { atomic_store(&g_dcs_pstop_mm[i], mm[i]); } + (void)atomic_fetch_add(&g_dcs_pstop_mm_seq, 1u); /* Aggregate PRIORITY-peer health (kept alongside the per-slot * notifications above, which cover each machine target individually): From 64ce7e54f1285bb5610d2bce9f32005b29b74221 Mon Sep 17 00:00:00 2001 From: Ilia Baranov <90713890+iliabaranov@users.noreply.github.com> Date: Sun, 20 Sep 2026 00:12:49 -0700 Subject: [PATCH 3/5] =?UTF-8?q?diag(safety):=20review=20round=203=20?= =?UTF-8?q?=E2=80=94=20worst-case=20gauge=20includes=20late=20publishes;?= =?UTF-8?q?=20mm[3]=20scoped=20to=20timeout=20records?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit - mm[5+c] (per-core worst notify->publish ms) now also folds in the on-time core's latency on a timeout tick and the late core's real latency when it lands, so the gauge no longer excludes exactly the slow publishes it exists to surface. - mm[3] (late core's latency) is written only while the record still describes that timeout event and is zeroed by a content event, so a content record can never carry a stale timeout-class latency. - seqlock readers (dcs_pstop_mm_snapshot, ml_peer_nvs_get_flush_diag) always deliver a copy — a best-effort one after 8 collisions — instead of leaving the caller's buffer untouched. - layout doc: on a timeout record the late core's verdict byte is from its previous publish (the late mask says which); mm[3]/mm[5..6] semantics. --- components/microlink/src/ml_peer_nvs.c | 6 +++++- firmware/components/dcs_support/src/dcs_internal.h | 6 ++++-- firmware/components/dcs_support/src/dcs_support.c | 5 +++++ firmware/main/main.c | 14 +++++++++++++- 4 files changed, 27 insertions(+), 4 deletions(-) diff --git a/components/microlink/src/ml_peer_nvs.c b/components/microlink/src/ml_peer_nvs.c index 1310e1aa..02286fe9 100644 --- a/components/microlink/src/ml_peer_nvs.c +++ b/components/microlink/src/ml_peer_nvs.c @@ -279,7 +279,11 @@ void ml_peer_nvs_get_flush_diag(uint32_t out[4]) out[3] = s_diag_flush_at_ms; if ((uint32_t)atomic_load(&s_diag_flush_seq) == s1) return; } - /* 8 collisions (flushes are >= 5 s apart, so effectively never): last read stands — diagnostics only */ + /* 8 collisions (flushes are >= 5 s apart, so effectively never): best-effort copy so out[] is always written */ + out[0] = s_diag_flush_last_ms; + out[1] = s_diag_flush_max_ms; + out[2] = s_diag_flush_count; + out[3] = s_diag_flush_at_ms; } esp_err_t ml_peer_nvs_flush_if_due(uint64_t now_ms, bool ingest_busy) diff --git a/firmware/components/dcs_support/src/dcs_internal.h b/firmware/components/dcs_support/src/dcs_internal.h index 448cc0dd..e8c48e86 100644 --- a/firmware/components/dcs_support/src/dcs_internal.h +++ b/firmware/components/dcs_support/src/dcs_internal.h @@ -174,8 +174,10 @@ extern "C" /* pstop_mismatch attribution (soak item 5; comparator-written; /state.json pstop_mm_*): [0] timeout-class * count (a core missed CORE_PUBLISH_TIMEOUT), [1] content-class count (both published, frames differed), * [2] last event packed = kind<<28 (1 timeout, 2 content) | late_core_mask<<26 (bit0 core0, bit1 core1) | - * slot<<24 | first_differing_byte<<16 (0xFF n/a) | verdict0<<8 | verdict1, [3] late core's actual - * notify->publish ms (0 = not by the next tick), [4] last event uptime ms, [5],[6] worst latency ms per core. */ + * slot<<24 | first_differing_byte<<16 (0xFF n/a) | verdict0<<8 | verdict1 (on a timeout record the LATE core's + * verdict byte is from its previous publish — the late mask says which), [3] slowest late core's actual + * notify->publish ms for a timeout record (0 = not landed yet / n/a for a content record), [4] last event + * uptime ms, [5],[6] worst notify->publish ms per core this boot, including late publishes. */ extern atomic_uint_fast32_t g_dcs_pstop_mm[7]; /* Seqlock for g_dcs_pstop_mm: the comparator (single writer) bumps it before and after the 7 stores, so it is * odd while the record is in flux. Readers use dcs_pstop_mm_snapshot() and never see two events mixed. */ diff --git a/firmware/components/dcs_support/src/dcs_support.c b/firmware/components/dcs_support/src/dcs_support.c index 121cecdd..2ba4ea21 100644 --- a/firmware/components/dcs_support/src/dcs_support.c +++ b/firmware/components/dcs_support/src/dcs_support.c @@ -116,6 +116,11 @@ void dcs_pstop_mm_snapshot(uint32_t out[7]) } if ((uint32_t)atomic_load(&g_dcs_pstop_mm_seq) == s1) return; } + /* 8 collisions in a row (writer runs once per 100 ms tick — effectively + * never): deliver a best-effort copy rather than leave `out` untouched. */ + for (int i = 0; i < 7; i++) { + out[i] = (uint32_t)atomic_load(&g_dcs_pstop_mm[i]); + } } atomic_uint_fast32_t g_dcs_pstop_send_fail; diff --git a/firmware/main/main.c b/firmware/main/main.c index 5e8dc2f5..aef93f9b 100644 --- a/firmware/main/main.c +++ b/firmware/main/main.c @@ -1250,7 +1250,9 @@ static void comparator_task(void * arg) uint64_t done = (uint64_t)atomic_load(&g_core_done_us[c]); if (done > mm_late_notify_us) { uint32_t lat = (uint32_t)((done - mm_late_notify_us) / 1000u); - if (lat > mm[3]) mm[3] = lat; + if (lat > mm[5 + c]) mm[5 + c] = lat; /* the worst-case gauge must include exactly these slow publishes */ + if (((mm[2] >> 28) == 1u) && (lat > mm[3])) + mm[3] = lat; /* only while the record still describes that timeout */ mm_late &= ~(1u << c); } } @@ -1320,6 +1322,14 @@ static void comparator_task(void * arg) if (!in1) { mm_late |= 2u; } + for (int c = 0; c < 2; c++) { /* the core that DID publish in time: fold its latency into the gauge now */ + if ((mm_late & (1u << c)) != 0u) continue; + uint64_t done = (uint64_t)atomic_load(&g_core_done_us[c]); + uint32_t lat = (done > notify_us) ? (uint32_t)((done - notify_us) / 1000u) : 0u; + if (lat > mm[5 + c]) mm[5 + c] = lat; + } + /* verdict bytes: the late core has not published for THIS tick, so its byte is + * from its previous publish — the late mask in the same word says which. */ mm[2] = ((uint32_t)1u << 28) | (mm_late << 26) | ((uint32_t)0xFFu << 16) | ((uint32_t)g_verdict[0] << 8); mm[2] |= g_verdict[1]; mm[4] = (uint32_t)now_ms; @@ -1327,6 +1337,8 @@ static void comparator_task(void * arg) } else if (!lockstep_ok) { mismatch++; mm[1]++; + mm[3] = + 0u; /* late-core latency is a timeout-class field: n/a for a content event (a still-pending attribution goes to mm[5+c] only) */ mm[2] = ((uint32_t)2u << 28) | ((uint32_t)mm_slot << 24) | ((uint32_t)mm_off << 16); mm[2] |= ((uint32_t)g_verdict[0] << 8) | g_verdict[1]; mm[4] = (uint32_t)now_ms; From bc53048a48904c4c834fae2ef65f89474bbc6285 Mon Sep 17 00:00:00 2001 From: Ilia Baranov <90713890+iliabaranov@users.noreply.github.com> Date: Sun, 20 Sep 2026 00:41:38 -0700 Subject: [PATCH 4/5] =?UTF-8?q?diag(safety):=20seqlock=20readers=20?= =?UTF-8?q?=E2=80=94=20acquire=20fence=20before=20the=20sequence=20re-read?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit An acquire LOAD only pins the accesses that follow it; without a fence the payload loads could sink below the second sequence read and a torn record could pass the check. Both readers (dcs_pstop_mm_snapshot, ml_peer_nvs_get_flush_diag) now use the textbook reader: load seq (acquire), copy payload, atomic_thread_fence(acquire), re-read seq. --- components/microlink/src/ml_peer_nvs.c | 4 ++++ firmware/components/dcs_support/src/dcs_support.c | 1 + 2 files changed, 5 insertions(+) diff --git a/components/microlink/src/ml_peer_nvs.c b/components/microlink/src/ml_peer_nvs.c index 02286fe9..73bca52c 100644 --- a/components/microlink/src/ml_peer_nvs.c +++ b/components/microlink/src/ml_peer_nvs.c @@ -277,6 +277,10 @@ void ml_peer_nvs_get_flush_diag(uint32_t out[4]) out[1] = s_diag_flush_max_ms; out[2] = s_diag_flush_count; out[3] = s_diag_flush_at_ms; + /* Textbook seqlock reader: the acquire fence keeps the payload loads above + * the re-read of the sequence (an acquire LOAD alone only pins what follows + * it); the writer's seq_cst fetch_adds order its stores on the other side. */ + atomic_thread_fence(memory_order_acquire); if ((uint32_t)atomic_load(&s_diag_flush_seq) == s1) return; } /* 8 collisions (flushes are >= 5 s apart, so effectively never): best-effort copy so out[] is always written */ diff --git a/firmware/components/dcs_support/src/dcs_support.c b/firmware/components/dcs_support/src/dcs_support.c index 2ba4ea21..7c36f81f 100644 --- a/firmware/components/dcs_support/src/dcs_support.c +++ b/firmware/components/dcs_support/src/dcs_support.c @@ -114,6 +114,7 @@ void dcs_pstop_mm_snapshot(uint32_t out[7]) for (int i = 0; i < 7; i++) { out[i] = (uint32_t)atomic_load(&g_dcs_pstop_mm[i]); } + atomic_thread_fence(memory_order_acquire); /* payload loads stay above the seq re-read */ if ((uint32_t)atomic_load(&g_dcs_pstop_mm_seq) == s1) return; } /* 8 collisions in a row (writer runs once per 100 ms tick — effectively From 010f4c0c04e5f795a6e1b30f6954d6a0b44673c0 Mon Sep 17 00:00:00 2001 From: Ilia Baranov <90713890+iliabaranov@users.noreply.github.com> Date: Sun, 20 Sep 2026 08:40:57 -0700 Subject: [PATCH 5/5] =?UTF-8?q?diag(safety):=20review=20round=204=20?= =?UTF-8?q?=E2=80=94=20atomic=20flush-diag=20payload,=20host-tested=20shar?= =?UTF-8?q?ed=20publish=20window,=20every=20dcs=20NVS=20write=20timed?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit - ml_peer_nvs flush diag: the four payload words are atomics now (no data race), still published under the seqlock for record consistency. - comparator: the shared CORE_PUBLISH_TIMEOUT window is expressed through lockstep_window.h (pure) and pinned by firmware/test/test_lockstep_window.c (17 checks + a 1681-point sweep asserting: transmit iff both cores published within the ONE window, never a relaxation vs the old sequential takes, hold bounded by the window). Runs in make -C firmware/test run (CI coverage job). - dcs_nvs: every READWRITE handle is timed open->close (nvs_open_rw / nvs_close_rw), not only the health blob, and a max-hold is kept; /state.json nvs_dcs = [start, duration, max]. --- components/microlink/src/ml_peer_nvs.c | 41 +++--- .../dcs_support/src/dcs_admin_pages.c | 5 +- .../components/dcs_support/src/dcs_internal.h | 8 +- firmware/components/dcs_support/src/dcs_nvs.c | 118 +++++++++++------- .../components/dcs_support/src/dcs_support.c | 1 + firmware/main/lockstep_window.h | 62 +++++++++ firmware/main/main.c | 6 +- firmware/test/Makefile | 9 +- firmware/test/test_lockstep_window.c | 92 ++++++++++++++ 9 files changed, 272 insertions(+), 70 deletions(-) create mode 100644 firmware/main/lockstep_window.h create mode 100644 firmware/test/test_lockstep_window.c diff --git a/components/microlink/src/ml_peer_nvs.c b/components/microlink/src/ml_peer_nvs.c index 73bca52c..6e2bd030 100644 --- a/components/microlink/src/ml_peer_nvs.c +++ b/components/microlink/src/ml_peer_nvs.c @@ -255,14 +255,17 @@ void ml_peer_nvs_set_protected(uint32_t vpn_ip) /* Flush timing diag (§7 R6): the flash commit suspends flash-resident * execution on BOTH cores — these gauges make that cost measurable and the * fix falsifiable (flush_count flat in steady state = §7a working). */ -/* Flush diag record, published under a seqlock (s_diag_flush_seq odd while the - * writer is mid-update) so ml_peer_nvs_get_flush_diag() never returns e.g. a - * new count with the previous flush's duration. Single writer (ml_wg_mgr). */ +/* Flush diag record. Every word is atomic (no data race, each load returns a + * value some store wrote), and the record as a whole is published under a + * seqlock (s_diag_flush_seq odd while the writer is mid-update) so + * ml_peer_nvs_get_flush_diag() never pairs e.g. a new count with the previous + * flush's duration. Single writer (ml_wg_mgr). */ static atomic_uint_fast32_t s_diag_flush_seq; -static uint32_t s_diag_flush_last_ms; -static uint32_t s_diag_flush_max_ms; -static uint32_t s_diag_flush_count; -static uint32_t s_diag_flush_at_ms; /* uptime ms at the START of the last flush (soak item 5: overlap test) */ +static atomic_uint_fast32_t s_diag_flush_last_ms; +static atomic_uint_fast32_t s_diag_flush_max_ms; +static atomic_uint_fast32_t s_diag_flush_count; +static atomic_uint_fast32_t + s_diag_flush_at_ms; /* uptime ms at the START of the last flush (soak item 5: overlap test) */ static uint64_t s_defer_start_ms; /* nonzero while an ingest-busy deferral runs */ void ml_peer_nvs_get_flush_diag(uint32_t out[4]) @@ -273,10 +276,10 @@ void ml_peer_nvs_get_flush_diag(uint32_t out[4]) taskYIELD(); continue; } - out[0] = s_diag_flush_last_ms; - out[1] = s_diag_flush_max_ms; - out[2] = s_diag_flush_count; - out[3] = s_diag_flush_at_ms; + out[0] = (uint32_t)atomic_load(&s_diag_flush_last_ms); + out[1] = (uint32_t)atomic_load(&s_diag_flush_max_ms); + out[2] = (uint32_t)atomic_load(&s_diag_flush_count); + out[3] = (uint32_t)atomic_load(&s_diag_flush_at_ms); /* Textbook seqlock reader: the acquire fence keeps the payload loads above * the re-read of the sequence (an acquire LOAD alone only pins what follows * it); the writer's seq_cst fetch_adds order its stores on the other side. */ @@ -284,10 +287,10 @@ void ml_peer_nvs_get_flush_diag(uint32_t out[4]) if ((uint32_t)atomic_load(&s_diag_flush_seq) == s1) return; } /* 8 collisions (flushes are >= 5 s apart, so effectively never): best-effort copy so out[] is always written */ - out[0] = s_diag_flush_last_ms; - out[1] = s_diag_flush_max_ms; - out[2] = s_diag_flush_count; - out[3] = s_diag_flush_at_ms; + out[0] = (uint32_t)atomic_load(&s_diag_flush_last_ms); + out[1] = (uint32_t)atomic_load(&s_diag_flush_max_ms); + out[2] = (uint32_t)atomic_load(&s_diag_flush_count); + out[3] = (uint32_t)atomic_load(&s_diag_flush_at_ms); } esp_err_t ml_peer_nvs_flush_if_due(uint64_t now_ms, bool ingest_busy) @@ -317,10 +320,10 @@ esp_err_t ml_peer_nvs_flush_if_due(uint64_t now_ms, bool ingest_busy) esp_err_t r = flush_table(); uint32_t dur = (uint32_t)((esp_timer_get_time() - t0) / 1000); (void)atomic_fetch_add(&s_diag_flush_seq, 1u); /* odd: record in flux */ - s_diag_flush_last_ms = dur; - s_diag_flush_at_ms = (uint32_t)(t0 / 1000); - if (dur > s_diag_flush_max_ms) s_diag_flush_max_ms = dur; - s_diag_flush_count++; + atomic_store(&s_diag_flush_last_ms, dur); + atomic_store(&s_diag_flush_at_ms, (uint32_t)(t0 / 1000)); + if (dur > (uint32_t)atomic_load(&s_diag_flush_max_ms)) atomic_store(&s_diag_flush_max_ms, dur); + (void)atomic_fetch_add(&s_diag_flush_count, 1u); (void)atomic_fetch_add(&s_diag_flush_seq, 1u); /* even: consistent */ s_last_flush_ms = now_ms; if (r == ESP_OK) { diff --git a/firmware/components/dcs_support/src/dcs_admin_pages.c b/firmware/components/dcs_support/src/dcs_admin_pages.c index f9bdf180..e273c719 100644 --- a/firmware/components/dcs_support/src/dcs_admin_pages.c +++ b/firmware/components/dcs_support/src/dcs_admin_pages.c @@ -288,7 +288,7 @@ static esp_err_t page_state(httpd_req_t * req) "\"pstop_peer_ip\":%lu,\"pstop_peer_port\":%lu," "\"pstop_sent\":%lu,\"pstop_replies\":%lu,\"pstop_last_msg\":%lu,\"pstop_mismatch\":%lu," "\"pstop_mm_timeout\":%lu,\"pstop_mm_content\":%lu,\"pstop_mm_last\":[%lu,%lu,%lu]," - "\"pstop_core_lat_max_ms\":[%lu,%lu],\"nvs_pf\":[%lu,%lu,%lu],\"nvs_dcs\":[%lu,%lu]," + "\"pstop_core_lat_max_ms\":[%lu,%lu],\"nvs_pf\":[%lu,%lu,%lu],\"nvs_dcs\":[%lu,%lu,%lu]," "\"pstop_send_fail\":%lu,\"pstop_sf_nomem\":%lu,\"pstop_sf_route\":%lu," "\"pstop_sf_txdrv\":%lu,\"pstop_sf_txdrv_recovered\":%lu,\"pstop_sf_other\":%lu," "\"pstop_sf_enotconn\":%lu,\"pstop_sf_enotconn_kicks\":%lu,\"pstop_sf_errno\":%d,\"pstop_" @@ -391,8 +391,9 @@ static esp_err_t page_state(httpd_req_t * req) (unsigned long)pf[3], /* nvs_pf: start uptime ms, duration ms, max duration ms */ (unsigned long)pf[0], (unsigned long)pf[1], - (unsigned long)(uint32_t)(nvs_w >> 32), /* nvs_dcs: start uptime ms, duration ms (one 64-bit word) */ + (unsigned long)(uint32_t)(nvs_w >> 32), /* nvs_dcs: start uptime ms, duration ms (one 64-bit word), max ms */ (unsigned long)(uint32_t)(nvs_w & 0xFFFFFFFFu), + (unsigned long)atomic_load(&g_dcs_nvs_write_max), (unsigned long)atomic_load(&g_dcs_pstop_send_fail), (unsigned long)atomic_load(&g_dcs_pstop_sf_nomem), (unsigned long)atomic_load(&g_dcs_pstop_sf_route), diff --git a/firmware/components/dcs_support/src/dcs_internal.h b/firmware/components/dcs_support/src/dcs_internal.h index e8c48e86..b57e2e78 100644 --- a/firmware/components/dcs_support/src/dcs_internal.h +++ b/firmware/components/dcs_support/src/dcs_internal.h @@ -183,10 +183,12 @@ extern "C" * odd while the record is in flux. Readers use dcs_pstop_mm_snapshot() and never see two events mixed. */ extern atomic_uint_fast32_t g_dcs_pstop_mm_seq; void dcs_pstop_mm_snapshot(uint32_t out[7]); - /* Last dcs-side NVS write (dcs_nvs.c; both cores stall for the flash op), ONE 64-bit word so start and - * duration are always from the same write: start uptime ms << 32 | duration ms. Peer-cache flushes have - * their own diag (ml_peer_nvs_get_flush_diag). /state.json nvs_dcs / nvs_pf. */ + /* Last dcs-side NVS write (dcs_nvs.c times EVERY read-write handle open->close; both cores stall for the + * flash op), ONE 64-bit word so start and duration are always from the same write: start uptime ms << 32 | + * duration ms; plus the max duration this boot. Peer-cache flushes have their own diag + * (ml_peer_nvs_get_flush_diag). /state.json nvs_dcs = [start, duration, max] / nvs_pf. */ extern atomic_uint_fast64_t g_dcs_nvs_write; + extern atomic_uint_fast32_t g_dcs_nvs_write_max; extern atomic_uint_fast32_t g_dcs_pstop_send_fail; /* send_fail split by cause (errno at the failing sendto): ENOMEM = * TX-queue/pbuf pressure (typically DERP relay backpressure), route = diff --git a/firmware/components/dcs_support/src/dcs_nvs.c b/firmware/components/dcs_support/src/dcs_nvs.c index 61aa3d54..374288ca 100644 --- a/firmware/components/dcs_support/src/dcs_nvs.c +++ b/firmware/components/dcs_support/src/dcs_nvs.c @@ -35,6 +35,27 @@ static const char * TAG = "dcs_nvs"; +/* Every dcs-side READWRITE handle is timed from open to close: any NVS + * program/erase suspends flash-resident execution on BOTH cores, so every write + * path — not only the health blob — must show up in the nvs_dcs gauge that the + * lockstep-mismatch attribution is correlated against. Start and duration are + * published as ONE 64-bit word (start << 32 | duration) plus a max-hold. */ +static esp_err_t nvs_open_rw(nvs_handle_t * h, uint32_t * t0_ms) +{ + *t0_ms = (uint32_t)(esp_timer_get_time() / 1000); + return nvs_open(DCS_NVS_NS, NVS_READWRITE, h); +} + +static void nvs_close_rw(nvs_handle_t h, uint32_t t0_ms) +{ + nvs_close(h); + const uint32_t dur = (uint32_t)(esp_timer_get_time() / 1000) - t0_ms; + atomic_store(&g_dcs_nvs_write, ((uint64_t)t0_ms << 32) | (uint64_t)dur); + if (dur > (uint32_t)atomic_load(&g_dcs_nvs_write_max)) { + atomic_store(&g_dcs_nvs_write_max, dur); + } +} + bool dcs_nvs_read_usb_enabled(void) { nvs_handle_t h; @@ -48,13 +69,14 @@ bool dcs_nvs_read_usb_enabled(void) esp_err_t dcs_nvs_write_usb_enabled(bool enable) { nvs_handle_t h; - esp_err_t r = nvs_open(DCS_NVS_NS, NVS_READWRITE, &h); + uint32_t t0 = 0; + esp_err_t r = nvs_open_rw(&h, &t0); if (r != ESP_OK) return r; r = nvs_set_u8(h, DCS_NVS_KEY_USB_EN, enable ? 1 : 0); if (r == ESP_OK) { r = nvs_commit(h); } - nvs_close(h); + nvs_close_rw(h, t0); return r; } @@ -71,13 +93,14 @@ bool dcs_nvs_read_ts_boot_en(void) esp_err_t dcs_nvs_write_ts_boot_en(bool enable) { nvs_handle_t h; - esp_err_t r = nvs_open(DCS_NVS_NS, NVS_READWRITE, &h); + uint32_t t0 = 0; + esp_err_t r = nvs_open_rw(&h, &t0); if (r != ESP_OK) return r; r = nvs_set_u8(h, DCS_NVS_KEY_TS_BOOT_EN, enable ? 1 : 0); if (r == ESP_OK) { r = nvs_commit(h); } - nvs_close(h); + nvs_close_rw(h, t0); return r; } @@ -94,13 +117,14 @@ uint16_t dcs_nvs_read_boot_count(void) esp_err_t dcs_nvs_write_boot_count(uint16_t v) { nvs_handle_t h; - esp_err_t r = nvs_open(DCS_NVS_NS, NVS_READWRITE, &h); + uint32_t t0 = 0; + esp_err_t r = nvs_open_rw(&h, &t0); if (r != ESP_OK) return r; r = nvs_set_u16(h, DCS_NVS_KEY_BOOT_COUNT, v); if (r == ESP_OK) { r = nvs_commit(h); } - nvs_close(h); + nvs_close_rw(h, t0); return r; } @@ -131,7 +155,8 @@ uint16_t dcs_nvs_read_pstop_peer_port(void) esp_err_t dcs_nvs_write_pstop_peer(uint32_t ip, uint16_t port) { nvs_handle_t h; - esp_err_t r = nvs_open(DCS_NVS_NS, NVS_READWRITE, &h); + uint32_t t0 = 0; + esp_err_t r = nvs_open_rw(&h, &t0); if (r != ESP_OK) return r; r = nvs_set_u32(h, DCS_NVS_KEY_PSTOP_IP, ip); if (r == ESP_OK) { @@ -140,7 +165,7 @@ esp_err_t dcs_nvs_write_pstop_peer(uint32_t ip, uint16_t port) if (r == ESP_OK) { r = nvs_commit(h); } - nvs_close(h); + nvs_close_rw(h, t0); return r; } @@ -149,47 +174,51 @@ esp_err_t dcs_nvs_write_pstop_peer(uint32_t ip, uint16_t port) void dcs_nvs_set_xcheck_detail(uint8_t detail) { nvs_handle_t h; - if (nvs_open(DCS_NVS_NS, NVS_READWRITE, &h) != ESP_OK) { + uint32_t t0 = 0; + if (nvs_open_rw(&h, &t0) != ESP_OK) { ESP_LOGW(TAG, "xc_det: nvs_open failed"); return; } if (nvs_set_u8(h, "xc_det", detail) != ESP_OK || nvs_commit(h) != ESP_OK) { ESP_LOGW(TAG, "xc_det: write failed"); } - nvs_close(h); + nvs_close_rw(h, t0); } uint8_t dcs_nvs_take_xcheck_detail(void) { nvs_handle_t h; + uint32_t t0 = 0; uint8_t v = 0; - if (nvs_open(DCS_NVS_NS, NVS_READWRITE, &h) != ESP_OK) return 0; + if (nvs_open_rw(&h, &t0) != ESP_OK) return 0; if (nvs_get_u8(h, "xc_det", &v) == ESP_OK) { if (nvs_erase_key(h, "xc_det") != ESP_OK || nvs_commit(h) != ESP_OK) { ESP_LOGW(TAG, "xc_det: erase failed"); } } - nvs_close(h); + nvs_close_rw(h, t0); return v; } void dcs_nvs_set_ctrl_reset_cause(uint8_t cause) { nvs_handle_t h; - if (nvs_open(DCS_NVS_NS, NVS_READWRITE, &h) != ESP_OK) { + uint32_t t0 = 0; + if (nvs_open_rw(&h, &t0) != ESP_OK) { ESP_LOGW(TAG, "ctrl-reset crumb open failed (cause %u will be lost)", (unsigned)cause); return; } if (nvs_set_u8(h, DCS_NVS_KEY_CTRL_RST, cause) != ESP_OK || nvs_commit(h) != ESP_OK) { ESP_LOGW(TAG, "ctrl-reset crumb write failed (cause %u will be lost)", (unsigned)cause); } - nvs_close(h); + nvs_close_rw(h, t0); } uint8_t dcs_nvs_take_ctrl_reset_cause(void) { nvs_handle_t h; - if (nvs_open(DCS_NVS_NS, NVS_READWRITE, &h) != ESP_OK) return 0; + uint32_t t0 = 0; + if (nvs_open_rw(&h, &t0) != ESP_OK) return 0; uint8_t v = 0; if (nvs_get_u8(h, DCS_NVS_KEY_CTRL_RST, &v) == ESP_OK) { /* One-shot: a stale crumb must not mislabel a later POWERON/panic. The @@ -199,14 +228,15 @@ uint8_t dcs_nvs_take_ctrl_reset_cause(void) ESP_LOGW(TAG, "ctrl-reset crumb erase failed (stale value may persist)"); } } - nvs_close(h); + nvs_close_rw(h, t0); return v; } void dcs_nvs_push_reset_reason(uint8_t reason) { nvs_handle_t h; - if (nvs_open(DCS_NVS_NS, NVS_READWRITE, &h) != ESP_OK) return; + uint32_t t0 = 0; + if (nvs_open_rw(&h, &t0) != ESP_OK) return; uint8_t hist[DCS_RST_HIST_LEN] = {0}; size_t len = sizeof(hist); (void)nvs_get_blob(h, DCS_NVS_KEY_RST_HIST, hist, &len); /* absent -> stays zeroed */ @@ -217,7 +247,7 @@ void dcs_nvs_push_reset_reason(uint8_t reason) ESP_LOGW(TAG, "reset-history commit failed"); } } - nvs_close(h); + nvs_close_rw(h, t0); } uint8_t dcs_nvs_read_pstop_unit_num(void) @@ -233,13 +263,14 @@ uint8_t dcs_nvs_read_pstop_unit_num(void) esp_err_t dcs_nvs_write_pstop_unit_num(uint8_t n) { nvs_handle_t h; - esp_err_t r = nvs_open(DCS_NVS_NS, NVS_READWRITE, &h); + uint32_t t0 = 0; + esp_err_t r = nvs_open_rw(&h, &t0); if (r != ESP_OK) return r; r = nvs_set_u8(h, DCS_NVS_KEY_PSTOP_NUM, n); if (r == ESP_OK) { r = nvs_commit(h); } - nvs_close(h); + nvs_close_rw(h, t0); return r; } @@ -256,13 +287,14 @@ uint8_t dcs_nvs_read_ring_offset(void) esp_err_t dcs_nvs_write_ring_offset(uint8_t off) { nvs_handle_t h; - esp_err_t r = nvs_open(DCS_NVS_NS, NVS_READWRITE, &h); + uint32_t t0 = 0; + esp_err_t r = nvs_open_rw(&h, &t0); if (r != ESP_OK) return r; r = nvs_set_u8(h, DCS_NVS_KEY_RING_OFF, (uint8_t)(off & 0x0Fu)); if (r == ESP_OK) { r = nvs_commit(h); } - nvs_close(h); + nvs_close_rw(h, t0); return r; } @@ -283,13 +315,14 @@ esp_err_t dcs_nvs_write_wifi_tx_power(uint8_t quarter_dbm) { if ((quarter_dbm < 8u) || (quarter_dbm > 84u)) return ESP_ERR_INVALID_ARG; nvs_handle_t h; - esp_err_t r = nvs_open(DCS_NVS_NS, NVS_READWRITE, &h); + uint32_t t0 = 0; + esp_err_t r = nvs_open_rw(&h, &t0); if (r != ESP_OK) return r; r = nvs_set_u8(h, DCS_NVS_KEY_WIFI_TXP, quarter_dbm); if (r == ESP_OK) { r = nvs_commit(h); } - nvs_close(h); + nvs_close_rw(h, t0); return r; } @@ -310,13 +343,14 @@ esp_err_t dcs_nvs_write_led_brightness(uint8_t pct) { if (pct > 100u) return ESP_ERR_INVALID_ARG; nvs_handle_t h; - esp_err_t r = nvs_open(DCS_NVS_NS, NVS_READWRITE, &h); + uint32_t t0 = 0; + esp_err_t r = nvs_open_rw(&h, &t0); if (r != ESP_OK) return r; r = nvs_set_u8(h, DCS_NVS_KEY_LED_BRIGHT, pct); if (r == ESP_OK) { r = nvs_commit(h); } - nvs_close(h); + nvs_close_rw(h, t0); return r; } @@ -338,13 +372,14 @@ esp_err_t dcs_nvs_write_role(uint8_t role) return ESP_ERR_INVALID_ARG; } nvs_handle_t h; - esp_err_t r = nvs_open(DCS_NVS_NS, NVS_READWRITE, &h); + uint32_t t0 = 0; + esp_err_t r = nvs_open_rw(&h, &t0); if (r != ESP_OK) return r; r = nvs_set_u8(h, DCS_NVS_KEY_ROLE, role); if (r == ESP_OK) { r = nvs_commit(h); } - nvs_close(h); + nvs_close_rw(h, t0); return r; } @@ -441,7 +476,8 @@ esp_err_t dcs_nvs_write_pstop_peers(const dcs_pstop_peer_rec_t recs[DCS_PSTOP_MA } nvs_handle_t h; - esp_err_t r = nvs_open(DCS_NVS_NS, NVS_READWRITE, &h); + uint32_t t0 = 0; + esp_err_t r = nvs_open_rw(&h, &t0); if (r != ESP_OK) return r; r = nvs_set_blob(h, DCS_NVS_KEY_PSTOP_PEERS, blob, sizeof(blob)); if (r == ESP_OK) { @@ -458,7 +494,7 @@ esp_err_t dcs_nvs_write_pstop_peers(const dcs_pstop_peer_rec_t recs[DCS_PSTOP_MA if (r == ESP_OK) { r = nvs_commit(h); } - nvs_close(h); + nvs_close_rw(h, t0); return r; } @@ -520,12 +556,13 @@ int dcs_nvs_migrate_legacy_operators(void) uint8_t blob[LIST_BLOB_LEN] = {0}; size_t len = sizeof(blob); nvs_handle_t h; - if (nvs_open(DCS_NVS_NS, NVS_READWRITE, &h) != ESP_OK) { + uint32_t t0 = 0; + if (nvs_open_rw(&h, &t0) != ESP_OK) { return 0; } esp_err_t r = nvs_get_blob(h, DCS_NVS_KEY_LEGACY_OPERATORS, blob, &len); if (r != ESP_OK) { - nvs_close(h); + nvs_close_rw(h, t0); return 0; /* no legacy list: normal */ } int count = (len >= 1u) ? blob[0] : 0; @@ -553,7 +590,7 @@ int dcs_nvs_migrate_legacy_operators(void) if (nvs_erase_key(h, DCS_NVS_KEY_LEGACY_OPERATORS) == ESP_OK) { (void)nvs_commit(h); } - nvs_close(h); + nvs_close_rw(h, t0); ESP_LOGW( TAG, "legacy 'operators' list: %d id(s) migrated to the WG pin list (admission stays open; re-arm authority is the " @@ -573,13 +610,14 @@ esp_err_t dcs_nvs_write_list(dcs_list_t which, const uint32_t ids[DCS_MAX_LIST_I ps_peers_put_u32(&blob[1 + (i * 4)], ids[i]); } nvs_handle_t h; - esp_err_t r = nvs_open(DCS_NVS_NS, NVS_READWRITE, &h); + uint32_t t0 = 0; + esp_err_t r = nvs_open_rw(&h, &t0); if (r != ESP_OK) return r; r = nvs_set_blob(h, list_key(which), blob, sizeof(blob)); if (r == ESP_OK) { r = nvs_commit(h); } - nvs_close(h); + nvs_close_rw(h, t0); return r; } @@ -622,17 +660,13 @@ esp_err_t dcs_nvs_write_health(const dcs_health_counters_t * c) uint8_t blob[DCS_HEALTH_BLOB_LEN]; dcs_health_encode(c, blob); nvs_handle_t h; - const uint32_t t0 = (uint32_t)(esp_timer_get_time() / 1000); /* soak item 5: stamp this flash write */ - esp_err_t r = nvs_open(DCS_NVS_NS, NVS_READWRITE, &h); + uint32_t t0 = 0; + esp_err_t r = nvs_open_rw(&h, &t0); if (r != ESP_OK) return r; r = nvs_set_blob(h, DCS_NVS_KEY_HEALTH, blob, sizeof(blob)); /* flash program/erase happens HERE (commit = no-op) */ if (r == ESP_OK) { r = nvs_commit(h); } - nvs_close(h); - /* start and duration in ONE atomic word: a reader never pairs this write's - * duration with the previous write's start (or vice versa). */ - const uint32_t dur = (uint32_t)(esp_timer_get_time() / 1000) - t0; - atomic_store(&g_dcs_nvs_write, ((uint64_t)t0 << 32) | (uint64_t)dur); + nvs_close_rw(h, t0); return r; } diff --git a/firmware/components/dcs_support/src/dcs_support.c b/firmware/components/dcs_support/src/dcs_support.c index 7c36f81f..e264a4c8 100644 --- a/firmware/components/dcs_support/src/dcs_support.c +++ b/firmware/components/dcs_support/src/dcs_support.c @@ -99,6 +99,7 @@ atomic_uint_fast32_t g_dcs_pstop_mismatch; atomic_uint_fast32_t g_dcs_pstop_mm[7]; /* mismatch attribution — layout in dcs_internal.h */ atomic_uint_fast32_t g_dcs_pstop_mm_seq; /* seqlock for g_dcs_pstop_mm — see dcs_internal.h */ atomic_uint_fast64_t g_dcs_nvs_write; /* last dcs-side NVS write, start<<32 | duration — dcs_internal.h */ +atomic_uint_fast32_t g_dcs_nvs_write_max; /* longest dcs-side NVS write this boot, ms */ void dcs_pstop_mm_snapshot(uint32_t out[7]) { diff --git a/firmware/main/lockstep_window.h b/firmware/main/lockstep_window.h new file mode 100644 index 00000000..8928ed6b --- /dev/null +++ b/firmware/main/lockstep_window.h @@ -0,0 +1,62 @@ +// SPDX-FileCopyrightText: 2026 Polymath Robotics +// SPDX-License-Identifier: Apache-2.0 + +/* Lockstep publish window — pure, host-testable (firmware/test/test_lockstep_window.c). + * + * Each 100 ms tick the comparator notifies both encode cores at the same + * instant and then waits for their completion semaphores, core 0 first, then + * core 1. A tick transmits only if BOTH cores published within + * CORE_PUBLISH_TIMEOUT (80 ms) of the notify (SR-R-07: transmit on exact + * agreement of two fresh encodings; a late encoding is not fresh). + * + * Two sequential takes each armed with the full timeout do not implement that: + * when core 0 consumed the whole budget, core 1 got a fresh 80 ms on top — + * a tick could transmit with core 1 landing at 160 ms, and a both-late event + * was reported as "core 0 late". The window is therefore ONE absolute deadline + * shared by both takes: the second take gets whatever the first left. + */ + +#ifndef LOCKSTEP_WINDOW_H +#define LOCKSTEP_WINDOW_H + +#include +#include + +/* Wait for the second take given the budget and what the first take consumed + * (both in ticks). 0 = non-blocking take (still evaluated: a give already + * pending is consumed; one landing later is drained by the next tick). */ +static inline uint32_t lockstep_second_wait_ticks(uint32_t budget_ticks, uint32_t elapsed_ticks) +{ + return (elapsed_ticks < budget_ticks) ? (budget_ticks - elapsed_ticks) : 0u; +} + +/* Model of one tick's decision, for the host test and for reasoning about the + * window: each core's publish latency in ticks since the notify + * (LOCKSTEP_NEVER = did not publish). Mirrors the comparator: take 0 returns + * when core 0 publishes or at the deadline; take 1 waits the remainder. */ +#define LOCKSTEP_NEVER 0xFFFFFFFFu + +typedef struct +{ + bool in0; /* core 0 published within the window */ + bool in1; /* core 1 published within the window */ + bool transmit; /* both in -> the comparator may transmit (given agreement) */ + uint32_t late_mask; /* bit 0 = core 0 late, bit 1 = core 1 late */ + uint32_t tick_hold; /* how long the comparator was held by the two takes */ +} lockstep_tick_t; + +static inline lockstep_tick_t lockstep_tick_model(uint32_t budget_ticks, uint32_t done0, uint32_t done1) +{ + lockstep_tick_t r; + r.in0 = (done0 <= budget_ticks); + uint32_t elapsed = r.in0 ? done0 : budget_ticks; /* take 0 returns at publish or deadline */ + uint32_t wait1 = lockstep_second_wait_ticks(budget_ticks, elapsed); + r.in1 = (done1 <= elapsed + wait1); /* core 1 may already be done, or land inside the remainder */ + uint32_t end1 = r.in1 ? ((done1 > elapsed) ? done1 : elapsed) : (elapsed + wait1); + r.tick_hold = end1; + r.transmit = r.in0 && r.in1; + r.late_mask = (r.in0 ? 0u : 1u) | (r.in1 ? 0u : 2u); + return r; +} + +#endif /* LOCKSTEP_WINDOW_H */ diff --git a/firmware/main/main.c b/firmware/main/main.c index aef93f9b..3ecff987 100644 --- a/firmware/main/main.c +++ b/firmware/main/main.c @@ -53,6 +53,7 @@ #include "freertos/semphr.h" #include "freertos/task.h" #include "hal/gpio_ll.h" /* gpio_ll_get_io_config — pad-config read-back (SR-R-09) */ +#include "lockstep_window.h" #include "lwip/sockets.h" #include "pstop/protocol_data.h" #include "pstop/pstop_msg.h" @@ -1281,8 +1282,9 @@ static void comparator_task(void * arg) const bool in0 = (xSemaphoreTake(g_done[0], CORE_PUBLISH_TIMEOUT) == pdTRUE); const TickType_t take_used = xTaskGetTickCount() - take_t0; const bool in1 = - (xSemaphoreTake(g_done[1], (take_used < CORE_PUBLISH_TIMEOUT) ? (CORE_PUBLISH_TIMEOUT - take_used) : 0) == - pdTRUE); + (xSemaphoreTake( + g_done[1], (TickType_t)lockstep_second_wait_ticks((uint32_t)CORE_PUBLISH_TIMEOUT, (uint32_t)take_used)) == + pdTRUE); /* lockstep_window.h, host-tested */ bool both_in = in0 && in1; /* 5. Lockstep check across ALL active slots. Any disagreement taints diff --git a/firmware/test/Makefile b/firmware/test/Makefile index 4b9f7605..9ca9a167 100644 --- a/firmware/test/Makefile +++ b/firmware/test/Makefile @@ -28,10 +28,15 @@ test_estop_verdict: $(SRCS) test_dcs_health_logic: $(HEALTH_SRCS) $(CC) $(CFLAGS) $(HEALTH_INC) -o $@ $(HEALTH_SRCS) +# Comparator shared publish window (lockstep_window.h): pure header-only logic. +test_lockstep_window: test_lockstep_window.c ../main/lockstep_window.h + $(CC) $(CFLAGS) -I../main -o $@ test_lockstep_window.c + .PHONY: run coverage clean -run: test_estop_verdict test_dcs_health_logic +run: test_estop_verdict test_dcs_health_logic test_lockstep_window ./test_estop_verdict ./test_dcs_health_logic + ./test_lockstep_window coverage: run $(GCOVR) --root .. --gcov-executable $(GCOV) \ @@ -40,4 +45,4 @@ coverage: run --json-summary-pretty -o coverage-summary.json clean: - rm -f test_estop_verdict test_dcs_health_logic *.gcda *.gcno *.gcov coverage-summary.json + rm -f test_estop_verdict test_dcs_health_logic test_lockstep_window *.gcda *.gcno *.gcov coverage-summary.json diff --git a/firmware/test/test_lockstep_window.c b/firmware/test/test_lockstep_window.c new file mode 100644 index 00000000..0c1f7241 --- /dev/null +++ b/firmware/test/test_lockstep_window.c @@ -0,0 +1,92 @@ +// SPDX-FileCopyrightText: 2026 Polymath Robotics +// SPDX-License-Identifier: Apache-2.0 + +/* Host test for lockstep_window.h — the comparator's shared publish window + * (SR-R-07: transmit only on exact agreement of two FRESH encodings). + * + * Pins the behavioural change made in the lockstep-attribution work: both + * cores must publish within ONE 80 ms window measured from the notify. Under + * the previous two sequential takes (each with its own 80 ms), a tick could + * transmit with core 1 landing at up to 160 ms, and a both-late tick was + * attributed to core 0 alone. + * + * Build/run: make -C firmware/test run + */ + +#include + +#include "lockstep_window.h" + +static int fails = 0; +#define CHECK(cond, msg) \ + do { \ + if (!(cond)) { \ + printf("FAIL %s:%d: %s\n", __FILE__, __LINE__, msg); \ + fails++; \ + } \ + } while (0) + +#define BUDGET 80u /* CORE_PUBLISH_TIMEOUT in ms (1 ms ticks) */ + +int main(void) +{ + /* Remainder arithmetic. */ + CHECK(lockstep_second_wait_ticks(BUDGET, 0) == 80u, "core 0 instant -> core 1 gets the full window"); + CHECK(lockstep_second_wait_ticks(BUDGET, 30) == 50u, "core 0 at 30 ms -> core 1 gets 50 ms"); + CHECK(lockstep_second_wait_ticks(BUDGET, 79) == 1u, "core 0 at 79 ms -> core 1 gets 1 ms"); + CHECK(lockstep_second_wait_ticks(BUDGET, 80) == 0u, "core 0 timed out -> core 1 take is non-blocking"); + CHECK(lockstep_second_wait_ticks(BUDGET, 200) == 0u, "never negative / never a fresh budget"); + + /* Normal tick: both well inside. */ + lockstep_tick_t t = lockstep_tick_model(BUDGET, 5, 7); + CHECK(t.transmit && t.late_mask == 0u, "5/7 ms -> transmit"); + CHECK(t.tick_hold == 7u, "comparator held only until the slower core (7 ms)"); + + /* Core 1 first, core 0 later but inside: still one window. */ + t = lockstep_tick_model(BUDGET, 60, 10); + CHECK(t.transmit && t.tick_hold == 60u, "core 1 already done when take 1 runs -> transmit at 60 ms"); + + /* Boundary: exactly at the window edge is in; one tick past is out. */ + CHECK(lockstep_tick_model(BUDGET, 80, 80).transmit, "80/80 ms -> in (edge inclusive)"); + CHECK(!lockstep_tick_model(BUDGET, 81, 10).transmit, "core 0 at 81 ms -> tainted"); + CHECK(!lockstep_tick_model(BUDGET, 10, 81).transmit, "core 1 at 81 ms -> tainted"); + + /* THE CHANGE: core 0 on time at 79 ms, core 1 at 150 ms. The old sequential + * takes gave core 1 a fresh 80 ms after the 79 -> in until 159 ms -> the tick + * transmitted with a 150 ms-old encoding. Now the window is shared. */ + t = lockstep_tick_model(BUDGET, 79, 150); + CHECK(!t.transmit, "79/150 ms -> TAINTED (previously transmitted)"); + CHECK(t.in0 && !t.in1 && t.late_mask == 2u, "attributed to core 1 only"); + CHECK(t.tick_hold == 80u, "held exactly the window, not 159 ms"); + + /* Both late: both bits set, hold is exactly the window (was 160 ms). */ + t = lockstep_tick_model(BUDGET, 120, 130); + CHECK(!t.transmit && t.late_mask == 3u, "both late -> mask 0b11 (previously 'core 0 late' only)"); + CHECK(t.tick_hold == 80u, "worst-case tick stall is the window, not 2x"); + + /* A core that never publishes: tainted, hold bounded. */ + t = lockstep_tick_model(BUDGET, LOCKSTEP_NEVER, 3); + CHECK(!t.transmit && t.late_mask == 1u && t.tick_hold == 80u, "core 0 dead -> tainted, core 0 late, 80 ms hold"); + t = lockstep_tick_model(BUDGET, 3, LOCKSTEP_NEVER); + CHECK(!t.transmit && t.late_mask == 2u && t.tick_hold == 80u, "core 1 dead -> tainted, core 1 late, 80 ms hold"); + + /* Fail-safe direction only: nothing that was tainted before can transmit now. */ + for (uint32_t d0 = 0; d0 <= 200; d0 += 5) { + for (uint32_t d1 = 0; d1 <= 200; d1 += 5) { + bool old_in0 = d0 <= BUDGET; + uint32_t old_elapsed = old_in0 ? d0 : BUDGET; + bool old_in1 = d1 <= old_elapsed + BUDGET; /* the previous fresh-budget second take */ + bool old_tx = old_in0 && old_in1; + lockstep_tick_t n = lockstep_tick_model(BUDGET, d0, d1); + if (n.transmit && !old_tx) { + CHECK(0, "new window transmits where the old one did not (would be a relaxation)"); + } + if (n.transmit != (d0 <= BUDGET && d1 <= BUDGET)) { + CHECK(0, "transmit iff both cores published within the shared window"); + } + } + } + + if (fails == 0) printf("test_lockstep_window: OK (17 checks + 1681-point sweep)\n"); + return fails ? 1 : 0; +}