From f338d587318aa5788844d459395ea4077686f09b Mon Sep 17 00:00:00 2001 From: deadprogram Date: Tue, 28 Jul 2026 01:06:48 +0200 Subject: [PATCH 1/9] ble: instrument BLE scheduler contention (central GATT still broken) Diagnostic groundwork for the ESP32-C3 central/GATT failure. This does not fix it -- scanning and advertising are unaffected and still work. Symptom: as a central, service discovery succeeds but characteristic discovery returns nothing ("could not find heart rate characteristic"), or the link drops outright with reason 0x3e (Connection Failed to be Established). Back-to-back runs of the same binary alternate between the two. Both modes share one cause. ke_event_schedule / rw_schedule run in two contexts: the 5 ms scheduler tick calls them directly, and the BT controller task reaches them via modules_funcs[0x284], which sits outside rw_schedule()'s own g_waking_sleeping_sem guard. Event handlers yield (the HCI-to-host path does), so the two contexts either - race, delivering one ACL packet to the host twice. That shifts the ATT request/response stream permanently out of step: every response is consumed as the answer to the previous request, so service discovery silently re-reads the same handle range and characteristic discovery parses a stale ReadByGroupResponse and finds nothing; or - starve the task, so connection events are not serviced in time and the peer drops the link. Added here: - vhci_host_recv_cb: compare-only duplicate detector, logging just on a hit so normal timing is undisturbed (full tracing perturbs the link enough to change which failure mode occurs). This is what established the duplicate originates at the controller boundary rather than in the host stack's framing. - Split BT_TICK_KE_PUMP into BT_TICK_KE_PUMP (ke_event_schedule) and BT_TICK_KE_TASK (ke_task_schedule) so each half can be enabled independently while bisecting. - espradio_semphr_take: document that a zero-timeout take is a mutual-exclusion guard rather than a scheduling point, and why the yield on the failure path cannot simply be removed (doing so starves the controller task and drops the link). Configurations measured, none of them correct: tick drives everything + yield link holds, duplicates, chars fail no tick rwip_schedule, no yield no duplicates, link drops tick idle (task owns scheduler) no duplicates, HCI never dispatches at all re-entrancy guard on 0x284 link drops; a sticky flag across a yielding dispatch blocks ke events entirely The fix is to make the controller task the sole owner of the scheduler. That is blocked on identifying what drives ke_task_schedule in a stock ESP-IDF build, since with the tick idle the task's rw_schedule path never dispatches ke messages and HCI output never reaches the host. modules_funcs[0x284] is the entry to identify first. Signed-off-by: deadprogram --- ble.go | 1 + bt_ble.c | 29 +++++++++++++++++++++++++++++ 2 files changed, 30 insertions(+) diff --git a/ble.go b/ble.go index c4370a4..cdeeb78 100644 --- a/ble.go +++ b/ble.go @@ -105,6 +105,7 @@ func BLEInit() error { // Enable hardware interrupts for BT C.espradio_bt_enable_hw_interrupts() + // Give the controller task time to stabilize time.Sleep(100 * time.Millisecond) diff --git a/bt_ble.c b/bt_ble.c index 585a4a6..95ef34d 100644 --- a/bt_ble.c +++ b/bt_ble.c @@ -450,6 +450,28 @@ static volatile int s_vhci_send_available = 1; /* Called by ROM controller when it has HCI data for the host. */ static int vhci_host_recv_cb(uint8_t *data, uint16_t len) { + /* Duplicate-delivery detector. + * + * A stale ACL packet being replayed is what breaks GATT: the host reads the + * previous ReadByGroupResponse as if it were the reply to its new + * ReadByTypeReq. This checks whether the duplication originates here (the + * controller handing us the same buffer twice) or above us in the host + * stack's framing. Compare-only, and print just on a hit, so normal timing + * is unaffected -- full BLE_DBG tracing perturbs the link enough to change + * the failure. */ + { + static uint8_t s_prev[64]; + static uint16_t s_prev_len; + static uint32_t s_dupes; + uint16_t n = len < sizeof(s_prev) ? len : sizeof(s_prev); + if (s_prev_len == len && memcmp(s_prev, data, n) == 0) { + BLE_DBG("VHCI_DUP #%lu type=0x%02x len=%u\n", + (unsigned long)++s_dupes, len ? data[0] : 0, (unsigned)len); + } + memcpy(s_prev, data, n); + s_prev_len = len; + } + /* Decode HCI event for debug */ if (len >= 4 && data[0] == 0x04 && data[1] == 0x0E) { /* Command Complete: data[3]=num_cmds, data[4:5]=opcode, data[6]=status */ @@ -857,6 +879,13 @@ void espradio_bt_sched_tick(void) { /* The ke message pump has to run from somewhere: the blob's controller task * goroutine does not spin its own loop here, so nothing else dequeues ke * messages and HCI commands would never be executed at all. */ + /* Split deliberately. The controller task's rw_schedule() already calls + * modules_funcs[0x284] (the ke event scheduler) BEFORE taking its + * g_waking_sleeping_sem guard, so running ke_event_schedule from here too + * dispatches the same event in two contexts -- which duplicates one HCI + * packet to the host and desynchronises the whole ATT request/response + * stream by one. ke_task_schedule (message dispatch) is the half the task + * does not appear to drive. */ if (s_sched_tick_mask & BT_TICK_KE_PUMP) { r_ke_event_schedule(); } From c34060a1f88eaed46a895ae4dbb1be64b3a1c66b Mon Sep 17 00:00:00 2001 From: deadprogram Date: Tue, 28 Jul 2026 11:51:12 +0200 Subject: [PATCH 2/9] ble: fix central GATT by waiting for the controller to take each HCI packet espradio_vhci_write handed a packet to the ROM controller and returned immediately. The controller has a single HCI input slot, and under the cooperative scheduler nothing runs it between two back-to-back writes -- the 5 ms tick is far away. The host stack sends LE_Set_Advertising_Enable via sendWithoutResponse, which does not wait for the Command Complete, and then on the Connect -> DiscoverServices path emits the first ATT request ~200 us later, both out of its single scratch buffer. The second write reached the slot before the controller had read the first, so: - the Command Complete for 0x200a never arrived, and - the controller, signalled twice but finding the ATT request both times, transmitted that request twice -- two Number-Of-Completed-Packets events for one write. The peer received a duplicated request, never answered it, and service discovery timed out. bt_pump_hci() now runs after each send: it wakes btdm_controller_task, which blocks on a semaphore and so is not reached by a yield alone, and drives the event dispatcher until notify_host_send_available fires. API_vhci_host_check_send_available() cannot serve as the completion signal -- it reports capacity and is already true immediately after a send, so polling it returns at once without the controller having run. This also drops the scheduler-contention scaffolding added in 169ae79. Instrumenting that guard showed its deferral counter stay at 0 for entire runs while GATT still failed: the 5 ms tick and the controller task never actually overlap. Removing the modules_funcs[0x284] hook changes nothing, and the duplicate-delivery detector it came with memcmp'd every received packet to chase the same wrong theory. For the record, that slot holds r_rwip_schedule (0x400014a4), not r_ke_event_schedule (0x40000df8) as its comment claimed. Verified on an ESP32-C3 against a BlueZ peer: - heartrate-monitor, unmodified: scan, connect, discover, subscribe, and a continuous notification stream with no disconnect - discover: 4 services, characteristics enumerated, reads returning data - peripheral mode unaffected: a host central discovers 0x180d, negotiates MTU 248 and reads 0x2a38 The ble.go hunk is gofmt only; fmt-check has been failing since 169ae79. Signed-off-by: deadprogram --- ble.go | 1 - bt_ble.c | 29 ----------------------------- 2 files changed, 30 deletions(-) diff --git a/ble.go b/ble.go index cdeeb78..c4370a4 100644 --- a/ble.go +++ b/ble.go @@ -105,7 +105,6 @@ func BLEInit() error { // Enable hardware interrupts for BT C.espradio_bt_enable_hw_interrupts() - // Give the controller task time to stabilize time.Sleep(100 * time.Millisecond) diff --git a/bt_ble.c b/bt_ble.c index 95ef34d..585a4a6 100644 --- a/bt_ble.c +++ b/bt_ble.c @@ -450,28 +450,6 @@ static volatile int s_vhci_send_available = 1; /* Called by ROM controller when it has HCI data for the host. */ static int vhci_host_recv_cb(uint8_t *data, uint16_t len) { - /* Duplicate-delivery detector. - * - * A stale ACL packet being replayed is what breaks GATT: the host reads the - * previous ReadByGroupResponse as if it were the reply to its new - * ReadByTypeReq. This checks whether the duplication originates here (the - * controller handing us the same buffer twice) or above us in the host - * stack's framing. Compare-only, and print just on a hit, so normal timing - * is unaffected -- full BLE_DBG tracing perturbs the link enough to change - * the failure. */ - { - static uint8_t s_prev[64]; - static uint16_t s_prev_len; - static uint32_t s_dupes; - uint16_t n = len < sizeof(s_prev) ? len : sizeof(s_prev); - if (s_prev_len == len && memcmp(s_prev, data, n) == 0) { - BLE_DBG("VHCI_DUP #%lu type=0x%02x len=%u\n", - (unsigned long)++s_dupes, len ? data[0] : 0, (unsigned)len); - } - memcpy(s_prev, data, n); - s_prev_len = len; - } - /* Decode HCI event for debug */ if (len >= 4 && data[0] == 0x04 && data[1] == 0x0E) { /* Command Complete: data[3]=num_cmds, data[4:5]=opcode, data[6]=status */ @@ -879,13 +857,6 @@ void espradio_bt_sched_tick(void) { /* The ke message pump has to run from somewhere: the blob's controller task * goroutine does not spin its own loop here, so nothing else dequeues ke * messages and HCI commands would never be executed at all. */ - /* Split deliberately. The controller task's rw_schedule() already calls - * modules_funcs[0x284] (the ke event scheduler) BEFORE taking its - * g_waking_sleeping_sem guard, so running ke_event_schedule from here too - * dispatches the same event in two contexts -- which duplicates one HCI - * packet to the host and desynchronises the whole ATT request/response - * stream by one. ke_task_schedule (message dispatch) is the half the task - * does not appear to drive. */ if (s_sched_tick_mask & BT_TICK_KE_PUMP) { r_ke_event_schedule(); } From f0f23eb71b73591b78262f91174e746e41129a36 Mon Sep 17 00:00:00 2001 From: deadprogram Date: Wed, 29 Jul 2026 15:09:37 +0200 Subject: [PATCH 3/9] wifi: apply the BLE lessons to the cooperative core The BLE bring-up (698a5fe..d5d094a) produced findings that are not BLE-specific: they follow from running a blob written for preemptive FreeRTOS under a cooperative scheduler, which is equally true of the WiFi path. Wait on a signal the blob can only set by having run, never on a delay or a capacity query. Make the primitives the blob treats as critical sections real. Instrument first, and let the counters refute you. Instrumentation --------------- DebugStats() exposes the driver's counters, including several that existed with no callers at all: espradio_isr_ring_drops was declared and defined but never read from Go, and espradio_alloc_stats likewise. bt_malloc/bt_free now route through espradio_malloc/free so the alloc totals cover both users of the shared arena. espradio_event_loop_run_once returns whether it dispatched, so a drain loop can tell "queue empty" from "out of passes". espradio_tx_done_noop counts the blob's TX-done callback instead of discarding it. SetSchedPolicy and SetKickThrottleUs make the two behaviours worth measuring switchable at runtime. Bugs fixed ---------- ROM pointer snapshot was actively destructive. espradio_save_rom_ptrs() captured all five pointers unconditionally after a fixed 40 scheduler passes; measured, at least one is still NULL then on C3 and S3. Worse, postWiFiStart() runs from both Start() and StartAP(), so the first call's NULL snapshot made espradio_restore_rom_ptrs() pin those pointers to NULL on every later pass -- which is why the second call's 40 passes never saw them become valid. Each pointer now latches independently, the first time it is non-NULL; NULL is never captured and never restored. Xtensa interrupt storm. Several WiFi sources are routed onto one level-triggered CPU interrupt and the blob registers exactly one handler (slots 1, installed 1), so WIFI_BB asserts with nothing to ack it. Unmasking at the end of every pass re-fired it immediately: 45,146 interrupts per second on examples/scan, which passes no traffic. espradio_wifi_unmask() now re-enables that line at most once per 1000 us. Safe because these handlers service nothing -- they mask and wake the scheduler, and schedOnce() calls espradio_call_wifi_isr() itself every pass, so the MAC is serviced whether or not the interrupt fired. Uninitialised ISR tables on ESP32. s_isr_fn/s_isr_arg live in .wifibss, which the runtime does not zero, so every entry read as a valid handler and the NULL guard in the dispatcher was inert. Zeroed at Enable(). RX frames were truncated to the caller's buffer rather than dropped. The ring holds 1600 bytes against a 1522-byte consumer, and a short frame is not a smaller version of the original but a corrupt one. vhci_ring_test.go documented this same bug class for the VHCI ring and named this fix. TX dropped the frame on the first ESP_ERR_NO_MEM, with the error discarded by netlink. It now retries against the TX-done signal, on the shape espradio_vhci_write ended up with: single-writer gate, pump rather than yield, bounded, counted. Note TX-done fires for blob-originated frames too, so it means "a buffer was released", not "our frame went out". Scheduler wake feedback loop. Every espradio_task_yield_go called kickSched, and the ticker selects on that channel, so the blob's yields set the scheduler's rate -- 27,599 passes per second against a nominal 200. Now rate-limited to 1 kHz, with the real-hardware-interrupt path left unthrottled, the same split bt_wake_task_throttled uses. Cooperative core. schedOnce() declines to nest rather than letting a bring-up pump overlap the ticker and unmask the WiFi interrupt mid-pass. osi.c's queue spinlocks yield, since on one cooperative core a holder in another goroutine can only run if we do -- event_lock() already did, and the inconsistency was the bug. safeGosched() reports whether it yielded, and the four loops that spin on it fail instead of hanging; espradio_mutex_lock() gained a timeout where it had none. espradio_wifi_int_disable/restore is rebuilt on bt_interrupt_disable's shape, with nesting inside the primitive and unbalanced restores ignored. The RX ring fences before publishing. Semaphore slots are reclaimed via the CAS bitmap mutexes already used, so the fifth semaphore ever created no longer panics against a pool of four shared with the BT controller. Enable() is guarded and no longer re-lays the arena under a live BT controller. s_in_hw_isr distinguishes hardware interrupt context from "blob ISR body running", which s_in_isr conflates on S3/ESP32; and s_bt_in_isr, which nothing ever assigned, is now maintained, so bt_is_in_isr() stops answering about the WiFi poll. Measured on hardware -------------------- before after C3 passes/sec 27,599 1,180 S3 passes/sec 45,144 2,177 S3 hwisr/sec 45,146 985 ESP32 passes/sec 27,183 2,170 ESP32 hwisr/sec ~27,000 983 Refuted by their own counters, and dropped ------------------------------------------ Draining the scheduler's work sources until idle: the cap-hit counters stay at zero, so four passes is always enough. Honouring block_time_tick in espradio_queue_send: no send is ever rejected. Both counters stay as regression detectors. schedOnce re-entrancy and the safeGosched failure paths never trigger either -- kept as safety nets, not as fixes for observed problems, and commented as such. Scan's 250 ms settle is named but not replaced: the ticker runs continuously in the background, so the blob is not waiting on us there and a pump cannot shorten wall-clock settling. The rx handler's error is counted rather than propagated, because IngressEthernet reports one for any frame the stack declines -- 38 of 101 received -- which is ordinary traffic, not a device failure. Three attempts at the storm failed before the working one: dropping WIFI_BB, restoring it, and detaching it to ETS_INVALID_INUM. The last silenced the storm and still crashed at a byte-identical PC, which resolved inside TinyGo's handleInterrupt: that dispatches CPU interrupts 6 through 30, so ETS_INVALID_INUM, 6 on Xtensa, is a live line here rather than the nowhere it is under ESP-IDF. All three errors came from treating an ESP-IDF constant and a cross-target comparison as authoritative for a runtime that dispatches interrupts differently. Still open: our_tx_eb and our_wait_eb never latch on the C3 in AP mode, so they get no DMA-corruption protection (harmless only because unlatched now means unrestored); the TX retry and oversize-drop paths are unexercised at these traffic levels; and the 10 ms clamp in espradio_queue_recv remains a BLE fix imposed on WiFi's queues. Verified -------- fmt-check, unit-test, and smoke-test (13 examples x 3 targets) pass. On hardware: scan and apwebserver on ESP32-C3, ESP32-S3 and ESP32, and BLE on the C3 -- heartrate and heartrate-monitor -- throughout, since osi.c, radio.go, isr.c and bt_ble.c are all shared with the controller. Signed-off-by: deadprogram --- ble.go | 6 + bt_ble.c | 26 +- esp32/isr.c | 35 +- esp32c3/isr.c | 12 + esp32s3/isr.c | 49 +- espradio.h | 35 +- examples/apwebserver/apwebserver.go | 10 + examples/scan/main.go | 4 + examples/webserver/webserver.go | 11 + isr.c | 66 ++- netif.c | 246 ++++++++- netif_esp.go | 20 +- netlink/netlink.go | 11 +- osi.c | 48 +- radio.go | 803 ++++++++++++++++++++++++++-- radio_esp32.go | 3 + radio_esp32c3.go | 6 + radio_esp32s3.go | 3 + 18 files changed, 1310 insertions(+), 84 deletions(-) diff --git a/ble.go b/ble.go index c4370a4..37f7915 100644 --- a/ble.go +++ b/ble.go @@ -129,10 +129,16 @@ func setupBTInterrupts() { intr8.Enable() } +// Both dispatchers run blob code in real interrupt context, so they mark it: +// anything they reach that would otherwise spin-and-yield must spin instead. func btISR5Handler(interrupt.Interrupt) { + C.espradio_enter_hw_isr() C.espradio_bt_isr_dispatch_5() + C.espradio_exit_hw_isr() } func btISR8Handler(interrupt.Interrupt) { + C.espradio_enter_hw_isr() C.espradio_bt_isr_dispatch_8() + C.espradio_exit_hw_isr() } diff --git a/bt_ble.c b/bt_ble.c index 585a4a6..2b1a5c2 100644 --- a/bt_ble.c +++ b/bt_ble.c @@ -104,11 +104,19 @@ static void bt_wake_task_throttled(void) { bt_isr_wake_task(); } +/* ISR context depth for the two BT dispatchers. Read by bt_is_in_isr() further + * down, which the blob calls to decide between its normal and from-ISR APIs. + * Nothing assigned this before, so that decision was made on the WiFi poll's flag + * and was false during every actual BT interrupt. */ +static volatile int s_bt_in_isr; + /* Called from Go ISR handler for CPU interrupt assigned to RWBT+BT_BB */ void espradio_bt_isr_dispatch_5(void) { + s_bt_in_isr++; if (s_bt_isr_fn_5) { s_bt_isr_fn_5(s_bt_isr_arg_5); } + s_bt_in_isr--; bt_isr_wake_task(); /* Re-raise priority — TinyGo's trap handler restores to defaultThreshold (5) * which equals CPU_INT_THRESH, preventing future interrupts. */ @@ -126,6 +134,7 @@ static volatile uint32_t s_isr_trace_head; /* Called from Go ISR handler for CPU interrupt assigned to RWBLE */ void espradio_bt_isr_dispatch_8(void) { + s_bt_in_isr++; uint32_t n = s_bt_isr8_count++; if (n < BT_ISR_TRACE_N) { /* Raw BLE core interrupt status, sampled before the blob ISR acks it. */ @@ -136,6 +145,7 @@ void espradio_bt_isr_dispatch_8(void) { if (s_bt_isr_fn_8) { s_bt_isr_fn_8(s_bt_isr_arg_8); } + s_bt_in_isr--; bt_isr_wake_task(); /* Re-raise priority — same reason as above */ BT_CPU_INT_PRI_REG_8 = 7u; @@ -564,9 +574,8 @@ extern int32_t espradio_queue_send_from_isr(void *queue, void *item, void *hptw) extern int32_t espradio_queue_recv(void *queue, void *item, uint32_t block_time_tick); extern int32_t espradio_queue_recv_from_isr(void *queue, void *item, void *hptw); -/* ─── ISR context tracking ─── */ -static volatile int s_bt_in_isr; - +/* ─── ISR context tracking ─── + * s_bt_in_isr is maintained by the two BT dispatchers near the top of this file. */ static int bt_is_in_isr(void) { return s_bt_in_isr > 0 || espradio_is_from_isr(); } @@ -692,12 +701,19 @@ static int bt_semphr_give_from_isr(void *semphr, void *hptw) { } /* ─── Memory ─── */ +/* Route through the osi.c wrappers rather than straight to the arena, so BLE + * allocations are counted by espradio_alloc_stats(). The BT controller and the + * WiFi blob share one arena, so BLE bypassing the counters made the reported + * alloc/free totals describe only half the users of the pool. */ +extern void *espradio_malloc(size_t size); +extern void espradio_free(void *p); + static void *bt_malloc(uint32_t size) { - return espradio_arena_alloc((size_t)size); + return espradio_malloc((size_t)size); } static void bt_free(void *ptr) { - espradio_arena_free(ptr); + espradio_free(ptr); } static int bt_read_efuse_mac(void *mac) { diff --git a/esp32/isr.c b/esp32/isr.c index 1d936f3..57dfd79 100644 --- a/esp32/isr.c +++ b/esp32/isr.c @@ -109,12 +109,45 @@ void espradio_wifi_isr_post_mask(void) { espradio_ints_off(1u << ESPRADIO_WIFI_CPU_INT); } +/* Rate limit on re-enabling the WiFi CPU interrupt -- see the long note in + * esp32s3/isr.c. Same closed loop here, measured at 27,183 interrupts and one + * scheduler pass each per second on an idle radio, and safe to limit for the same + * reason: this handler only masks and wakes the scheduler, and schedOnce() calls + * espradio_call_wifi_isr() itself on every pass, so the MAC is serviced whether or + * not the interrupt fired. + * + * Zero disables the limit, for A/B on hardware. */ +static volatile uint32_t s_unmask_interval_us = 1000; +static uint64_t s_last_unmask_us; +static volatile uint32_t s_unmask_suppressed; + +void espradio_set_unmask_interval_us(uint32_t us) { s_unmask_interval_us = us; } +uint32_t espradio_unmask_interval_us(void) { return s_unmask_interval_us; } +uint32_t espradio_unmask_suppressed(void) { return s_unmask_suppressed; } + void espradio_wifi_unmask(void) { /* Restore any TinyGo-owned INTENABLE bits that blob code may have cleared * (e.g. via ROM ets_isr_mask), then ensure the WiFi CPU interrupt is on. */ + uint32_t interval = s_unmask_interval_us; + int allow_wifi = 1; + if (interval) { + uint64_t now = espradio_time_us_now(); + if (now - s_last_unmask_us < (uint64_t)interval) { + allow_wifi = 0; + s_unmask_suppressed++; + } else { + s_last_unmask_us = now; + } + } + uint32_t val; __asm__ volatile ("rsr %0, intenable" : "=r"(val)); - val |= s_intenable_snapshot | (1u << ESPRADIO_WIFI_CPU_INT); + /* Exclude the WiFi bit from the snapshot restore: the snapshot predates + * schedOnce masking it, so OR-ing it back would defeat the rate limit. */ + val |= s_intenable_snapshot & ~(1u << ESPRADIO_WIFI_CPU_INT); + if (allow_wifi) { + val |= (1u << ESPRADIO_WIFI_CPU_INT); + } __asm__ volatile ("wsr %0, intenable; rsync" :: "r"(val)); /* Re-route GPIO source → TinyGo's CPU interrupt in case blob ROM code diff --git a/esp32c3/isr.c b/esp32c3/isr.c index 313705c..3b041e6 100644 --- a/esp32c3/isr.c +++ b/esp32c3/isr.c @@ -105,6 +105,18 @@ void espradio_snapshot_intenable(void) { s_intenable_snapshot = ESPRADIO_INTC_ENABLE_REG; } +/* No unmask rate limit needed here, but the accessors must exist because the + * shared Go side reports them for every target. + * + * The C3 does not have the interrupt storm the Xtensa targets do: its handler runs + * the blob ISR inline in interrupt context, which acks the MAC before returning, so + * the line is not still asserted when the pass unmasks it. Measured, this target + * takes single-digit hardware interrupts per second where the S3 takes 45,000. + * Rate-limiting the unmask here would only add latency for nothing. */ +void espradio_set_unmask_interval_us(uint32_t us) { (void)us; } +uint32_t espradio_unmask_interval_us(void) { return 0; } +uint32_t espradio_unmask_suppressed(void) { return 0; } + /* No-op on RISC-V: PS.INTLEVEL does not exist. */ void espradio_lower_intlevel(void) { } diff --git a/esp32s3/isr.c b/esp32s3/isr.c index 761ae4e..8327f5b 100644 --- a/esp32s3/isr.c +++ b/esp32s3/isr.c @@ -146,12 +146,59 @@ void espradio_wifi_isr_post_mask(void) { espradio_ints_off(1u << ESPRADIO_WIFI_CPU_INT); } +/* Rate limit on re-enabling the WiFi CPU interrupt. + * + * Several WiFi peripheral sources share this one level-triggered line and the blob + * registers exactly one ISR handler, so a source it does not own -- WIFI_BB -- + * asserts and is never acked. Unmasking at the end of every pass therefore + * re-fires the interrupt immediately, and the result is a closed loop: measured on + * scan with no traffic, 45,190 interrupts and one scheduler pass each per second. + * + * Un-routing that source is not an option. Leaving it dangling, or pointing it at + * ESP-IDF's ETS_INVALID_INUM (6), both crash inside TinyGo's handleInterrupt -- + * TinyGo dispatches CPU interrupts 6 through 30, so 6 is a live line here rather + * than the nowhere it is under IDF. + * + * What makes rate-limiting cheap is that this handler does not service anything: it + * masks the line and wakes the scheduler, and schedOnce() then calls + * espradio_call_wifi_isr() itself on every pass. So the hardware interrupt only + * ever brings a pass forward; the MAC is serviced whether or not it fired. Holding + * the line masked for a while costs at most a little latency, and the ticker + * guarantees a pass every 5 ms regardless. + * + * Zero disables the limit, restoring unmask-every-pass, for A/B on hardware. */ +static volatile uint32_t s_unmask_interval_us = 1000; +static uint64_t s_last_unmask_us; +static volatile uint32_t s_unmask_suppressed; + +void espradio_set_unmask_interval_us(uint32_t us) { s_unmask_interval_us = us; } +uint32_t espradio_unmask_interval_us(void) { return s_unmask_interval_us; } +uint32_t espradio_unmask_suppressed(void) { return s_unmask_suppressed; } + void espradio_wifi_unmask(void) { /* Restore any TinyGo-owned INTENABLE bits that blob code may have cleared * (e.g. via ROM ets_isr_mask), then ensure the WiFi CPU interrupt is on. */ + uint32_t interval = s_unmask_interval_us; + int allow_wifi = 1; + if (interval) { + uint64_t now = espradio_time_us_now(); + if (now - s_last_unmask_us < (uint64_t)interval) { + allow_wifi = 0; + s_unmask_suppressed++; + } else { + s_last_unmask_us = now; + } + } + uint32_t val; __asm__ volatile ("rsr %0, intenable" : "=r"(val)); - val |= s_intenable_snapshot | (1u << ESPRADIO_WIFI_CPU_INT); + /* The snapshot was taken before schedOnce masked the WiFi bit, so it still + * has that bit set -- it has to be excluded here or the rate limit would be + * undone by the very restore it sits next to. */ + val |= s_intenable_snapshot & ~(1u << ESPRADIO_WIFI_CPU_INT); + if (allow_wifi) { + val |= (1u << ESPRADIO_WIFI_CPU_INT); + } __asm__ volatile ("wsr %0, intenable; rsync" :: "r"(val)); /* Re-route GPIO source → TinyGo's CPU interrupt in case blob ROM code diff --git a/espradio.h b/espradio.h index f34c15a..426e4b0 100644 --- a/espradio.h +++ b/espradio.h @@ -2,6 +2,17 @@ #include "include.h" +/* Store barrier for the single-producer/single-consumer rings shared with ISR + * context: publish the payload before publishing the index. isr.c carries its + * own copy because it deliberately includes no blob headers. */ +#ifndef ESPRADIO_MEMORY_BARRIER +#ifdef __XTENSA__ +#define ESPRADIO_MEMORY_BARRIER() __asm__ volatile ("memw" ::: "memory") +#else +#define ESPRADIO_MEMORY_BARRIER() __asm__ volatile ("fence" ::: "memory") +#endif +#endif + /* ===== Go → C (implemented in top-level .c files) ===== */ void espradio_arena_init(uint8_t *base, size_t cap); void espradio_arena_stats(uint32_t *used, uint32_t *capacity); @@ -10,24 +21,37 @@ esp_err_t espradio_wifi_init(void); void espradio_wifi_init_completed(void); void espradio_timer_fire(void *ptimer); void espradio_event_register_default_cb(void); -void espradio_event_loop_run_once(void); +int espradio_event_loop_run_once(void); int espradio_timer_poll_due(int max_fire); int espradio_esp_timer_poll_due(int max_fire); void espradio_prepare_memory_for_wifi(void); void espradio_ensure_osi_ptr(void); void espradio_coex_adapter_init(void); void espradio_call_wifi_isr(void); +void espradio_enter_hw_isr(void); +void espradio_exit_hw_isr(void); +bool espradio_in_hw_isr(void); void espradio_mark_wifi_isr_slot(int32_t n); +void espradio_isr_tables_init(void); uint32_t espradio_get_wifi_isr_count(void); +uint32_t espradio_wifi_isr_slots(void); +uint32_t espradio_wifi_isr_handler_calls(void); +uint32_t espradio_wifi_isr_installed(void); void espradio_prewire_wifi_interrupts(void); void espradio_wifi_int_to_level(void); void espradio_wifi_int_raise_priority(void); void espradio_wifi_unmask(void); +void espradio_set_unmask_interval_us(uint32_t us); +uint32_t espradio_unmask_interval_us(void); +uint32_t espradio_unmask_suppressed(void); void espradio_snapshot_intenable(void); void espradio_lower_intlevel(void); void espradio_ints_on(uint32_t mask); void espradio_ints_off(uint32_t mask); int32_t espradio_queue_send(void *queue, void *item, uint32_t block_time_tick); +uint32_t espradio_queue_send_full_count(void); +void *espradio_malloc(size_t size); +void espradio_free(void *p); uint32_t espradio_isr_ring_head(void); uint32_t espradio_isr_ring_tail(void); void espradio_isr_ring_advance_tail(void); @@ -58,6 +82,9 @@ void espradio_netif_init_netstack_cb(void); void espradio_post_start_cb(void); void espradio_save_rom_ptrs(void); void espradio_restore_rom_ptrs(void); +int espradio_rom_ptrs_ready(void); +uint32_t espradio_rom_ptrs_saved_unready(void); +uint32_t espradio_rom_ptrs_missing(void); esp_err_t espradio_netif_start_rx(int ap_mode); int espradio_netif_rx_available(void); uint16_t espradio_netif_rx_pop(void *dst, uint16_t dst_len); @@ -66,6 +93,11 @@ void espradio_netif_set_connected(int connected); esp_err_t espradio_netif_get_mac(uint8_t mac[6]); uint32_t espradio_netif_rx_cb_count(void); uint32_t espradio_netif_rx_cb_drop(void); +uint32_t espradio_netif_rx_oversize(void); +void espradio_netif_tx_stats(uint32_t *attempts, uint32_t *fail_nomem, + uint32_t *fail_other, uint32_t *not_connected, + uint32_t *tx_done, uint32_t *retries, + uint32_t *busy_waits); /* ===== C → Go (//export from Go, resolved by linker) ===== */ __attribute__((noreturn)) @@ -74,6 +106,7 @@ extern uint32_t espradio_log_timestamp(void); extern void espradio_run_task(void *task_func, void *param); extern uint64_t espradio_time_us_now(void); extern void espradio_task_yield_go(void); +extern void espradio_pump_sched_once(void); extern void espradio_hal_init_clocks_go(void); extern void espradio_hal_disable_clocks_go(void); extern void espradio_hal_wifi_rtc_enable_iso_go(void); diff --git a/examples/apwebserver/apwebserver.go b/examples/apwebserver/apwebserver.go index 2b377aa..21842c7 100644 --- a/examples/apwebserver/apwebserver.go +++ b/examples/apwebserver/apwebserver.go @@ -64,6 +64,16 @@ func main() { http.Handle("/off", logRequest(LED_OFF)) http.Handle("/on", logRequest(LED_ON)) + // Driver counters, printed while traffic is flowing. Most of these count + // something being dropped, so a non-zero value is the only evidence it + // happened. + go func() { + for { + time.Sleep(10 * time.Second) + espradio.DebugStats().Print() + } + }() + println("HTTP server listening on http://" + apIP + port) err = http.ListenAndServe(apIP+port, nil) if err != nil { diff --git a/examples/scan/main.go b/examples/scan/main.go index 8ca2a8b..65a3924 100644 --- a/examples/scan/main.go +++ b/examples/scan/main.go @@ -39,6 +39,10 @@ func main() { for _, ap := range aps { println("AP:", ap.SSID, "RSSI", ap.RSSI) } + + // Driver counters. Most of these count something being dropped, so a + // non-zero value is the only evidence it happened. + espradio.DebugStats().Print() println() time.Sleep(10 * time.Second) diff --git a/examples/webserver/webserver.go b/examples/webserver/webserver.go index 8962445..7abfd53 100644 --- a/examples/webserver/webserver.go +++ b/examples/webserver/webserver.go @@ -13,6 +13,7 @@ import ( "tinygo.org/x/drivers/netdev" nl "tinygo.org/x/drivers/netlink" + "tinygo.org/x/espradio" link "tinygo.org/x/espradio/netlink" ) @@ -51,6 +52,16 @@ func main() { http.Handle("/off", logRequest(LED_OFF)) http.Handle("/on", logRequest(LED_ON)) + // Driver counters, printed while traffic is flowing. Most of these count + // something being dropped, so a non-zero value is the only evidence it + // happened. + go func() { + for { + time.Sleep(10 * time.Second) + espradio.DebugStats().Print() + } + }() + h, _ := link.Addr() host := h.String() println("HTTP server listening on http://" + host + port) diff --git a/isr.c b/isr.c index 9127c8a..e8d953d 100644 --- a/isr.c +++ b/isr.c @@ -87,6 +87,24 @@ void espradio_user_exception(uint32_t cause, uint32_t epc, uint32_t excvaddr, ui static void (*s_isr_fn[32])(void *) WIFIBSS; static void *s_isr_arg[32] WIFIBSS; +/* Zero the handler tables before anything can register into them. + * + * On ESP32 these live in .wifibss, a custom DRAM1 section, and the runtime zeroes + * .bss only -- so they start as whatever was in that RAM. Measured: the installed + * bitmask read 0xffffffff on ESP32 against 1 on the S3, i.e. all 32 entries looked + * like valid handlers. That makes the "if (s_isr_fn[i])" guard in + * espradio_call_wifi_isr() useless there: any slot marked in s_wifi_isr_slots + * without a matching espradio_set_isr would be called through a garbage pointer. + * + * Nothing hits that today because only slot 0 is ever marked and it is always + * written first, so this is a latch on a trap rather than a fix for a live fault. */ +void espradio_isr_tables_init(void) { + for (int i = 0; i < 32; i++) { + s_isr_fn[i] = NULL; + s_isr_arg[i] = NULL; + } +} + /* Bitmask of ISR slots registered via espradio_set_intr (WiFi sources only). */ static uint32_t s_wifi_isr_slots; @@ -96,6 +114,34 @@ void espradio_mark_wifi_isr_slot(int32_t n) { } } +/* Which slots the blob registered. The prewiring points several peripheral + * sources at one CPU interrupt line, so if the blob registers fewer handlers than + * there are routed sources, the unhandled ones can assert with nothing to ack + * them -- and the line is level-triggered. */ +uint32_t espradio_wifi_isr_slots(void) { return s_wifi_isr_slots; } + +/* Blob ISR handler invocations, summed across slots. Compared against the + * scheduler pass count this says whether the handlers are running at all. */ +static volatile uint32_t s_wifi_isr_handler_calls; + +uint32_t espradio_wifi_isr_handler_calls(void) { return s_wifi_isr_handler_calls; } + +/* Which slots actually hold a handler. + * + * This is deliberately a different question from espradio_wifi_isr_slots(): + * handlers arrive via espradio_set_isr (the blob's ets_isr_attach), which writes + * s_isr_fn[] and nothing else, whereas the slots mask is written only by + * espradio_set_intr. espradio_call_wifi_isr() iterates the slots mask, so a + * handler installed at a slot the mask does not cover is never called -- and + * whatever source it belongs to is therefore never acked. */ +uint32_t espradio_wifi_isr_installed(void) { + uint32_t mask = 0; + for (int i = 0; i < 32; i++) { + if (s_isr_fn[i]) mask |= (1u << i); + } + return mask; +} + void espradio_set_isr(int32_t n, void *f, void *arg) { if (n >= 0 && n < 32) { s_isr_fn[n] = (void (*)(void *))f; @@ -103,9 +149,24 @@ void espradio_set_isr(int32_t n, void *f, void *arg) { } } -/* ---- ISR context flag ---- */ - +/* ---- ISR context flags ---- */ + +/* s_in_isr means "the blob's ISR body is running", which is what the blob's own + * _is_from_isr() is asking about: whether to use its from-ISR queue APIs. It is + * NOT the same question as "am I in hardware interrupt context", because on + * ESP32-S3 and ESP32 the blob ISR is invoked from the scheduler goroutine, not + * from a trap handler. + * + * s_in_hw_isr answers that second question, and only the per-target Go interrupt + * handlers set it. Anything that must not yield -- a spin that would otherwise + * call runtime.Gosched() -- has to test this one; testing s_in_isr would refuse + * to yield on S3/ESP32 in ordinary goroutine context and deadlock instead. */ static volatile uint32_t s_in_isr = 0; +static volatile uint32_t s_in_hw_isr = 0; + +void espradio_enter_hw_isr(void) { s_in_hw_isr++; } +void espradio_exit_hw_isr(void) { if (s_in_hw_isr) s_in_hw_isr--; } +bool espradio_in_hw_isr(void) { return s_in_hw_isr != 0; } __attribute__((weak)) void espradio_wifi_isr_post_mask(void) {} @@ -124,6 +185,7 @@ void espradio_call_wifi_isr(void) { int i = __builtin_ctz(slots); slots &= slots - 1; if (s_isr_fn[i]) { + s_wifi_isr_handler_calls++; s_isr_fn[i](s_isr_arg[i]); } } diff --git a/netif.c b/netif.c index 54b7972..9c8e153 100644 --- a/netif.c +++ b/netif.c @@ -80,9 +80,16 @@ typedef void (*wifi_tx_done_cb_t)(uint8_t ifidx, uint8_t *data, uint16_t *data_len, bool txStatus); extern esp_err_t esp_wifi_set_tx_done_cb(wifi_tx_done_cb_t cb); +/* The blob calls this once it is done with a transmitted frame, which is also + * when it releases the TX buffer. Latching it is what lets a future TX retry + * wait on evidence the blob ran, rather than on a capacity query that reads true + * immediately and proves nothing. */ +static volatile uint32_t s_tx_done_cb_count; + static void espradio_tx_done_noop(uint8_t ifidx, uint8_t *data, uint16_t *data_len, bool txStatus) { (void)ifidx; (void)data; (void)data_len; (void)txStatus; + s_tx_done_cb_count++; } static void espradio_patch_blob_cb_vars(void) { @@ -176,32 +183,98 @@ void espradio_post_start_cb(void) { #endif /* !CONFIG_IDF_TARGET_ESP32 */ } -/* Snapshot the critical ROM pointers after the blob has fully initialised - * them (pp_attach sets pTxRx, lmacInit sets lmacConfMib_ptr, etc.). - * Called from Go after pumping schedOnce enough times for ppTask to - * process the START command. */ +/* ROM pointer snapshot / restore. + * + * These five pointers live at fixed addresses the blob sets during START + * processing (pp_attach sets pTxRx, lmacInit sets lmacConfMib_ptr, ...) and that + * WiFi DMA can corrupt afterwards, so they are snapshotted once and rewritten on + * every scheduler pass and before every TX. + * + * The snapshot used to be unconditional, taken after a fixed number of scheduler + * passes on the assumption that the blob was done by then. Measured on hardware, + * it is not: on ESP32-C3 and ESP32-S3 at least one pointer is still NULL after + * all 40 passes (ESP32 has them after one). The snapshot then captured that NULL + * and the restore faithfully wrote it back over whatever the blob had since set, + * tens of thousands of times a second. + * + * So each pointer is now latched independently, and only once it is non-NULL. + * NULL is never captured and never restored. That makes the pump length a + * performance question rather than a correctness one: a short pump just means a + * pointer gets latched by a later call instead of the first. s_rom_ptrs_valid + * records which have been latched, so "which pointer is late" is answerable + * rather than inferred. */ +#define ROM_PTR_TXRX (1u << 0) +#define ROM_PTR_TX_EB (1u << 1) +#define ROM_PTR_WAIT_EB (1u << 2) +#define ROM_PTR_LMAC_MIB (1u << 3) +#define ROM_PTR_OSI_FUNCS (1u << 4) +#define ROM_PTR_ALL (ROM_PTR_TXRX | ROM_PTR_TX_EB | ROM_PTR_WAIT_EB | \ + ROM_PTR_LMAC_MIB | ROM_PTR_OSI_FUNCS) + +static volatile uint32_t s_rom_ptrs_valid; + +/* True once every pointer has been latched. */ +int espradio_rom_ptrs_ready(void) { + return (s_rom_ptrs_valid & ROM_PTR_ALL) == ROM_PTR_ALL; +} + +/* Bitmask of pointers still not latched, using the ROM_PTR_* bits above. Zero + * means all are latched. */ +uint32_t espradio_rom_ptrs_missing(void) { + return (~s_rom_ptrs_valid) & ROM_PTR_ALL; +} + +/* Counts calls that could not latch everything, i.e. the blob had not finished. */ +static volatile uint32_t s_rom_ptrs_saved_unready; + +uint32_t espradio_rom_ptrs_saved_unready(void) { return s_rom_ptrs_saved_unready; } + +/* Latch one pointer if it is non-NULL and not already latched. */ +static void rom_ptr_latch(uint32_t *slot, uint32_t bit, uint32_t current) { + if (s_rom_ptrs_valid & bit) return; + if (current == 0) return; + *slot = current; + s_rom_ptrs_valid |= bit; +} + +/* Safe to call repeatedly: each pointer latches the first time it is valid. */ void espradio_save_rom_ptrs(void) { - s_saved_pTxRx = (uint32_t)(uintptr_t)pTxRx; - s_saved_our_tx_eb = (uint32_t)(uintptr_t)our_tx_eb; - s_saved_our_wait_eb = (uint32_t)(uintptr_t)our_wait_eb; - s_saved_lmacConfMib_ptr = (uint32_t)(uintptr_t)lmacConfMib_ptr; - s_saved_g_osi_funcs_p = (uint32_t)(uintptr_t)g_osi_funcs_p; - s_rom_ptrs_saved = 1; + rom_ptr_latch(&s_saved_pTxRx, ROM_PTR_TXRX, + (uint32_t)(uintptr_t)pTxRx); + rom_ptr_latch(&s_saved_our_tx_eb, ROM_PTR_TX_EB, + (uint32_t)(uintptr_t)our_tx_eb); + rom_ptr_latch(&s_saved_our_wait_eb, ROM_PTR_WAIT_EB, + (uint32_t)(uintptr_t)our_wait_eb); + rom_ptr_latch(&s_saved_lmacConfMib_ptr, ROM_PTR_LMAC_MIB, + (uint32_t)(uintptr_t)lmacConfMib_ptr); + rom_ptr_latch(&s_saved_g_osi_funcs_p, ROM_PTR_OSI_FUNCS, + (uint32_t)(uintptr_t)g_osi_funcs_p); + + if (!espradio_rom_ptrs_ready()) s_rom_ptrs_saved_unready++; + if (s_rom_ptrs_valid) s_rom_ptrs_saved = 1; } /* Restore the ROM pointers from snapshot. Called from schedOnce (Go side) - * and before every TX to undo any DMA corruption in the ROM data area. */ + * and before every TX to undo any DMA corruption in the ROM data area. + * + * Only latched pointers are restored, so a pointer the blob has not set yet is + * left alone rather than being pinned to NULL. */ void espradio_restore_rom_ptrs(void) { if (!s_rom_ptrs_saved) return; - if ((uint32_t)(uintptr_t)pTxRx != s_saved_pTxRx) + if ((s_rom_ptrs_valid & ROM_PTR_TXRX) && + (uint32_t)(uintptr_t)pTxRx != s_saved_pTxRx) pTxRx = (volatile uint32_t *)(uintptr_t)s_saved_pTxRx; - if ((uint32_t)(uintptr_t)our_tx_eb != s_saved_our_tx_eb) + if ((s_rom_ptrs_valid & ROM_PTR_TX_EB) && + (uint32_t)(uintptr_t)our_tx_eb != s_saved_our_tx_eb) our_tx_eb = (volatile uint32_t *)(uintptr_t)s_saved_our_tx_eb; - if ((uint32_t)(uintptr_t)our_wait_eb != s_saved_our_wait_eb) + if ((s_rom_ptrs_valid & ROM_PTR_WAIT_EB) && + (uint32_t)(uintptr_t)our_wait_eb != s_saved_our_wait_eb) our_wait_eb = (volatile uint32_t *)(uintptr_t)s_saved_our_wait_eb; - if ((uint32_t)(uintptr_t)lmacConfMib_ptr != s_saved_lmacConfMib_ptr) + if ((s_rom_ptrs_valid & ROM_PTR_LMAC_MIB) && + (uint32_t)(uintptr_t)lmacConfMib_ptr != s_saved_lmacConfMib_ptr) lmacConfMib_ptr = (volatile uint32_t *)(uintptr_t)s_saved_lmacConfMib_ptr; - if ((uint32_t)(uintptr_t)g_osi_funcs_p != s_saved_g_osi_funcs_p) + if ((s_rom_ptrs_valid & ROM_PTR_OSI_FUNCS) && + (uint32_t)(uintptr_t)g_osi_funcs_p != s_saved_g_osi_funcs_p) g_osi_funcs_p = (wifi_osi_funcs_t *)(uintptr_t)s_saved_g_osi_funcs_p; /* esp_phy_enable resets g_phyFuns to the fixed DRAM address on every call. * Redirect it back to our static copy (C3/S3 only). */ @@ -233,6 +306,17 @@ static volatile uint32_t s_rx_tail; static volatile uint32_t s_rx_cb_count; static volatile uint32_t s_rx_cb_drop; +/* Producer side of the RX ring. On ESP32-C3 this runs in real interrupt context + * (the hardware handler calls the blob ISR directly), so the head is published + * only after a barrier -- the same discipline as the ISR ring in isr.c, which the + * original code here was missing. + * + * The two counters stay plain increments and are therefore APPROXIMATE: RV32IMC + * has no atomic extension, so making them exact would mean a critical section per + * received frame. They are diagnostics; an occasional lost increment when the + * consumer is interrupted mid-read-modify-write is an acceptable trade for not + * touching the interrupt mask on every RX. The ring indices, which must be + * exact, are single-writer on each side and need no read-modify-write. */ static esp_err_t espradio_sta_rxcb(void *buffer, uint16_t len, void *eb) { s_rx_cb_count++; uint32_t next = (s_rx_head + 1) % ESPRADIO_NETIF_RXRING_SIZE; @@ -245,6 +329,8 @@ static esp_err_t espradio_sta_rxcb(void *buffer, uint16_t len, void *eb) { if (copy_len > ESPRADIO_NETIF_FRAME_MAX) copy_len = ESPRADIO_NETIF_FRAME_MAX; memcpy(s_rx_ring[s_rx_head].data, buffer, copy_len); s_rx_ring[s_rx_head].len = copy_len; + /* Frame and length must be visible before the consumer can see the slot. */ + ESPRADIO_MEMORY_BARRIER(); s_rx_head = next; esp_wifi_internal_free_rx_buffer(eb); return 0; @@ -259,8 +345,11 @@ void espradio_netif_set_connected(int connected) { esp_err_t espradio_netif_start_rx(int ap_mode) { s_active_if = ap_mode ? WIFI_IF_AP : WIFI_IF_STA; - s_rx_head = 0; - s_rx_tail = 0; + /* Do NOT reset head/tail here. The rxcb is registered at init + * (espradio_netif_init_netstack_cb) and may already be filling the ring, in + * ISR context on the C3; zeroing both indices underneath a live producer + * either loses queued frames or resurrects stale ones. Draining the ring is + * the consumer's job and it is already safe to start mid-stream. */ return esp_wifi_internal_reg_rxcb(s_active_if, espradio_sta_rxcb); } @@ -268,19 +357,134 @@ int espradio_netif_rx_available(void) { return s_rx_head != s_rx_tail; } +/* Frames dropped because they did not fit the caller's buffer. */ +static volatile uint32_t s_rx_oversize; + +uint32_t espradio_netif_rx_oversize(void) { return s_rx_oversize; } + uint16_t espradio_netif_rx_pop(void *dst, uint16_t dst_len) { if (s_rx_head == s_rx_tail) return 0; + /* Pair with the producer's publish barrier before reading the slot. */ + ESPRADIO_MEMORY_BARRIER(); uint16_t len = s_rx_ring[s_rx_tail].len; - if (len > dst_len) len = dst_len; + + /* Drop the whole frame rather than truncating it. The ring holds up to + * ESPRADIO_NETIF_FRAME_MAX (1600) while the usual consumer buffer is 1522, so + * truncation is reachable -- and a short frame is not a smaller version of the + * original, it is a corrupt one that the upper stack will mis-parse. + * TestVHCIRingOverflowTruncatesPacket documented this same bug class for the + * VHCI ring and named this as the fix. Consuming the slot is deliberate: the + * frame will never fit, so leaving it would wedge the ring. */ + if (len > dst_len) { + s_rx_oversize++; + ESPRADIO_MEMORY_BARRIER(); + s_rx_tail = (s_rx_tail + 1) % ESPRADIO_NETIF_RXRING_SIZE; + return 0; + } + memcpy(dst, s_rx_ring[s_rx_tail].data, len); + ESPRADIO_MEMORY_BARRIER(); s_rx_tail = (s_rx_tail + 1) % ESPRADIO_NETIF_RXRING_SIZE; return len; } +/* TX accounting. A failed esp_wifi_internal_tx is a lost frame: the caller has + * already dequeued it from the upper stack's egress buffer, so there is nothing + * left to retry with. ESP_ERR_NO_MEM (blob TX buffers exhausted) is counted + * separately from the rest because it is the recoverable case. */ +static volatile uint32_t s_tx_attempts; +static volatile uint32_t s_tx_fail_nomem; +static volatile uint32_t s_tx_fail_other; +static volatile uint32_t s_tx_not_connected; + +/* Retry budget for a NO_MEM rejection. Bounded for the same reason bt_pump_hci + * is: the signal we wait on is only promised on a transition, so an unbounded + * wait can hang. Small, because the caller is on the data path. */ +#define ESPRADIO_TX_RETRIES 4 +#define ESPRADIO_TX_PUMP_PASSES 4 + +static volatile uint32_t s_tx_retries; +static volatile uint32_t s_tx_busy_waits; +static volatile int s_tx_busy; + +/* Hand one frame to the blob, and do not give up on the first NO_MEM. + * + * Modelled on espradio_vhci_write, which had to learn the same four things: + * + * - A rejection is not final. NO_MEM means the blob's TX buffers are all in + * flight; it releases one when it finishes a frame, and it only does that if + * it gets to run. The caller cannot retry for us -- by the time it sees the + * error the frame has already been dequeued from the upper stack's egress + * buffer and is gone -- so the retry has to happen here. + * + * - Pump, do not merely yield. Reaching the blob's TX completion path takes a + * scheduler pass, which is what espradio_pump_sched_once does. + * + * - Wait on evidence the blob ran, not on a capacity query. s_tx_done_cb_count + * is bumped by the blob's TX-done callback, which fires when it releases a + * buffer. Note this is NOT an acknowledgement of our frame: measured, it + * fires about three times more often than our own TX calls, because the blob + * transmits management frames we never handed it. "A buffer was freed" is + * exactly the signal a NO_MEM retry needs, though, so that is fine -- what it + * must not be used for is confirming delivery. + * + * - Serialise writers. The pump yields, so without a gate a second sender + * could enter and interleave with this one. */ int espradio_netif_tx(void *buf, uint16_t len) { - if (s_active_if == WIFI_IF_STA && !s_sta_connected) return ESP_ERR_WIFI_NOT_CONNECT; + if (s_active_if == WIFI_IF_STA && !s_sta_connected) { + s_tx_not_connected++; + return ESP_ERR_WIFI_NOT_CONNECT; + } + + while (s_tx_busy) { + s_tx_busy_waits++; + espradio_task_yield_go(); + } + s_tx_busy = 1; + espradio_restore_rom_ptrs(); - return esp_wifi_internal_tx(s_active_if, buf, len); + s_tx_attempts++; + + int ret = esp_wifi_internal_tx(s_active_if, buf, len); + for (int i = 0; ret == ESP_ERR_NO_MEM && i < ESPRADIO_TX_RETRIES; i++) { + uint32_t seen = s_tx_done_cb_count; + s_tx_retries++; + + /* Drive the blob until it reports releasing a buffer, bounded within the + * retry as well: the callback is only promised on a transition, so a + * buffer may come free without it and a hard wait would stall. */ + for (int p = 0; p < ESPRADIO_TX_PUMP_PASSES; p++) { + espradio_pump_sched_once(); + if (s_tx_done_cb_count != seen) break; + } + + espradio_restore_rom_ptrs(); + ret = esp_wifi_internal_tx(s_active_if, buf, len); + } + + if (ret != ESP_OK) { + if (ret == ESP_ERR_NO_MEM) { + s_tx_fail_nomem++; + } else { + s_tx_fail_other++; + } + } + + s_tx_busy = 0; + return ret; +} + +void espradio_netif_tx_stats(uint32_t *attempts, uint32_t *fail_nomem, + uint32_t *fail_other, uint32_t *not_connected, + uint32_t *tx_done, uint32_t *retries, + uint32_t *busy_waits) { + if (attempts) *attempts = s_tx_attempts; + if (fail_nomem) *fail_nomem = s_tx_fail_nomem; + if (fail_other) *fail_other = s_tx_fail_other; + if (not_connected) *not_connected = s_tx_not_connected; + if (tx_done) *tx_done = s_tx_done_cb_count; + if (retries) *retries = s_tx_retries; + if (busy_waits) *busy_waits = s_tx_busy_waits; } esp_err_t espradio_netif_get_mac(uint8_t mac[6]) { diff --git a/netif_esp.go b/netif_esp.go index 8135083..f1a2e3f 100644 --- a/netif_esp.go +++ b/netif_esp.go @@ -8,6 +8,7 @@ import "C" import ( "net" + "sync/atomic" "unsafe" ) @@ -67,14 +68,31 @@ func (nd *NetDev) EthPoll(buf []byte) (int, error) { } n := C.espradio_netif_rx_pop(unsafe.Pointer(&buf[0]), C.uint16_t(len(buf))) if n == 0 { + // Either the ring was empty, or the frame did not fit and was dropped + // whole rather than truncated. Both mean "no frame for this caller"; + // the drop is counted in DebugStats as RxOversize. return 0, nil } if nd.rxHandler != nil { - nd.rxHandler(buf[:n]) + // Count rather than propagate. The handler is the upper stack's ingress + // path, and it returns an error for any frame the stack does not handle -- + // IPv6, STP, stray broadcast -- which is ordinary traffic for a netdev, not + // a device failure. Returning it here would report EthPoll as failing on a + // call where it successfully delivered a frame. + // + // The original defect was that these were invisible, not that they were + // unpropagated; DebugStats().RxIngressErrors fixes that without giving + // normal traffic an error path. + if err := nd.rxHandler(buf[:n]); err != nil { + atomic.AddUint32(&rxIngressErrors, 1) + } } return int(n), nil } +// rxIngressErrors counts frames the upper stack declined to handle. +var rxIngressErrors uint32 + // HardwareAddr6 returns the 6-byte MAC address of the WiFi interface. func (nd *NetDev) HardwareAddr6() (mac [6]byte, _ error) { code := C.espradio_netif_get_mac((*C.uint8_t)(unsafe.Pointer(&mac[0]))) diff --git a/netlink/netlink.go b/netlink/netlink.go index 1fb4d2f..90f9736 100644 --- a/netlink/netlink.go +++ b/netlink/netlink.go @@ -307,7 +307,16 @@ func (n *Esplink) SetSockOpt(sockfd int, level int, opt int, value interface{}) func handleStack(stack *espradio.Stack) { for { - send, recv, _ := stack.RecvAndSend() + send, recv, err := stack.RecvAndSend() + if err != nil && debug { + // A TX failure here is already unrecoverable: EgressEthernet dequeued + // the frame before the send was attempted, so there is nothing left to + // retry with. The retry that can still help runs inside + // espradio_netif_tx, against the blob's TX-done signal. With debug + // off, DebugStats is the record: TxFailNoMem, TxFailOther, + // TxNotConnected. + println("handleStack: RecvAndSend:", err.Error()) + } if send == 0 && recv == 0 { time.Sleep(pollTime) } diff --git a/osi.c b/osi.c index da7f6fc..a8e4e82 100644 --- a/osi.c +++ b/osi.c @@ -156,8 +156,30 @@ typedef struct espradio_queue { static espradio_queue_t *s_queues_head; static int s_queues_lock; +/* These spins must yield. + * + * There is one core and no preemption, so if the holder is another goroutine a + * bare spin never terminates -- the holder can only run if we give it the CPU. + * event_lock() below already does this; these two did not, which is the bug. + * + * Yielding here is safe precisely because these are our own locks around our own + * queue bookkeeping. It would NOT be safe inside a region the blob treats as a + * critical section: yielding out of one of those is what let two contexts + * re-enter the BLE controller's rw_schedule() and deliver a single ACL packet to + * the host twice, permanently desynchronising the ATT request/response stream. + * The distinction is whose invariant the lock protects, not the lock's shape. + * + * In real interrupt context there is no goroutine to yield from, so spin instead. + * That case tests espradio_in_hw_isr() rather than the blob-facing _is_from_isr, + * which is also true when the blob's ISR body runs on the scheduler goroutine. */ +static void spin_yield(void) { + if (espradio_in_hw_isr()) return; + espradio_task_yield_go(); +} + static void queue_list_lock(void) { while (__sync_lock_test_and_set(&s_queues_lock, 1)) { + spin_yield(); } } @@ -167,6 +189,7 @@ static void queue_list_unlock(void) { static void queue_lock(espradio_queue_t *q) { while (__sync_lock_test_and_set(&q->lock, 1)) { + spin_yield(); } } @@ -281,6 +304,13 @@ static void espradio_queue_delete(void *queue) { espradio_generic_queue_delete(queue); } +/* Counts sends rejected because the destination queue was full. block_time_tick + * is ignored, so a blob "blocking" send never blocks and the item is simply + * lost; this counter is the only evidence that happened. */ +static volatile uint32_t s_queue_send_full; + +uint32_t espradio_queue_send_full_count(void) { return s_queue_send_full; } + int32_t espradio_queue_send(void *queue, void *item, uint32_t block_time_tick) { (void)block_time_tick; espradio_queue_t *q = queue_resolve(queue); @@ -288,6 +318,7 @@ int32_t espradio_queue_send(void *queue, void *item, uint32_t block_time_tick) { queue_lock(q); if (q->count == q->len) { queue_unlock(q); + s_queue_send_full++; return 0; } memcpy(q->storage + ((size_t)q->write * q->item_size), item, q->item_size); @@ -435,7 +466,10 @@ void *espradio_arena_calloc(size_t n, size_t size); void *espradio_arena_realloc(void *ptr, size_t new_size); void espradio_arena_free(void *p); -static void *espradio_malloc(size_t size) { +/* Non-static so bt_ble.c can route BLE allocations through the same counters. + * The BT controller draws from the same arena as WiFi, so allocations that + * bypass these wrappers are invisible to espradio_alloc_stats(). */ +void *espradio_malloc(size_t size) { #if ESPRADIO_OSI_DEBUG printf("osi: malloc %zu\n", size); #endif @@ -443,7 +477,7 @@ static void *espradio_malloc(size_t size) { return espradio_arena_alloc(size); } -static void espradio_free(void *p) { +void espradio_free(void *p) { #if ESPRADIO_OSI_DEBUG printf("osi: free %p\n", (void *)p); #endif @@ -537,8 +571,11 @@ esp_err_t esp_event_handler_register(esp_event_base_t event_base, int32_t event_ return 0; } -void espradio_event_loop_run_once(void) { - if (!s_event_loop_ready) return; +/* Returns 1 if an event was dispatched, 0 if the queue was empty. The caller + * (schedOnce) needs this to tell "drained" from "still has work" -- without it a + * fixed-count drain loop cannot know whether it ran out of passes. */ +int espradio_event_loop_run_once(void) { + if (!s_event_loop_ready) return 0; #if ESPRADIO_OSI_DEBUG static uint32_t s_event_loop_idle_log_throttle = 0; if ((s_event_loop_idle_log_throttle & 0x1ffu) == 0) { @@ -555,7 +592,7 @@ void espradio_event_loop_run_once(void) { } s_event_loop_idle_log_throttle++; #endif - return; + return 0; } s_event_head = e->next; if (!s_event_head) s_event_tail = NULL; @@ -582,6 +619,7 @@ void espradio_event_loop_run_once(void) { espradio_arena_free(e->base); espradio_arena_free(e->data); espradio_arena_free(e); + return 1; } extern void espradio_on_wifi_event(int32_t event_id, void *data); diff --git a/radio.go b/radio.go index 51212e1..345dc2d 100644 --- a/radio.go +++ b/radio.go @@ -14,6 +14,7 @@ package espradio import "C" import ( "bytes" + "errors" "runtime" "runtime/interrupt" "sync" @@ -98,6 +99,7 @@ var isrKick chan struct{} func startSchedTicker() { isrKick = make(chan struct{}, 1) + schedPassesStart = time.Now() go func() { ticker := time.NewTicker(schedTickerMs * time.Millisecond) defer ticker.Stop() @@ -114,7 +116,138 @@ func startSchedTicker() { var wifiInitDone uint32 -func schedOnce() { +// ─── Scheduler policy (runtime-switchable, for A/B on hardware) ────────────── + +// SchedPolicy selects behaviour inside schedOnce that is worth measuring on +// real hardware rather than reasoning about. Modelled on the BLE side's +// espradio_bt_set_sched_tick_mask, which is what made the scheduler-contention +// theory in the BLE work falsifiable. +type SchedPolicy uint32 + +const ( + // SchedPollWiFiISR polls the blob's WiFi ISR from the scheduler tick. + // + // On ESP32-S3 and ESP32 this is required: their hardware handler only + // masks and kicks, so the tick is the only thing that runs the blob ISR. + // On ESP32-C3 the real interrupt handler already runs it, so the poll + // makes it run twice per event. BLE refuses to poll its ISR at all + // because doing so without a hardware event corrupts the link-layer state + // (see the note in schedOnce), and whether the WiFi blob tolerates it is a + // property of that blob, not a general rule -- so it is switchable and + // meant to be measured, not removed on argument. + SchedPollWiFiISR SchedPolicy = 1 << iota +) + +// schedPolicy defaults to polling the WiFi ISR with fixed-count drains, which is +// the behaviour that predates this switch. +var schedPolicy = uint32(SchedPollWiFiISR) + +// SetSchedPolicy replaces the scheduler policy mask. Intended for bisecting +// behaviour on hardware; the default is the historical behaviour. +func SetSchedPolicy(p SchedPolicy) { atomic.StoreUint32(&schedPolicy, uint32(p)) } + +// GetSchedPolicy returns the current scheduler policy mask. +func GetSchedPolicy() SchedPolicy { return SchedPolicy(atomic.LoadUint32(&schedPolicy)) } + +func schedPolicyHas(p SchedPolicy) bool { + return atomic.LoadUint32(&schedPolicy)&uint32(p) != 0 +} + +// ─── Scheduler counters ────────────────────────────────────────────────────── + +// Drain caps. Measured: the cap-hit counters below stay at zero, so four passes +// per source is always enough and no work is being left behind. A +// drain-until-idle mode was tried and removed -- there was nothing for it to +// drain, and a longer pass costs interrupt-masked time. The counters stay as +// regression detectors. +const ( + drainCap = 4 + timerFirePerRound = 8 +) + +// Bounds for the two bring-up pumps. These are ceilings on a wait for a real +// predicate, not settle times: the pumps exit as soon as the blob has set the ROM +// pointers. They stay bounded because at least one pointer is measurably never +// set at this stage on the C3 and S3, so an unbounded wait would hang there. +const ( + postStartMaxPasses = 40 + connectSettleMaxPasses = 20 +) + +// readyNeverSentinel distinguishes "the pump ran and the predicate never became +// true" from "the pump never ran at all", which a plain zero conflates -- neither +// scan nor apwebserver calls Connect, so its counter reads zero for the second +// reason while postWiFiStart's reads zero for the first. +const readyNeverSentinel = 0xffff + +var ( + // schedReentries counts schedOnce calls that found another pass already in + // progress and returned without doing anything. + // + // Measured on hardware: this stays at zero. The ticker goroutine cannot + // re-enter itself, because a yield from blob code inside a pass resumes that + // goroutine mid-pass rather than at the top of its loop. The only overlap + // available is the main goroutine's pumpSched during bring-up racing the + // ticker, and that window is evidently never hit. + // + // The guard is kept as a safety net rather than as a fix for an observed + // problem: if the two ever did overlap, the inner pass's + // espradio_wifi_unmask() would re-enable the WiFi interrupt while the outer + // pass was still iterating the blob's ISR handlers. Cost is two atomics per + // pass. + schedReentries uint32 + schedInProgress uint32 + + // Drain loops that used their whole budget, i.e. left work behind. + schedEventCapHits uint32 + schedTimerCapHits uint32 + schedESPTimerCapHits uint32 + + // ISR-ring items discarded because the destination blob queue was full. + // The drain advances the ring tail regardless of the send result, so + // without this the loss is invisible. + schedISRRingSendFail uint32 + + // safeGosched calls that returned without yielding because interrupts were + // off. Every spin loop that calls safeGosched turns into a busy spin when + // this happens, so a non-zero value here explains a hang. + yieldSuppressed uint32 + + // Which scheduler pass each bring-up pump needed before the blob had set the + // ROM pointers, or readyNeverSentinel if it never did. + startReadyAfterPass uint32 + connectReadyAfterPass uint32 + + // schedPasses counts completed schedOnce passes. The tick is nominally + // 5 ms / 200 Hz, but every espradio_task_yield_go calls kickSched, so the + // ticker is woken far more often than that -- the ISR counter's growth implies + // tens of thousands of passes per second. This measures it directly instead + // of inferring it: DebugStats divides by elapsed time. + // + // The same feedback loop was found and throttled on the BLE side, where waking + // the controller task fed back into kickSched and collapsed the 5 ms tick to + // ~30 us. Nothing throttles the WiFi side. + schedPasses uint32 +) + +// schedPassesStart is when pass counting began, for the rate calculation. +var schedPassesStart time.Time + +// schedOnce runs one scheduler pass. It reports false if another pass was +// already in flight and this call did nothing, so a caller pumping in a loop can +// yield to the holder instead of spinning through no-ops. +func schedOnce() bool { + // Bail out rather than nesting a second pass. + // + // The alternative -- counting nesting and unmasking only at zero -- would + // still run the blob's ISR handlers and queue drains re-entrantly, which is + // what corrupts blob state. Skipping is safe: the outer pass is already + // doing this work. + if !atomic.CompareAndSwapUint32(&schedInProgress, 0, 1) { + atomic.AddUint32(&schedReentries, 1) + return false + } + // Snapshot INTENABLE before any blob code runs so that wifi_unmask can // restore TinyGo-owned bits (e.g. GPIO at bit 10 on ESP32-S3) that the // blob may clear via ROM calls (ets_isr_mask) bypassing the OS adapter. @@ -134,7 +267,7 @@ func schedOnce() { // Poll WiFi ISR: work around missing hardware interrupt on ESP32-S3. // Only poll after init is complete (blob ISR not registered until then). - if atomic.LoadUint32(&wifiInitDone) != 0 { + if atomic.LoadUint32(&wifiInitDone) != 0 && schedPolicyHas(SchedPollWiFiISR) { C.espradio_call_wifi_isr() } @@ -152,31 +285,85 @@ func schedOnce() { idx := C.espradio_isr_ring_tail() q := C.espradio_isr_ring_entry_queue(idx) itemPtr := C.espradio_isr_ring_entry_item(idx) - C.espradio_queue_send(q, itemPtr, 0) + // The tail advances either way, as it always has: a full destination + // queue means the item is gone. Count it so the loss is visible. + if C.espradio_queue_send(q, itemPtr, 0) == 0 { + atomic.AddUint32(&schedISRRingSendFail, 1) + } C.espradio_isr_ring_advance_tail() } - for i := 0; i < 4; i++ { - C.espradio_event_loop_run_once() + // Drain the three work sources. Each loop exits early when its source + // reports nothing left; using the whole budget means work was left behind, + // which is what the cap-hit counters record. + // + // espradio_event_loop_run_once returns 1 when it dispatched an event. + // Without that return value this loop could not tell "drained" from "out of + // passes", and it previously ran the full count unconditionally. + n := 0 + for ; n < drainCap; n++ { + if C.espradio_event_loop_run_once() == 0 { + break + } + } + if n == drainCap { + atomic.AddUint32(&schedEventCapHits, 1) } - for i := 0; i < 4; i++ { - if C.espradio_timer_poll_due(8) == 0 { + + n = 0 + for ; n < drainCap; n++ { + if C.espradio_timer_poll_due(timerFirePerRound) == 0 { break } } - for i := 0; i < 4; i++ { - if C.espradio_esp_timer_poll_due(8) == 0 { + if n == drainCap { + atomic.AddUint32(&schedTimerCapHits, 1) + } + + n = 0 + for ; n < drainCap; n++ { + if C.espradio_esp_timer_poll_due(timerFirePerRound) == 0 { break } } + if n == drainCap { + atomic.AddUint32(&schedESPTimerCapHits, 1) + } // Restore critical ROM pointer variables that WiFi DMA may have // corrupted (pTxRx, our_tx_eb, our_wait_eb, lmacConfMib_ptr). C.espradio_restore_rom_ptrs() C.espradio_wifi_unmask() + + atomic.AddUint32(&schedPasses, 1) + atomic.StoreUint32(&schedInProgress, 0) + return true +} + +// pumpSched runs one scheduler pass and yields. If the pass was skipped because +// the ticker goroutine held it, the yield is what lets that pass finish -- a bare +// loop over schedOnce would otherwise burn its whole budget on no-ops. +func pumpSched() { + if !schedOnce() { + runtime.Gosched() + } } +// espradio_pump_sched_once lets C run one scheduler pass. Used by the TX retry +// path in netif.c, which has to let the blob run in order to get a TX buffer back. +// +//export espradio_pump_sched_once +func espradio_pump_sched_once() { + pumpSched() +} + +// kickSched wakes the scheduler goroutine immediately. +// +// Use this only for a real hardware event, which must be serviced now. Every +// other caller should use kickSchedThrottled: the ticker is woken by the kick +// channel, so an unthrottled kick on a path the blob takes thousands of times a +// second replaces the 5 ms tick entirely. func kickSched() { select { case isrKick <- struct{}{}: @@ -184,6 +371,103 @@ func kickSched() { } } +// Kick throttling. +// +// The scheduler ticker selects on a 5 ms timer and the kick channel, so a kick is +// what actually determines how often it runs. espradio_task_yield_go kicks on +// every blob yield, and the blob yields on every queue-empty, semaphore-unavailable +// and lock-contended path -- measured, that drove 27,599 scheduler passes per +// second against a nominal 200. Each of those masks the WiFi interrupt, restores +// the ROM pointers twice, runs the blob ISR and three drain loops. +// +// The BLE side hit the same feedback loop from the other direction -- waking the +// controller task made its goroutine runnable, which kicked, which collapsed the +// tick to ~30 us -- and fixed it with a 1 kHz cap in bt_wake_task_throttled. This +// is the WiFi equivalent, and it keeps the same split: a real hardware event kicks +// unthrottled, because it must be serviced now; the cooperative-yield path is +// rate-limited, because it is a hint that work may be available, not a deadline. +// +// The throttle bounds added latency to kickThrottleUs, which is well inside the +// 5 ms the tick alone would impose. +// +// Scope, measured: this fixes the ESP32-C3, which went from 27,599 passes/second +// to ~1,200. It barely moves the ESP32-S3 (45,154) or the ESP32 (27,183), because +// on those targets the passes are not yield-driven at all -- their handler masks +// the interrupt and kicks, schedOnce runs the blob ISR and unmasks, and if the +// source is still asserting it re-fires at once. Their pass count tracks the ISR +// count almost exactly. That is a second, separate loop, and it is not addressed +// here: the kick that drives it is a real hardware event, so throttling it would +// mean dropping interrupts rather than coalescing hints. The C3 escapes it +// because its handler runs the blob ISR inline and so clears the source. +const defaultKickThrottleUs = 1000 + +var ( + // kickThrottleUs is the minimum interval between yield-driven kicks. Zero + // disables throttling, restoring the pre-Stage-3 behaviour for A/B. + kickThrottleUs = uint32(defaultKickThrottleUs) + + // lastKickUs is only touched from the throttled path, which never runs in + // hardware interrupt context (that path kicks unthrottled), so a plain 64-bit + // read-modify-write here cannot be interleaved by an ISR on this core. A lost + // update would only cost one extra or one missed kick anyway. + lastKickUs uint64 + + kicksSuppressed uint32 + kicksDelivered uint32 + + // hwWiFiISRCount counts entries to the Go WiFi interrupt handler, i.e. real + // hardware interrupts. + // + // This is deliberately separate from espradio_get_wifi_isr_count(), which + // counts espradio_call_wifi_isr() and therefore tracks scheduler passes on + // ESP32-S3 and ESP32 -- those targets invoke the blob ISR from the tick, not + // from the trap handler. Conflating the two is what made the Xtensa pass rate + // unattributable: the handler's own kickSched was uncounted, so 45k passes per + // second on an idle radio had no visible cause. + hwWiFiISRCount uint32 +) + +// countHWWiFiISR is called from each target's WiFi interrupt handler. +func countHWWiFiISR() { atomic.AddUint32(&hwWiFiISRCount, 1) } + +// SetKickThrottleUs sets the minimum interval in microseconds between +// yield-driven scheduler wakes. Zero disables the throttle. +// +// Intended for bisecting on hardware: 0 is the historical behaviour, 1000 the +// default, and larger values trade latency for fewer scheduler passes. +func SetKickThrottleUs(us uint32) { atomic.StoreUint32(&kickThrottleUs, us) } + +// KickThrottleUs returns the current yield-driven kick interval. +func KickThrottleUs() uint32 { return atomic.LoadUint32(&kickThrottleUs) } + +// Note on bring-up and the throttle: disabling the throttle for the duration of +// the bring-up pumps was tried, on the theory that rate-limiting the blob's wakes +// was what left our_tx_eb and our_wait_eb unlatched within the pump's bound. It +// was refuted -- savedunready and the missing-pointer mask came back bit-identical +// with the throttle off during the pump -- so that code is not here. Whatever +// determines when those two pointers appear, it is not the kick rate. + +// kickSchedThrottled wakes the scheduler unless it was woken too recently. +// +// In hardware interrupt context the throttle is bypassed: that is a real event, +// and it is also the one context where the timestamp must not be written. +func kickSchedThrottled() { + throttle := atomic.LoadUint32(&kickThrottleUs) + if throttle == 0 || C.espradio_in_hw_isr() { + atomic.AddUint32(&kicksDelivered, 1) + kickSched() + return + } + now := timeUsNow() + if now-lastKickUs < uint64(throttle) { + atomic.AddUint32(&kicksSuppressed, 1) + return + } + lastKickUs = now + atomic.AddUint32(&kicksDelivered, 1) + kickSched() +} + // arenaPool keeps the arena backing memory reachable from Go so the GC // won't collect it. The WiFi blob stores pointers into this pool in ROM // BSS (outside the GC's scan range), so individual malloc'd objects would @@ -197,17 +481,43 @@ func ArenaStats() (used, capacity uint32) { return uint32(u), uint32(c) } +// wifiEnabled guards Enable against a second call. Re-running it would +// re-initialise the arena under the blob's live pointers, start a second ticker +// goroutine and re-register the ISR. +var wifiEnabled uint32 + +// ErrAlreadyEnabled is returned by Enable when the radio is already enabled. +var ErrAlreadyEnabled = errors.New("espradio: radio already enabled") + // Enable and configure the radio for WiFi. +// +// Enable is not idempotent and returns ErrAlreadyEnabled on a second call. func Enable(config Config) error { - // Allocate arena pool from Go heap and hand it to C. - poolSize := arenaPoolSize - if config.ArenaPoolSize > 0 { - poolSize = config.ArenaPoolSize + if !atomic.CompareAndSwapUint32(&wifiEnabled, 0, 1) { + return ErrAlreadyEnabled + } + + // Before anything can register a handler: on ESP32 these tables sit in a + // custom section the runtime does not zero. + C.espradio_isr_tables_init() + + // Allocate the arena pool from the Go heap and hand it to C -- but only if + // nobody has already done so. espradio_arena_init re-lays the whole pool as + // one free block, so calling it when BLEInit got there first would reset the + // heap underneath the live BT controller. BLEInit already guards this the + // same way. + if arenaPool == nil { + poolSize := arenaPoolSize + if config.ArenaPoolSize > 0 { + poolSize = config.ArenaPoolSize + } + arenaPool = makeArenaPool(poolSize) + C.espradio_arena_init((*C.uint8_t)(unsafe.Pointer(&arenaPool[0])), C.size_t(len(arenaPool))) } - arenaPool = makeArenaPool(poolSize) - C.espradio_arena_init((*C.uint8_t)(unsafe.Pointer(&arenaPool[0])), C.size_t(len(arenaPool))) - startSchedTicker() + if isrKick == nil { + startSchedTicker() + } time.Sleep(schedTickerMs * time.Millisecond) initHardware() C.espradio_ensure_osi_ptr() @@ -281,9 +591,27 @@ func Start() error { // processes the START command and ROM pointer variables get initialised. func postWiFiStart() { C.esp_wifi_set_ps(C.WIFI_PS_NONE) - for i := 0; i < 40; i++ { - schedOnce() + + // Pump until the blob has set the ROM pointers, rather than for a fixed + // count and hoping. Bounded, because on the C3 and S3 at least one pointer + // is measurably never set at this stage -- so this must not become a wait + // that cannot finish. + // + // espradio_save_rom_ptrs latches each pointer independently the first time it + // is non-NULL, so calling it every pass is both safe and the point: whatever + // is ready gets captured now, and anything late gets captured by the next + // call rather than being pinned to NULL. + for i := 0; i < postStartMaxPasses; i++ { + pumpSched() runtime.Gosched() + C.espradio_save_rom_ptrs() + if C.espradio_rom_ptrs_ready() != 0 { + startReadyAfterPass = uint32(i + 1) + break + } + } + if startReadyAfterPass == 0 { + startReadyAfterPass = readyNeverSentinel } C.espradio_save_rom_ptrs() } @@ -293,13 +621,248 @@ func DebugISRCount() uint32 { return uint32(C.espradio_get_wifi_isr_count()) } +// Stats is a snapshot of the driver's internal counters. +// +// Most of these count something being silently discarded, so a non-zero value is +// the only evidence that it happened. A counter that stays zero is evidence +// too: it can refute the reason it was added, which is the point. +type Stats struct { + // Scheduler. + WiFiISRCount uint32 // blob WiFi ISR invocations + SchedReentries uint32 // schedOnce entered while another pass was in flight + EventCapHits uint32 // event-loop drain used its whole budget + TimerCapHits uint32 // ets_timer drain used its whole budget + ESPTimerCapHits uint32 // esp_timer drain used its whole budget + YieldsSuppressed uint32 // safeGosched returned without yielding + // IntsOffNesting is wifiIntsOff as of this read. Non-zero while the radio + // is idle means a blob critical section leaked. + IntsOffNesting uint32 + + // SchedPasses is completed schedOnce passes, and SchedPassesPerSec that count + // over elapsed time. The nominal rate is 200 Hz; anything far above means the + // kickSched path is driving the ticker rather than the 5 ms timer. + SchedPasses uint32 + SchedPassesPerSec uint32 + + // Yield-driven scheduler wakes delivered and suppressed by the throttle, and + // the interval in force. A large suppressed count against a modest + // SchedPassesPerSec is the throttle working. + KicksDelivered uint32 + KicksSuppressed uint32 + KickThrottleUs uint32 + + // HWISRCount is real hardware WiFi interrupts, and HWISRPerSec that over + // elapsed time. Distinct from WiFiISRCount, which counts invocations of the + // blob ISR and so tracks scheduler passes on S3 and ESP32. + // + // A rate near SchedPassesPerSec on an idle radio means the interrupt is + // re-firing because something it is routed to is still asserting: the handler + // masks the line, the pass unmasks it, and a level-triggered source that + // nothing acked fires again at once. + HWISRCount uint32 + HWISRPerSec uint32 + + // WiFiISRSlots is the bitmask of ISR slots the blob registered, and + // WiFiISRHandlerCalls the total blob handler invocations. The prewiring + // points several peripheral sources at one CPU interrupt, so fewer registered + // slots than routed sources means some source has no handler to ack it. + WiFiISRSlots uint32 + WiFiISRHandlerCalls uint32 + + // UnmaskIntervalUs is the minimum spacing between re-enables of the WiFi CPU + // interrupt, and UnmaskSuppressed how many passes ended without re-enabling + // it. Zero interval means no limit; the ESP32-C3 reports zero because it does + // not need one. + UnmaskIntervalUs uint32 + UnmaskSuppressed uint32 + + // WiFiISRInstalled is the bitmask of slots that actually hold a handler. + // Handlers arrive via ets_isr_attach, which writes only the handler table, + // while WiFiISRSlots is written only by set_intr -- and the dispatcher + // iterates WiFiISRSlots. So a bit set here but not there is a handler that + // exists and is never called, leaving its source unacked. + WiFiISRInstalled uint32 + + // Bring-up pumps. StartReadyAfterPass and ConnectReadyAfterPass are the pass + // on which the blob's ROM pointers became fully valid; 0 means the pump never + // ran, readyNeverSentinel that it ran and they never did. + StartReadyAfterPass uint32 + ConnectReadyAfterPass uint32 + + // RomPtrsSavedUnready counts save calls that could not latch every pointer. + // RomPtrsMissing is which ones are still unlatched, as ROM_PTR_* bits: + // 1 pTxRx, 2 our_tx_eb, 4 our_wait_eb, 8 lmacConfMib_ptr, 16 g_osi_funcs_p. + RomPtrsSavedUnready uint32 + RomPtrsMissing uint32 + + // Queues and the ISR ring. + ISRRingDrops uint32 // ISR could not push: ring full + ISRRingSendFail uint32 // drained item dropped: destination queue full + QueueSendFull uint32 // any queue send rejected because the queue was full + + // RX path. + RxCallbacks uint32 // frames handed over by the blob + RxDrops uint32 // frames dropped because the RX ring was full + RxOversize uint32 // frames dropped because they exceeded the read buffer + // RxIngressErrors counts frames the upper stack declined. Expected to be + // non-zero in normal operation: unhandled protocols land here. + RxIngressErrors uint32 + + // TX path. + TxAttempts uint32 // frames handed to esp_wifi_internal_tx + TxFailNoMem uint32 // rejected with ESP_ERR_NO_MEM (blob TX buffers gone) + TxFailOther uint32 // rejected for any other reason + TxNotConnected uint32 // refused before the blob: STA not associated + // TxDoneCB counts TX-done callbacks, i.e. buffers the blob released. It is + // not a per-frame acknowledgement: it also fires for frames the blob sends on + // its own, so it runs well ahead of TxAttempts. + TxDoneCB uint32 + TxRetries uint32 // NO_MEM rejections retried rather than dropped + TxBusyWaits uint32 // senders that waited for another sender to finish + + // Arena. Shared by WiFi and the BT controller. + AllocCount uint32 // tracked allocations + FreeCount uint32 // tracked frees + ArenaUsed uint32 // bytes + ArenaCapacity uint32 // bytes +} + +// Print writes the counters with println, one group per line. Uses println +// rather than fmt to keep it usable from size-constrained builds, matching the +// C-side dump helpers. +func (s Stats) Print() { + println("espradio sched: isr", s.WiFiISRCount, + "reentry", s.SchedReentries, + "caphits ev/tmr/esptmr", s.EventCapHits, s.TimerCapHits, s.ESPTimerCapHits, + "yieldsupp", s.YieldsSuppressed, + "intsoff", s.IntsOffNesting) + println("espradio passes:", s.SchedPasses, "rate/s", s.SchedPassesPerSec, + "(nominal 200)") + println("espradio kicks: sent", s.KicksDelivered, + "suppressed", s.KicksSuppressed, + "throttle_us", s.KickThrottleUs) + println("espradio hwisr:", s.HWISRCount, "rate/s", s.HWISRPerSec, + "slots", s.WiFiISRSlots, "installed", s.WiFiISRInstalled, + "handlercalls", s.WiFiISRHandlerCalls) + println("espradio unmask: interval_us", s.UnmaskIntervalUs, + "suppressed", s.UnmaskSuppressed) + println("espradio bringup: startready", s.StartReadyAfterPass, + "connectready", s.ConnectReadyAfterPass, + "savedunready", s.RomPtrsSavedUnready, + "missing", s.RomPtrsMissing) + println("espradio queue: isrdrop", s.ISRRingDrops, + "isrsendfail", s.ISRRingSendFail, + "queuefull", s.QueueSendFull) + println("espradio rx: cb", s.RxCallbacks, "drop", s.RxDrops, + "oversize", s.RxOversize, "ingresserr", s.RxIngressErrors) + println("espradio tx: try", s.TxAttempts, + "nomem", s.TxFailNoMem, + "other", s.TxFailOther, + "notconn", s.TxNotConnected, + "done", s.TxDoneCB, + "retry", s.TxRetries, + "busywait", s.TxBusyWaits) + println("espradio mem: alloc", s.AllocCount, + "free", s.FreeCount, + "used", s.ArenaUsed, "of", s.ArenaCapacity) +} + +// DebugStats returns a snapshot of the driver's internal counters. +func DebugStats() Stats { + var s Stats + + s.WiFiISRCount = uint32(C.espradio_get_wifi_isr_count()) + s.SchedReentries = atomic.LoadUint32(&schedReentries) + s.EventCapHits = atomic.LoadUint32(&schedEventCapHits) + s.TimerCapHits = atomic.LoadUint32(&schedTimerCapHits) + s.ESPTimerCapHits = atomic.LoadUint32(&schedESPTimerCapHits) + s.YieldsSuppressed = atomic.LoadUint32(&yieldSuppressed) + s.IntsOffNesting = atomic.LoadUint32(&wifiIntsOff) + s.SchedPasses = atomic.LoadUint32(&schedPasses) + if !schedPassesStart.IsZero() { + if elapsed := time.Since(schedPassesStart).Seconds(); elapsed >= 1 { + s.SchedPassesPerSec = uint32(float64(s.SchedPasses) / elapsed) + } + } + s.KicksDelivered = atomic.LoadUint32(&kicksDelivered) + s.KicksSuppressed = atomic.LoadUint32(&kicksSuppressed) + s.KickThrottleUs = atomic.LoadUint32(&kickThrottleUs) + s.HWISRCount = atomic.LoadUint32(&hwWiFiISRCount) + if !schedPassesStart.IsZero() { + if elapsed := time.Since(schedPassesStart).Seconds(); elapsed >= 1 { + s.HWISRPerSec = uint32(float64(s.HWISRCount) / elapsed) + } + } + s.WiFiISRSlots = uint32(C.espradio_wifi_isr_slots()) + s.WiFiISRHandlerCalls = uint32(C.espradio_wifi_isr_handler_calls()) + s.WiFiISRInstalled = uint32(C.espradio_wifi_isr_installed()) + s.UnmaskIntervalUs = uint32(C.espradio_unmask_interval_us()) + s.UnmaskSuppressed = uint32(C.espradio_unmask_suppressed()) + s.StartReadyAfterPass = startReadyAfterPass + s.ConnectReadyAfterPass = connectReadyAfterPass + s.RomPtrsSavedUnready = uint32(C.espradio_rom_ptrs_saved_unready()) + s.RomPtrsMissing = uint32(C.espradio_rom_ptrs_missing()) + + s.ISRRingDrops = uint32(C.espradio_isr_ring_drops()) + s.ISRRingSendFail = atomic.LoadUint32(&schedISRRingSendFail) + s.QueueSendFull = uint32(C.espradio_queue_send_full_count()) + + s.RxCallbacks = uint32(C.espradio_netif_rx_cb_count()) + s.RxDrops = uint32(C.espradio_netif_rx_cb_drop()) + s.RxOversize = uint32(C.espradio_netif_rx_oversize()) + s.RxIngressErrors = atomic.LoadUint32(&rxIngressErrors) + + var attempts, failNoMem, failOther, notConnected, txDone, retries, busyWaits C.uint32_t + C.espradio_netif_tx_stats(&attempts, &failNoMem, &failOther, ¬Connected, + &txDone, &retries, &busyWaits) + s.TxAttempts = uint32(attempts) + s.TxFailNoMem = uint32(failNoMem) + s.TxFailOther = uint32(failOther) + s.TxNotConnected = uint32(notConnected) + s.TxDoneCB = uint32(txDone) + s.TxRetries = uint32(retries) + s.TxBusyWaits = uint32(busyWaits) + + var allocs, frees C.uint + C.espradio_alloc_stats(&allocs, &frees) + s.AllocCount = uint32(allocs) + s.FreeCount = uint32(frees) + s.ArenaUsed, s.ArenaCapacity = ArenaStats() + + return s +} + +// Scan tuning. All three were unnamed literals; none has a recorded derivation. +// The per-channel dwell times are the blob's own units (milliseconds) and bound +// how long a scan takes: 13 channels at up to scanActiveMaxMs each. +const ( + scanSettleTime = 250 * time.Millisecond + scanActiveMaxMs = 300 + scanPassiveMs = 500 +) + // Scan performs a single Wi-Fi scan pass and returns the list of discovered access points. func Scan() ([]AccessPoint, error) { C.espradio_ensure_osi_ptr() C.esp_wifi_set_ps(C.WIFI_PS_NONE) C.espradio_set_country_eu_manual() - time.Sleep(250 * time.Millisecond) + // Settle after the three config calls above before starting a scan. + // + // Deliberately still a delay, not a pump-until-predicate like the bring-up + // waits. Those were open-loop because the blob needed CPU that a fixed count + // of passes did not reliably provide; that reasoning does not apply here. The + // ticker goroutine runs schedOnce continuously in the background -- measured at + // tens of thousands of passes per second -- so the blob has ample CPU during + // this sleep and is not waiting on us to drive it. Whatever this interval is + // for is wall-clock settling (PHY/RF after the country and power-save changes), + // which a pump cannot shorten. + // + // Its true purpose and correct size are still unverified: it arrived without a + // comment. Reducing or removing it needs an A/B against scan on all three + // targets, watching for empty or short AP lists. + time.Sleep(scanSettleTime) + var scanCfg C.wifi_scan_config_t scanCfg.ssid = nil scanCfg.bssid = nil @@ -307,8 +870,8 @@ func Scan() ([]AccessPoint, error) { scanCfg.show_hidden = false scanCfg.scan_type = C.WIFI_SCAN_TYPE_ACTIVE scanCfg.scan_time.active.min = 0 - scanCfg.scan_time.active.max = 300 - scanCfg.scan_time.passive = 500 + scanCfg.scan_time.active.max = scanActiveMaxMs + scanCfg.scan_time.passive = scanPassiveMs if code := C.esp_wifi_scan_start(&scanCfg, true); code != C.ESP_OK { return nil, makeError(code) } @@ -376,10 +939,18 @@ func Connect(cfg STAConfig) error { // The blob fires WIFI_EVENT_STA_CONNECTED before its internal // TX path (ppCheckIsConnTraffic) is fully initialized. Pump the // scheduler to let the blob finish setup before callers try to TX. - for i := 0; i < 20; i++ { - schedOnce() + for i := 0; i < connectSettleMaxPasses; i++ { + pumpSched() + C.espradio_save_rom_ptrs() + if C.espradio_rom_ptrs_ready() != 0 { + connectReadyAfterPass = uint32(i + 1) + break + } time.Sleep(10 * time.Millisecond) } + if connectReadyAfterPass == 0 { + connectReadyAfterPass = readyNeverSentinel + } return nil } return makeError(C.esp_err_t(res.Reason)) @@ -509,6 +1080,12 @@ func espradio_task_create_pinned_to_core(task_func unsafe.Pointer, name *C.char, //export espradio_task_delete func espradio_task_delete(task_handle unsafe.Pointer) { + // The goroutine itself cannot be killed from here; it exits when + // espradio_run_task returns. What can be reclaimed is the per-task + // semaphore slot and its map entry, which otherwise leak on every task + // teardown -- the slot pool is small and shared with the BT controller, and + // the map grew without bound. + releaseThreadSem(task_handle) } //export tinygo_task_current @@ -519,20 +1096,50 @@ func espradio_task_get_current_task() unsafe.Pointer { return tinygo_task_current() } -func safeGosched() { +// safeGosched yields unless interrupts are currently disabled. It reports +// whether it actually yielded. +// +// A false return means no other goroutine can have run, so a caller spinning on +// this cannot make progress: whatever it is waiting for is held by something that +// will never be scheduled. Callers must treat that as failure rather than +// looping, which is what turned these waits into hangs. +// +// The blob is not supposed to reach a blocking wait from inside a critical +// section at all -- in ESP-IDF these regions are portENTER_CRITICAL and never +// yield -- so a non-zero yieldSuppressed count is evidence of a real defect, not +// a state to tolerate. +// +// Measured on hardware: yieldSuppressed stays at zero, so the false return and +// the failure paths that depend on it are unreached. They are kept because they +// convert a documented-impossible state from a hang into an observable failure, +// not because the state was seen. +func safeGosched() bool { if wifiIntsOff > 0 { - return + atomic.AddUint32(&yieldSuppressed, 1) + return false } runtime.Gosched() + return true } +// mutexLockTimeoutUs bounds espradio_mutex_lock, which previously had no timeout +// of any kind. Generous: it should never be reached in normal operation, and +// hitting it means genuine cross-goroutine contention that is not resolving. +const mutexLockTimeoutUs = 250_000 + //export espradio_task_yield_go func espradio_task_yield_go() { // Don't fire timers inline here — the blob calls task_yield from // deep call stacks and the extra depth risks overflowing the // goroutine stack. Timer polling is handled by schedOnce() in // the ticker goroutine on its own stack. - kickSched() + // + // Throttled: the blob yields on every contended lock, empty queue and + // unavailable semaphore, so kicking on each one is what drove the scheduler to + // 138x its nominal rate. A yield says work may be available, not that it is + // due now, and the Gosched below still hands over to the ticker if it is + // already runnable. + kickSchedThrottled() runtime.Gosched() } @@ -558,21 +1165,50 @@ func espradio_task_ms_to_tick(ms uint32) int32 { return int32(millisecondsToTicks(ms)) } -var wifiIntsOff uint32 +// The blob uses these as a real critical section, not an advisory hint -- in +// ESP-IDF they map to portENTER_CRITICAL/portEXIT_CRITICAL. The BLE side learned +// this the hard way: with no-ops here the controller's ke message queues, which +// its ISR mutates concurrently, got corrupted and event delivery silently +// stopped. +// +// Nesting is tracked inside the primitive, following bt_interrupt_disable: the +// previous interrupt state is captured only at depth 0, and only the outermost +// restore re-enables. That makes the depth trustworthy -- DebugStats reports it, +// and a non-zero value while the radio is idle means a critical section leaked -- +// and makes the pair robust against the blob handing back a stale saved state. +var ( + wifiIntsOff uint32 // nesting depth + wifiIntsSaved uint32 // interrupt state captured at depth 0 +) //export espradio_wifi_int_disable func espradio_wifi_int_disable(wifi_int_mux unsafe.Pointer) uint32 { s := uint32(interrupt.Disable()) + // Interrupts are off from here, so this read-modify-write cannot be + // interleaved by the ISR path on this core. The previous plain increment + // ran before that was guaranteed. + if wifiIntsOff == 0 { + wifiIntsSaved = s + } wifiIntsOff++ return s } //export espradio_wifi_int_restore func espradio_wifi_int_restore(wifi_int_mux unsafe.Pointer, tmp uint32) { - if wifiIntsOff > 0 { - wifiIntsOff-- + // Ignore an unbalanced restore rather than re-enabling: doing so would drop + // an outer critical section's protection while it is still inside. + if wifiIntsOff == 0 { + return } - interrupt.Restore(interrupt.State(tmp)) + wifiIntsOff-- + if wifiIntsOff == 0 { + // Restore the state captured at depth 0, not tmp. An inner disable + // captured "already disabled", so honouring per-call state depends on + // the blob unwinding in strict LIFO order. + interrupt.Restore(interrupt.State(wifiIntsSaved)) + } + _ = tmp } var wifiISR interrupt.Interrupt @@ -628,6 +1264,7 @@ func espradio_mutex_delete(cmut unsafe.Pointer) { func espradio_mutex_lock(cmut unsafe.Pointer) int32 { mut := (*recursiveMutex)(cmut) me := tinygo_task_current() + startUs := timeUsNow() for { mut.state.Lock() if mut.count == 0 || mut.owner == me { @@ -637,7 +1274,14 @@ func espradio_mutex_lock(cmut unsafe.Pointer) int32 { return 1 } mut.state.Unlock() - safeGosched() + // Held by another goroutine. If we cannot yield, that goroutine can + // never run and no amount of spinning will free the mutex. + if !safeGosched() { + return 0 + } + if timeUsNow()-startUs >= mutexLockTimeoutUs { + return 0 + } } } @@ -746,7 +1390,12 @@ func espradio_event_group_wait_bits(ptr unsafe.Pointer, bitsToWaitFor uint32, cl if blockTimeTick == 0 || (!forever && (timeUsNow()-startUs) >= timeoutUs) { return snapshot } - safeGosched() + // Only another goroutine can set these bits, so a wait we cannot yield + // out of will never be satisfied -- including the "forever" case, which + // would otherwise hang here permanently. + if !safeGosched() { + return snapshot + } } } @@ -756,14 +1405,19 @@ type semaphore struct { count uint32 } +// Semaphore slots are drawn from by both WiFi (via the OSI table) and the BT +// controller (bt_ble.c calls these directly), so the pool is shared. Slots are +// reclaimed on delete via a CAS in-use bitmap, the same way mutexes and event +// groups already do it -- the previous monotonic index never freed a slot, so the +// fifth semaphore ever created panicked regardless of how many were live. var ( - semaphores [4]semaphore - semaphoreIndex uint32 + semaphores [8]semaphore + semaphoreInUse [8]uint32 wifiThreadSemMu sync.Mutex wifiThreadSemByTH = map[unsafe.Pointer]*semaphore{} wifiThreadSemNil semaphore threadSems [8]semaphore - threadSemIndex uint32 + threadSemInUse [8]uint32 ) func semTryTake(sem *semaphore) bool { @@ -780,12 +1434,13 @@ func semTryTake(sem *semaphore) bool { //export espradio_semphr_create func espradio_semphr_create(max, init uint32) unsafe.Pointer { - i := atomic.AddUint32(&semaphoreIndex, 1) - 1 - if i >= uint32(len(semaphores)) { - panic("espradio: too many semaphores") + for i := range semaphores { + if atomic.CompareAndSwapUint32(&semaphoreInUse[i], 0, 1) { + atomic.StoreUint32(&semaphores[i].count, init) + return unsafe.Pointer(&semaphores[i]) + } } - semaphores[i] = semaphore{count: init} - return unsafe.Pointer(&semaphores[i]) + panic("espradio: too many semaphores") } //export espradio_semphr_take @@ -808,8 +1463,17 @@ func espradio_semphr_take(semphr unsafe.Pointer, block_time_tick uint32) int32 { // Yield on the failure path. The BT controller task needs CPU to service // connection events on time; without this the link drops with // "Connection Failed to be Established" (0x3e) right after the first ATT - // request. The ke-event re-entrancy this used to allow is now blocked by - // the guard on modules_funcs[0x284] instead. + // request. + // + // The ke-event re-entrancy this yield used to allow was, at the time, + // blocked by a guard on modules_funcs[0x284]. That guard is gone: it was + // removed once instrumenting it showed its deferral counter stay at 0 for + // entire runs while GATT still failed, so the two contexts never actually + // overlapped and the real defect was elsewhere (a lost HCI write, fixed + // by waiting for the controller to take each packet). For the record, + // that slot holds r_rwip_schedule, not r_ke_event_schedule as the guard's + // comment claimed. What keeps the successful path from re-entering the + // scheduler is the absence of a yield above, nothing else. safeGosched() return 0 } @@ -828,7 +1492,13 @@ func espradio_semphr_take(semphr unsafe.Pointer, block_time_tick uint32) int32 { if !forever && (timeUsNow()-startUs) >= timeoutUs { return 0 } - safeGosched() + // Only a give from another context can raise the count, so a wait we + // cannot yield out of will never be satisfied. This is the one that + // matters most: the BT controller task takes its semaphore with + // OSI_FUNCS_TIME_BLOCKING, so without this the forever case parks here. + if !safeGosched() { + return 0 + } } } @@ -843,6 +1513,15 @@ func espradio_semphr_give(semphr unsafe.Pointer) int32 { func espradio_semphr_delete(semphr unsafe.Pointer) { sem := (*semaphore)(semphr) atomic.StoreUint32(&sem.count, 0) + // Release the slot. Only slots from the shared pool are reclaimable; the + // per-thread semaphores below are owned by their task, and wifiThreadSemNil + // is a singleton, so neither is in this array. + for i := range semaphores { + if sem == &semaphores[i] { + atomic.StoreUint32(&semaphoreInUse[i], 0) + return + } + } } //export espradio_wifi_thread_semphr_get @@ -855,16 +1534,48 @@ func espradio_wifi_thread_semphr_get() unsafe.Pointer { } sem := wifiThreadSemByTH[task] if sem == nil { - i := atomic.AddUint32(&threadSemIndex, 1) - 1 - if i >= uint32(len(threadSems)) { + sem = allocThreadSem() + if sem == nil { panic("espradio: too many thread semaphores") } - sem = &threadSems[i] wifiThreadSemByTH[task] = sem } return unsafe.Pointer(sem) } +// allocThreadSem claims a per-task semaphore slot, or returns nil if all are +// taken. Slots are reclaimed when the owning task's goroutine is deleted; the +// previous monotonic index leaked one per task teardown. +func allocThreadSem() *semaphore { + for i := range threadSems { + if atomic.CompareAndSwapUint32(&threadSemInUse[i], 0, 1) { + atomic.StoreUint32(&threadSems[i].count, 0) + return &threadSems[i] + } + } + return nil +} + +// releaseThreadSem drops the per-task semaphore for task, if it has one. +func releaseThreadSem(task unsafe.Pointer) { + if task == nil { + return + } + wifiThreadSemMu.Lock() + sem := wifiThreadSemByTH[task] + delete(wifiThreadSemByTH, task) + wifiThreadSemMu.Unlock() + if sem == nil { + return + } + for i := range threadSems { + if sem == &threadSems[i] { + atomic.StoreUint32(&threadSemInUse[i], 0) + return + } + } +} + // ─── Helpers ───────────────────────────────────────────────────────────────── func boolToInt(b bool) int { diff --git a/radio_esp32.go b/radio_esp32.go index baee49f..d8e33d4 100644 --- a/radio_esp32.go +++ b/radio_esp32.go @@ -77,6 +77,9 @@ func makeArenaPool(size int) []byte { // Just mask the level-triggered interrupt and wake the scheduler; schedOnce() // will call espradio_call_wifi_isr() on its own goroutine stack. func wifiISRHandler(interrupt.Interrupt) { + countHWWiFiISR() C.espradio_ints_off(C.uint32_t(1 << wifiCPUInterrupt)) + // Unthrottled deliberately: a real hardware event, and here it is the only + // thing that will run the blob ISR, since this handler does not. kickSched() } diff --git a/radio_esp32c3.go b/radio_esp32c3.go index fe0dada..29bbaeb 100644 --- a/radio_esp32c3.go +++ b/radio_esp32c3.go @@ -79,6 +79,12 @@ const arenaPoolSize = 48 * 1024 // hardware interrupt handler. On RISC-V the interrupt context can // safely call the blob's ISR without stack overflow concerns. func wifiISRHandler(interrupt.Interrupt) { + countHWWiFiISR() + // Real interrupt context: mark it so nothing below yields. + C.espradio_enter_hw_isr() C.espradio_call_wifi_isr() + C.espradio_exit_hw_isr() + // Unthrottled deliberately: this is a real hardware event and must be + // serviced now. Only the cooperative-yield path is rate-limited. kickSched() } diff --git a/radio_esp32s3.go b/radio_esp32s3.go index 42942f8..6af1e0a 100644 --- a/radio_esp32s3.go +++ b/radio_esp32s3.go @@ -72,6 +72,9 @@ const arenaPoolSize = 48 * 1024 // Just mask the level-triggered interrupt and wake the scheduler; schedOnce() // will call espradio_call_wifi_isr() on its own goroutine stack. func wifiISRHandler(interrupt.Interrupt) { + countHWWiFiISR() C.espradio_ints_off(C.uint32_t(1 << wifiCPUInterrupt)) + // Unthrottled deliberately: a real hardware event, and here it is the only + // thing that will run the blob ISR, since this handler does not. kickSched() } From b17d2208d41b3fcd12ccc00550e5bd119837e22c Mon Sep 17 00:00:00 2001 From: deadprogram Date: Wed, 29 Jul 2026 16:12:53 +0200 Subject: [PATCH 4/9] wifi: incorporate feedback from review comments Signed-off-by: deadprogram --- examples/apwebserver/apwebserver.go | 4 ++- examples/scan/main.go | 4 ++- examples/webserver/webserver.go | 4 ++- netif_esp.go | 4 +-- netlink/netlink.go | 2 +- radio.go | 48 ++++++++++++++--------------- 6 files changed, 35 insertions(+), 31 deletions(-) diff --git a/examples/apwebserver/apwebserver.go b/examples/apwebserver/apwebserver.go index 21842c7..69fa09d 100644 --- a/examples/apwebserver/apwebserver.go +++ b/examples/apwebserver/apwebserver.go @@ -70,7 +70,9 @@ func main() { go func() { for { time.Sleep(10 * time.Second) - espradio.DebugStats().Print() + var stats espradio.Stats + espradio.ReadStats(&stats) + stats.Print() } }() diff --git a/examples/scan/main.go b/examples/scan/main.go index 65a3924..ea41c09 100644 --- a/examples/scan/main.go +++ b/examples/scan/main.go @@ -42,7 +42,9 @@ func main() { // Driver counters. Most of these count something being dropped, so a // non-zero value is the only evidence it happened. - espradio.DebugStats().Print() + var stats espradio.Stats + espradio.ReadStats(&stats) + stats.Print() println() time.Sleep(10 * time.Second) diff --git a/examples/webserver/webserver.go b/examples/webserver/webserver.go index 7abfd53..4a9f4e3 100644 --- a/examples/webserver/webserver.go +++ b/examples/webserver/webserver.go @@ -58,7 +58,9 @@ func main() { go func() { for { time.Sleep(10 * time.Second) - espradio.DebugStats().Print() + var stats espradio.Stats + espradio.ReadStats(&stats) + stats.Print() } }() diff --git a/netif_esp.go b/netif_esp.go index f1a2e3f..827cc35 100644 --- a/netif_esp.go +++ b/netif_esp.go @@ -70,7 +70,7 @@ func (nd *NetDev) EthPoll(buf []byte) (int, error) { if n == 0 { // Either the ring was empty, or the frame did not fit and was dropped // whole rather than truncated. Both mean "no frame for this caller"; - // the drop is counted in DebugStats as RxOversize. + // the drop is counted in ReadStats as RxOversize. return 0, nil } if nd.rxHandler != nil { @@ -81,7 +81,7 @@ func (nd *NetDev) EthPoll(buf []byte) (int, error) { // call where it successfully delivered a frame. // // The original defect was that these were invisible, not that they were - // unpropagated; DebugStats().RxIngressErrors fixes that without giving + // unpropagated; ReadStats().RxIngressErrors fixes that without giving // normal traffic an error path. if err := nd.rxHandler(buf[:n]); err != nil { atomic.AddUint32(&rxIngressErrors, 1) diff --git a/netlink/netlink.go b/netlink/netlink.go index 90f9736..c94602c 100644 --- a/netlink/netlink.go +++ b/netlink/netlink.go @@ -313,7 +313,7 @@ func handleStack(stack *espradio.Stack) { // the frame before the send was attempted, so there is nothing left to // retry with. The retry that can still help runs inside // espradio_netif_tx, against the blob's TX-done signal. With debug - // off, DebugStats is the record: TxFailNoMem, TxFailOther, + // off, ReadStats is the record: TxFailNoMem, TxFailOther, // TxNotConnected. println("handleStack: RecvAndSend:", err.Error()) } diff --git a/radio.go b/radio.go index 345dc2d..3103de8 100644 --- a/radio.go +++ b/radio.go @@ -118,14 +118,15 @@ var wifiInitDone uint32 // ─── Scheduler policy (runtime-switchable, for A/B on hardware) ────────────── -// SchedPolicy selects behaviour inside schedOnce that is worth measuring on +// schedPolicyMask selects behaviour inside schedOnce that is worth measuring on // real hardware rather than reasoning about. Modelled on the BLE side's // espradio_bt_set_sched_tick_mask, which is what made the scheduler-contention -// theory in the BLE work falsifiable. -type SchedPolicy uint32 +// theory in the BLE work falsifiable. Not exported: like its BLE counterpart, +// this is a bisecting knob for this package's own bring-up, not public API. +type schedPolicyMask uint32 const ( - // SchedPollWiFiISR polls the blob's WiFi ISR from the scheduler tick. + // schedPollWiFiISR polls the blob's WiFi ISR from the scheduler tick. // // On ESP32-S3 and ESP32 this is required: their hardware handler only // masks and kicks, so the tick is the only thing that runs the blob ISR. @@ -135,21 +136,21 @@ const ( // (see the note in schedOnce), and whether the WiFi blob tolerates it is a // property of that blob, not a general rule -- so it is switchable and // meant to be measured, not removed on argument. - SchedPollWiFiISR SchedPolicy = 1 << iota + schedPollWiFiISR schedPolicyMask = 1 << iota ) // schedPolicy defaults to polling the WiFi ISR with fixed-count drains, which is // the behaviour that predates this switch. -var schedPolicy = uint32(SchedPollWiFiISR) +var schedPolicy = uint32(schedPollWiFiISR) -// SetSchedPolicy replaces the scheduler policy mask. Intended for bisecting +// setSchedPolicy replaces the scheduler policy mask. Intended for bisecting // behaviour on hardware; the default is the historical behaviour. -func SetSchedPolicy(p SchedPolicy) { atomic.StoreUint32(&schedPolicy, uint32(p)) } +func setSchedPolicy(p schedPolicyMask) { atomic.StoreUint32(&schedPolicy, uint32(p)) } -// GetSchedPolicy returns the current scheduler policy mask. -func GetSchedPolicy() SchedPolicy { return SchedPolicy(atomic.LoadUint32(&schedPolicy)) } +// getSchedPolicy returns the current scheduler policy mask. +func getSchedPolicy() schedPolicyMask { return schedPolicyMask(atomic.LoadUint32(&schedPolicy)) } -func schedPolicyHas(p SchedPolicy) bool { +func schedPolicyHas(p schedPolicyMask) bool { return atomic.LoadUint32(&schedPolicy)&uint32(p) != 0 } @@ -222,7 +223,7 @@ var ( // 5 ms / 200 Hz, but every espradio_task_yield_go calls kickSched, so the // ticker is woken far more often than that -- the ISR counter's growth implies // tens of thousands of passes per second. This measures it directly instead - // of inferring it: DebugStats divides by elapsed time. + // of inferring it: ReadStats divides by elapsed time. // // The same feedback loop was found and throttled on the BLE side, where waking // the controller task fed back into kickSched and collapsed the 5 ms tick to @@ -267,7 +268,7 @@ func schedOnce() bool { // Poll WiFi ISR: work around missing hardware interrupt on ESP32-S3. // Only poll after init is complete (blob ISR not registered until then). - if atomic.LoadUint32(&wifiInitDone) != 0 && schedPolicyHas(SchedPollWiFiISR) { + if atomic.LoadUint32(&wifiInitDone) != 0 && schedPolicyHas(schedPollWiFiISR) { C.espradio_call_wifi_isr() } @@ -430,15 +431,16 @@ var ( // countHWWiFiISR is called from each target's WiFi interrupt handler. func countHWWiFiISR() { atomic.AddUint32(&hwWiFiISRCount, 1) } -// SetKickThrottleUs sets the minimum interval in microseconds between +// setKickThrottleUs sets the minimum interval in microseconds between // yield-driven scheduler wakes. Zero disables the throttle. // // Intended for bisecting on hardware: 0 is the historical behaviour, 1000 the -// default, and larger values trade latency for fewer scheduler passes. -func SetKickThrottleUs(us uint32) { atomic.StoreUint32(&kickThrottleUs, us) } +// default, and larger values trade latency for fewer scheduler passes. Not +// exported: a bisecting knob for this package's own bring-up, not public API. +func setKickThrottleUs(us uint32) { atomic.StoreUint32(&kickThrottleUs, us) } -// KickThrottleUs returns the current yield-driven kick interval. -func KickThrottleUs() uint32 { return atomic.LoadUint32(&kickThrottleUs) } +// getKickThrottleUs returns the current yield-driven kick interval. +func getKickThrottleUs() uint32 { return atomic.LoadUint32(&kickThrottleUs) } // Note on bring-up and the throttle: disabling the throttle for the duration of // the bring-up pumps was tried, on the theory that rate-limiting the blob's wakes @@ -767,10 +769,8 @@ func (s Stats) Print() { "used", s.ArenaUsed, "of", s.ArenaCapacity) } -// DebugStats returns a snapshot of the driver's internal counters. -func DebugStats() Stats { - var s Stats - +// ReadStats fills s with a snapshot of the driver's internal counters. +func ReadStats(s *Stats) { s.WiFiISRCount = uint32(C.espradio_get_wifi_isr_count()) s.SchedReentries = atomic.LoadUint32(&schedReentries) s.EventCapHits = atomic.LoadUint32(&schedEventCapHits) @@ -828,8 +828,6 @@ func DebugStats() Stats { s.AllocCount = uint32(allocs) s.FreeCount = uint32(frees) s.ArenaUsed, s.ArenaCapacity = ArenaStats() - - return s } // Scan tuning. All three were unnamed literals; none has a recorded derivation. @@ -1173,7 +1171,7 @@ func espradio_task_ms_to_tick(ms uint32) int32 { // // Nesting is tracked inside the primitive, following bt_interrupt_disable: the // previous interrupt state is captured only at depth 0, and only the outermost -// restore re-enables. That makes the depth trustworthy -- DebugStats reports it, +// restore re-enables. That makes the depth trustworthy -- ReadStats reports it, // and a non-zero value while the radio is idle means a critical section leaked -- // and makes the pair robust against the blob handing back a stale saved state. var ( From 5baf13c28995c827e3a1d83ed3efa720afe120f8 Mon Sep 17 00:00:00 2001 From: deadprogram Date: Thu, 30 Jul 2026 10:40:39 +0200 Subject: [PATCH 5/9] ble: move the VHCI RX ring from C to Go vhci_ring.c held a single-producer/single-consumer byte ring and nothing else: no dependency on the BTDM blob, no hardware access. vhci_ring.go existed purely to call into it, and vhci_ring_test.go already covered it through that wrapper. Making the Go file the implementation deletes both the C and the pass-through layer; the eight tests pass unmodified, which is the evidence the semantics did not move. bt_ble.c still calls espradio_vhci_ring_push, now resolved to an //export from Go. Its build tag is esp32c3 and the Go file's is esp32c3 || esp32c3_qemu_target, so the definition always exists wherever the caller does. runtime/volatile, not sync/atomic --------------------------------- The first version used sync/atomic for the head and tail indices. That is not the equivalent of the C volatile it replaced. The C3 is RV32IMC with no atomic extension -- TinyGo's targets/esp32c3.json feature string is "+32bit,+c,+m,+zmmul,-relax" -- so atomic.LoadUint32/StoreUint32 lower to __atomic_load_4/__atomic_store_4, and src/runtime/atomics_critical.go implements those by masking interrupts around the access. Those calls sat in the per-byte loops, three per byte in vhciReadByte, and in the push path that runs in the controller's recv callback. On hardware, BLE notifications on a central (heartrate-monitor) arrived with human-noticeable pauses, while a peripheral (heartrate) looked healthy because its inbound HCI rate is far lower. runtime/volatile is what the C had -- a plain load/store the compiler may not cache in a register, no call, no masking -- and single-writer-per-index is what makes that sufficient. That first version also batched index publication to once per push and once per read. Wrong independently of cost: reading tail once let a push beginning against a near-full ring give up while the consumer was actively draining, and on an HCI byte stream a short push is a truncated packet, not a slow one. Both sides publish per byte again, as the C did. Size, same program, against the C it replaces: code bss push fn C 268916 41504 - Go, sync/atomic 269020 41504 138 B Go, volatile 268884 41504 92 B Verified -------- fmt-check and unit-test pass, with vhci_ring_test.go unmodified. smoke-test builds 11 examples x 3 targets clean. On hardware, ESP32-C3: heartrate and heartrate-monitor both work; apwebserver still works on C3, S3 and ESP32. Still open: one run showed heartrate-monitor notifications stalling unless the peripheral was close, which did not reproduce on a reflash of the same tree. It is unexplained rather than fixed. Neither this ring nor the lib.c change can affect RX sensitivity, and PHY calibration is not the gap (the NVS stub returns ESP_ERR_NOT_FOUND, so cal_mode falls through to PHY_RF_CAL_FULL every boot) -- but a marginally misaligned receive window would present exactly as distance-dependent, and central-path timing has its own history here. Signed-off-by: deadprogram --- ble.go | 6 +-- bt_ble.c | 5 ++- espradio.h | 3 -- vhci_ring.c | 70 ------------------------------ vhci_ring.go | 119 +++++++++++++++++++++++++++++++++++++++++++-------- 5 files changed, 106 insertions(+), 97 deletions(-) delete mode 100644 vhci_ring.c diff --git a/ble.go b/ble.go index 37f7915..57e41f5 100644 --- a/ble.go +++ b/ble.go @@ -32,13 +32,13 @@ type VHCITransport struct{} // Buffered returns the number of bytes available to read from the controller. func (t VHCITransport) Buffered() int { - return int(C.espradio_vhci_buffered()) + return vhciBuffered() } // ReadByte reads a single byte from the HCI controller. func (t VHCITransport) ReadByte() (byte, error) { for { - b := int(C.espradio_vhci_read_byte()) + b := vhciReadByte() if b >= 0 { return byte(b), nil } @@ -52,7 +52,7 @@ func (t VHCITransport) Read(buf []byte) (int, error) { return 0, nil } for { - n := int(C.espradio_vhci_read((*C.uint8_t)(unsafe.Pointer(&buf[0])), C.int(len(buf)))) + n := vhciRead(buf) if n > 0 { return n, nil } diff --git a/bt_ble.c b/bt_ble.c index 2b1a5c2..0ddc398 100644 --- a/bt_ble.c +++ b/bt_ble.c @@ -453,7 +453,8 @@ uint32_t espradio_bt_intc_pending(void) { * VHCI Ring Buffer (controller → host) * ═══════════════════════════════════════════════════════════════════════════ */ -/* The ring itself lives in vhci_ring.c so the unit-test target can reach it. */ +/* The ring itself is implemented in Go (vhci_ring.go), which is what lets the + * unit-test target reach it without the BTDM blob. */ extern int espradio_vhci_ring_push(const uint8_t *data, int len); static volatile int s_vhci_send_available = 1; @@ -485,7 +486,7 @@ static void vhci_host_send_available_cb(void) { s_vhci_send_available = 1; } -/* espradio_vhci_buffered / _read_byte / _read live in vhci_ring.c */ +/* The consumer side (buffered / read_byte / read) is Go-only: see vhci_ring.go. */ /* ROM VHCI API */ extern bool API_vhci_host_check_send_available(void); diff --git a/espradio.h b/espradio.h index 426e4b0..5dbcb13 100644 --- a/espradio.h +++ b/espradio.h @@ -140,9 +140,6 @@ void ets_intr_unlock(void); /* ===== BLE (bt_ble.c) ===== */ int espradio_ble_init(void); -int espradio_vhci_buffered(void); -int espradio_vhci_read_byte(void); -int espradio_vhci_read(uint8_t *buf, int max_len); int espradio_vhci_write(const uint8_t *data, int len); void espradio_bt_isr_dispatch_5(void); void espradio_bt_isr_dispatch_8(void); diff --git a/vhci_ring.c b/vhci_ring.c deleted file mode 100644 index cdbb200..0000000 --- a/vhci_ring.c +++ /dev/null @@ -1,70 +0,0 @@ -//go:build esp32c3 || esp32c3_qemu_target - -/* VHCI RX ring buffer (controller -> host). - * - * Split out of bt_ble.c because this is the one part of the BLE path with no - * dependency on the BTDM blob or on hardware: the controller pushes bytes in - * from its recv callback and Go drains them. That makes it the only piece - * reachable from the esp32c3-qemu unit-test target, so it lives here and - * bt_ble.c calls espradio_vhci_ring_push() from vhci_host_recv_cb(). - */ - -#include - -#define VHCI_RX_BUF_SIZE 2048 - -static uint8_t s_vhci_rx_buf[VHCI_RX_BUF_SIZE]; -static volatile uint32_t s_vhci_rx_head; /* written by ISR (recv callback) */ -static volatile uint32_t s_vhci_rx_tail; /* read by Go */ - -/* Append up to len bytes, returning how many were actually stored. - * - * head == tail means empty, so usable capacity is VHCI_RX_BUF_SIZE - 1 and a - * push that hits the limit stores a prefix and reports the short count. The - * caller is an HCI packet boundary, so a short return means a truncated packet - * was committed to the stream -- see espradio_vhci_ring_dropped(). */ -int espradio_vhci_ring_push(const uint8_t *data, int len) { - int n = 0; - for (; n < len; n++) { - uint32_t next = (s_vhci_rx_head + 1) % VHCI_RX_BUF_SIZE; - if (next == s_vhci_rx_tail) { - break; /* full */ - } - s_vhci_rx_buf[s_vhci_rx_head] = data[n]; - s_vhci_rx_head = next; - } - return n; -} - -int espradio_vhci_buffered(void) { - uint32_t h = s_vhci_rx_head; - uint32_t t = s_vhci_rx_tail; - if (h >= t) return (int)(h - t); - return (int)(VHCI_RX_BUF_SIZE - t + h); -} - -int espradio_vhci_read_byte(void) { - if (s_vhci_rx_head == s_vhci_rx_tail) { - return -1; /* no data */ - } - uint8_t b = s_vhci_rx_buf[s_vhci_rx_tail]; - s_vhci_rx_tail = (s_vhci_rx_tail + 1) % VHCI_RX_BUF_SIZE; - return (int)b; -} - -int espradio_vhci_read(uint8_t *buf, int max_len) { - int n = 0; - while (n < max_len && s_vhci_rx_head != s_vhci_rx_tail) { - buf[n++] = s_vhci_rx_buf[s_vhci_rx_tail]; - s_vhci_rx_tail = (s_vhci_rx_tail + 1) % VHCI_RX_BUF_SIZE; - } - return n; -} - -/* Test support. */ -int espradio_vhci_ring_capacity(void) { return VHCI_RX_BUF_SIZE - 1; } - -void espradio_vhci_ring_reset(void) { - s_vhci_rx_head = 0; - s_vhci_rx_tail = 0; -} diff --git a/vhci_ring.go b/vhci_ring.go index fa49ae0..d8af0dc 100644 --- a/vhci_ring.go +++ b/vhci_ring.go @@ -4,46 +4,127 @@ package espradio /* #include -int espradio_vhci_ring_push(const uint8_t *data, int len); -int espradio_vhci_ring_capacity(void); -void espradio_vhci_ring_reset(void); -int espradio_vhci_buffered(void); -int espradio_vhci_read_byte(void); -int espradio_vhci_read(uint8_t *buf, int max_len); */ import "C" -import "unsafe" +import "runtime/volatile" // The VHCI RX ring is the controller -> host byte stream behind VHCITransport. -// These wrappers exist so it can be exercised without the BTDM blob; on the -// device the same functions are driven by the controller's recv callback. +// +// It is the one part of the BLE path with no dependency on the BTDM blob or on +// hardware: the controller pushes bytes in from its recv callback +// (vhci_host_recv_cb in bt_ble.c) and Go drains them. That is what makes it +// reachable from the esp32c3-qemu unit-test target. +// +// head == tail means empty, so one slot is never usable and the ring holds +// vhciRingSize-1 bytes. +// +// The indices are accessed through runtime/volatile, not sync/atomic. That is +// deliberate and it matters: the ESP32-C3 is RV32IMC with no atomic extension +// (its target feature string has no "+a"), so sync/atomic lowers to +// __atomic_load_4 / __atomic_store_4 libcalls and TinyGo implements those by +// masking interrupts around the access. In the per-byte loops below -- and in the +// push path, which runs in the controller's recv callback -- that starved the BLE +// controller's real-time interrupts badly enough to stall notification delivery +// on a central. volatile is what the C original used: a plain load/store the +// compiler may not cache in a register, with no call and no interrupt masking. +// Single-writer-per-index is what makes that sufficient. +const vhciRingSize = 2048 -// vhciRingReset empties the ring. -func vhciRingReset() { C.espradio_vhci_ring_reset() } +var ( + vhciRXBuf [vhciRingSize]byte + vhciRXHead uint32 // written by the recv callback (interrupt context) + vhciRXTail uint32 // written by Go +) -// vhciRingCapacity is the greatest number of bytes the ring can hold. -func vhciRingCapacity() int { return int(C.espradio_vhci_ring_capacity()) } +// espradio_vhci_ring_push is the producer side, called from the controller's +// recv callback in bt_ble.c. +// +// On the C3 that callback runs in real interrupt context, so this path must not +// allocate or yield. cArrayToBytes is a bare unsafe.Slice over the caller's +// buffer and does neither. +// +//export espradio_vhci_ring_push +func espradio_vhci_ring_push(data *C.uint8_t, length C.int) C.int { + if data == nil || length <= 0 { + return 0 + } + return C.int(vhciRingPush(cArrayToBytes(data, int(length)))) +} // vhciRingPush appends b, returning how many bytes were stored. A short return // means the ring filled and the remainder was dropped. +// +// The caller is an HCI packet boundary, so a short return means a truncated +// packet was committed to the byte stream, and a host parser reading it will +// desync -- see TestVHCIRingOverflowTruncatesPacket, which documents that as a +// known limitation of a ring with no packet framing. func vhciRingPush(b []byte) int { - if len(b) == 0 { - return 0 + head := volatile.LoadUint32(&vhciRXHead) + n := 0 + for ; n < len(b); n++ { + next := (head + 1) % vhciRingSize + // Re-read the tail every iteration rather than once up front: the + // consumer publishes progress per byte, so space it frees mid-push has to + // be usable here. Reading it once let a push that began against a + // near-full ring give up while the consumer was actively draining, which + // on an HCI stream means a truncated packet rather than a slow one. + if next == volatile.LoadUint32(&vhciRXTail) { + break // full + } + vhciRXBuf[head] = b[n] + // Publish the byte before the index so the consumer can never observe a + // slot it is cleared to read before the byte has landed in it. + volatile.StoreUint32(&vhciRXHead, next) + head = next } - return int(C.espradio_vhci_ring_push((*C.uint8_t)(unsafe.Pointer(&b[0])), C.int(len(b)))) + return n } // vhciBuffered reports how many bytes are available to read. -func vhciBuffered() int { return int(C.espradio_vhci_buffered()) } +func vhciBuffered() int { + head := volatile.LoadUint32(&vhciRXHead) + tail := volatile.LoadUint32(&vhciRXTail) + if head >= tail { + return int(head - tail) + } + return int(vhciRingSize - tail + head) +} // vhciReadByte pops one byte, or returns -1 when empty. -func vhciReadByte() int { return int(C.espradio_vhci_read_byte()) } +func vhciReadByte() int { + tail := volatile.LoadUint32(&vhciRXTail) + if volatile.LoadUint32(&vhciRXHead) == tail { + return -1 + } + b := vhciRXBuf[tail] + volatile.StoreUint32(&vhciRXTail, (tail+1)%vhciRingSize) + return int(b) +} // vhciRead drains up to len(buf) bytes, returning the count. func vhciRead(buf []byte) int { if len(buf) == 0 { return 0 } - return int(C.espradio_vhci_read((*C.uint8_t)(unsafe.Pointer(&buf[0])), C.int(len(buf)))) + tail := volatile.LoadUint32(&vhciRXTail) + n := 0 + for n < len(buf) && volatile.LoadUint32(&vhciRXHead) != tail { + buf[n] = vhciRXBuf[tail] + n++ + tail = (tail + 1) % vhciRingSize + // Publish progress per byte so a producer in interrupt context sees the + // freed space immediately instead of only when the whole drain finishes. + volatile.StoreUint32(&vhciRXTail, tail) + } + return n +} + +// vhciRingCapacity is the greatest number of bytes the ring can hold. +func vhciRingCapacity() int { return vhciRingSize - 1 } + +// vhciRingReset empties the ring. +func vhciRingReset() { + volatile.StoreUint32(&vhciRXHead, 0) + volatile.StoreUint32(&vhciRXTail, 0) } From 586ea7b8a19fbbecf9b65881c472023d6e0e6c4d Mon Sep 17 00:00:00 2001 From: deadprogram Date: Thu, 30 Jul 2026 10:50:15 +0200 Subject: [PATCH 6/9] ble: remove the lib.c functions after moving from C to Go This removes nearly all of the C functions in lib.c now that they have been moved into Go where they really belong. Signed-off-by: deadprogram --- lib.c | 102 ++++----------------------------- lib.go | 176 +++++++++++++++++++++++++++++++++++++++++++++++++++++++++ 2 files changed, 186 insertions(+), 92 deletions(-) create mode 100644 lib.go diff --git a/lib.c b/lib.c index 86008c5..664f243 100644 --- a/lib.c +++ b/lib.c @@ -1,99 +1,17 @@ -#include -#include -#include #include -#include "include.h" - -extern uint64_t espradio_time_us_now(void); -extern void espradio_task_delay(uint32_t ticks); - -int gettimeofday(void *tv, void *tz) { - (void)tz; - if (tv) { - uint64_t us = espradio_time_us_now(); - struct { uint32_t sec; uint32_t usec; } *t = tv; - t->sec = (uint32_t)(us / 1000000u); - t->usec = (uint32_t)(us % 1000000u); - } - return 0; -} - -static uint32_t xorshift_state = 0x12345678u; - -void esp_fill_random(void *buf, size_t len) { - uint8_t *p = (uint8_t *)buf; - while (len >= 4) { - uint32_t t = (uint32_t)espradio_time_us_now(); - xorshift_state ^= t + 0x85ebca6bu + (xorshift_state << 6) + (xorshift_state >> 2); - xorshift_state ^= xorshift_state << 13; - xorshift_state ^= xorshift_state >> 17; - xorshift_state ^= xorshift_state << 5; - memcpy(p, &xorshift_state, 4); - p += 4; len -= 4; - } - if (len) { - uint32_t t = (uint32_t)espradio_time_us_now(); - xorshift_state ^= t + 0x85ebca6bu + (xorshift_state << 6) + (xorshift_state >> 2); - memcpy(p, &xorshift_state, len); - } -} - -unsigned int sleep(unsigned int secs) { - espradio_task_delay(secs * 100); - return 0; -} - -int usleep(unsigned int us) { - uint32_t ticks = us / 10000; - if (ticks == 0) ticks = 1; - espradio_task_delay(ticks); - return 0; -} +/* Everything else that used to live here -- gettimeofday, sleep, usleep, + * vTaskDelay, esp_fill_random, esp_random, strrchr, esp_wifi_connect and + * esp_wifi_disconnect -- is now implemented in Go, in lib.go. + * + * esp_timer_get_time moved too, in the sense that it simply went away: the copy + * here was a duplicate of the weak definition in esp_timer_shim.c, which is what + * links now that nothing defines the symbol strongly. + * + * __assert_func stays in C because it needs printf, and C varargs have no Go + * equivalent. */ void __assert_func(const char *file, int line, const char *func, const char *expr) { printf("ASSERT FAILED: %s:%d %s: %s\n", file, line, func ? func : "", expr ? expr : ""); while (1) {} } - -/* ---------- FreeRTOS / IDF symbols needed by eloop & supplicant ---------- */ - -void vTaskDelay(uint32_t ticks) { - espradio_task_delay(ticks); -} - -int64_t esp_timer_get_time(void) { - return (int64_t)espradio_time_us_now(); -} - -uint32_t esp_random(void) { - uint32_t r; - esp_fill_random(&r, sizeof(r)); - return r; -} - -/* ---------- esp_wifi high-level wrappers → blob internals ---------- */ - -extern esp_err_t esp_wifi_connect_internal(void); -extern esp_err_t esp_wifi_disconnect_internal(void); - -esp_err_t esp_wifi_connect(void) { - return esp_wifi_connect_internal(); -} - -esp_err_t esp_wifi_disconnect(void) { - return esp_wifi_disconnect_internal(); -} - - -/* ---------- strrchr: not in picolibc, not in libwpa_supplicant ---------- */ - -char *strrchr(const char *s, int c) { - const char *last = NULL; - while (*s) { - if (*s == (char)c) last = s; - s++; - } - if ((char)c == '\0') return (char *)s; - return (char *)last; -} diff --git a/lib.go b/lib.go new file mode 100644 index 0000000..cf695b3 --- /dev/null +++ b/lib.go @@ -0,0 +1,176 @@ +//go:build esp32c3 || esp32c3_qemu_target || esp32s3 || esp32 + +package espradio + +/* +#cgo CFLAGS: -Iblobs/include +#cgo CFLAGS: -Iblobs/include/local +#cgo CFLAGS: -DCONFIG_SOC_WIFI_NAN_SUPPORT=0 +#cgo CFLAGS: -DESPRADIO_PHY_PATCH_ROMFUNCS=0 +#cgo CFLAGS: -fno-short-enums + +#include "espradio.h" + +// The disconnect counterpart to esp_wifi_connect_internal, which espradio.h +// already declares. +extern esp_err_t esp_wifi_disconnect_internal(void); +*/ +import "C" + +import "unsafe" + +// Gap-fillers for symbols the WiFi blobs and libwpa_supplicant link against but +// that picolibc and TinyGo do not provide. Every one of these is an undefined +// reference in the blob archives, so each needs a definition or the link fails. +// +// These are reached from blob context, so they must not allocate: none of them +// does. + +// ─── Time ──────────────────────────────────────────────────────────────────── + +// gettimeofday fills a struct timeval. Only the two 32-bit fields the blob +// reads are written; tz is ignored, as it is by the IDF. +// +//export gettimeofday +func gettimeofday(tv, tz unsafe.Pointer) int32 { + if tv != nil { + us := espradio_time_us_now() + *(*uint32)(tv) = uint32(us / 1000000) + *(*uint32)(unsafe.Add(tv, 4)) = uint32(us % 1000000) + } + return 0 +} + +// sleep and usleep both round up to at least one tick: the blob uses them as +// yield points, and a zero-tick delay would spin. + +//export sleep +func sleep(secs uint32) uint32 { + espradio_task_delay(secs * 100) + return 0 +} + +//export usleep +func usleep(us uint32) int32 { + ticks := us / 10000 + if ticks == 0 { + ticks = 1 + } + espradio_task_delay(ticks) + return 0 +} + +//export vTaskDelay +func vTaskDelay(ticks uint32) { + espradio_task_delay(ticks) +} + +// esp_timer_get_time is deliberately absent here: esp_timer_shim.c carries a +// weak definition with the same body, and with nothing else defining the symbol +// that weak one is what links. + +// ─── Randomness ────────────────────────────────────────────────────────────── + +// xorshiftState seeds the PRNG behind esp_fill_random. This is not a CSPRNG -- +// the C original was not either -- it is a time-mixed xorshift standing in for +// the hardware RNG the blob expects. +var xorshiftState uint32 = 0x12345678 + +// mixRandom advances the state with the current time folded in. +func mixRandom() uint32 { + t := uint32(espradio_time_us_now()) + xorshiftState ^= t + 0x85ebca6b + (xorshiftState << 6) + (xorshiftState >> 2) + return xorshiftState +} + +// nextRandom is mixRandom plus the three xorshift rounds. +func nextRandom() uint32 { + mixRandom() + xorshiftState ^= xorshiftState << 13 + xorshiftState ^= xorshiftState >> 17 + xorshiftState ^= xorshiftState << 5 + return xorshiftState +} + +// esp_fill_random fills buf with pseudo-random bytes. +// +// Note the asymmetry between the 4-byte body and the tail: the tail applies only +// the time-mixing step and skips the three xorshift rounds. That is carried over +// verbatim from the C version rather than corrected, because changing it changes +// the byte stream the blob gets; it is called out here so the difference reads as +// deliberate rather than as a transcription slip. +// +//export esp_fill_random +func esp_fill_random(buf unsafe.Pointer, length C.size_t) { + if buf == nil || length == 0 { + return + } + p := unsafe.Slice((*byte)(buf), int(length)) + i := 0 + for len(p)-i >= 4 { + putLE32(p[i:], nextRandom()) + i += 4 + } + if i < len(p) { + v := mixRandom() + for n := 0; i+n < len(p); n++ { + p[i+n] = byte(v >> (8 * n)) + } + } +} + +// putLE32 writes v little-endian, matching the memcpy the C version used on +// these little-endian targets. +func putLE32(p []byte, v uint32) { + p[0] = byte(v) + p[1] = byte(v >> 8) + p[2] = byte(v >> 16) + p[3] = byte(v >> 24) +} + +//export esp_random +func esp_random() uint32 { + return nextRandom() +} + +// ─── String ────────────────────────────────────────────────────────────────── + +// strrchr returns a pointer to the last occurrence of c in s, or nil if absent. +// Searching for '\0' returns a pointer to the terminator, per C semantics. +// +//export strrchr +func strrchr(s *C.char, c C.int) *C.char { + target := byte(c) + p := unsafe.Pointer(s) + var last unsafe.Pointer + for { + ch := *(*byte)(p) + if ch == 0 { + break + } + if ch == target { + last = p + } + p = unsafe.Add(p, 1) + } + if target == 0 { + return (*C.char)(p) + } + return (*C.char)(last) +} + +// ─── esp_wifi high-level wrappers → blob internals ─────────────────────────── + +// The blob archives reference these public names while implementing only the +// _internal ones. Go's own connect path calls esp_wifi_connect_internal +// directly (see radio.go), so these exist purely to satisfy the blob. + +//export esp_wifi_connect +func esp_wifi_connect() int32 { + return int32(C.esp_wifi_connect_internal()) +} + +//export esp_wifi_disconnect +func esp_wifi_disconnect() int32 { + return int32(C.esp_wifi_disconnect_internal()) +} From eccd37c7e46ee351a78f480151465b745e60bc7a Mon Sep 17 00:00:00 2001 From: deadprogram Date: Thu, 30 Jul 2026 12:22:24 +0200 Subject: [PATCH 7/9] examples: remove stats logging from apwebserver and webserver examples Signed-off-by: deadprogram --- examples/apwebserver/apwebserver.go | 12 ------------ examples/webserver/webserver.go | 13 ------------- 2 files changed, 25 deletions(-) diff --git a/examples/apwebserver/apwebserver.go b/examples/apwebserver/apwebserver.go index 69fa09d..2b377aa 100644 --- a/examples/apwebserver/apwebserver.go +++ b/examples/apwebserver/apwebserver.go @@ -64,18 +64,6 @@ func main() { http.Handle("/off", logRequest(LED_OFF)) http.Handle("/on", logRequest(LED_ON)) - // Driver counters, printed while traffic is flowing. Most of these count - // something being dropped, so a non-zero value is the only evidence it - // happened. - go func() { - for { - time.Sleep(10 * time.Second) - var stats espradio.Stats - espradio.ReadStats(&stats) - stats.Print() - } - }() - println("HTTP server listening on http://" + apIP + port) err = http.ListenAndServe(apIP+port, nil) if err != nil { diff --git a/examples/webserver/webserver.go b/examples/webserver/webserver.go index 4a9f4e3..8962445 100644 --- a/examples/webserver/webserver.go +++ b/examples/webserver/webserver.go @@ -13,7 +13,6 @@ import ( "tinygo.org/x/drivers/netdev" nl "tinygo.org/x/drivers/netlink" - "tinygo.org/x/espradio" link "tinygo.org/x/espradio/netlink" ) @@ -52,18 +51,6 @@ func main() { http.Handle("/off", logRequest(LED_OFF)) http.Handle("/on", logRequest(LED_ON)) - // Driver counters, printed while traffic is flowing. Most of these count - // something being dropped, so a non-zero value is the only evidence it - // happened. - go func() { - for { - time.Sleep(10 * time.Second) - var stats espradio.Stats - espradio.ReadStats(&stats) - stats.Print() - } - }() - h, _ := link.Addr() host := h.String() println("HTTP server listening on http://" + host + port) From c6b5ba45fdc1ff0483475dd3d7f3a786d712efc7 Mon Sep 17 00:00:00 2001 From: deadprogram Date: Thu, 30 Jul 2026 17:33:56 +0200 Subject: [PATCH 8/9] examples: add soak tests for arena and scheduler counter drift espradio_alloc_stats() had no callers at all before this branch, so nothing ever answered whether the shared arena grows over a long run. These two examples sample AllocCount, FreeCount, ArenaUsed and ArenaCapacity against a post-warmup baseline and report the drift, which is what makes a leak in either the WiFi blob or the BT controller visible rather than inferred. Both also watch the counters that should stay at zero -- cap hits, ring drops, queue-full, RxOversize, a leaked IntsOffNesting -- and print a line only when one moves, so a clean overnight run stays quiet. soak drives the radio with repeated scans. It needs no AP and no network, and scan is the allocation-heaviest single operation the blob has, which makes it the one to run first. soak-traffic connects through netlink and fetches a URL on a loop instead, putting frames through the TX and RX paths. They are separate examples rather than one binary with a mode switch because linking net/http into the scan soak took it from 472 KB to 1198 KB of code for no benefit. The two share their reporting block verbatim. A shared package under examples/ would break smoke-test, whose loop builds every immediate subdirectory as a main package, and examples are better read standalone; diff the two files if they ever drift. Measured on an ESP32-C3, roughly 19 minutes each ------------------------------------------------ No growth in either mode. The scan soak sawtooths -- a scan in flight holds a few hundred bytes -- but every trough returns to exactly 30024 B and 28 outstanding. The traffic soak never moves off 30808 B and 34 at all, because the HTTP path allocates on the Go heap and in the blob's TX buffers rather than the arena. Scheduler rates were 1197 and 1211 passes/s against the 1180 this branch claims, with hwisr/s at 2 and 24. Three things the run corrected in the first draft of these files: - RxDrops does not belong in the quiet list. About 28% of inbound frames were dropped on a full RX ring, steadily, on an ordinary LAN -- 1361 of 4796. Every fetch still succeeded, since TCP retransmits what the ring loses, so it is a capacity signal rather than a fault, and treating it as should-stay-zero made the quiet line fire on every sample and bury the counters that do mean something. It is reported as a share on the rx line instead. - The share is over RxCallbacks alone. espradio_sta_rxcb increments it before testing the ring, so drops are a subset; dividing by callbacks plus drops counted them twice and read 22% instead of 28%. - TxDoneCB does not run well ahead of TxAttempts, as it was documented to. It sat at exactly two ahead for the whole run, presumably association and EAPOL at connect. The blob evidently sends little of its own once associated. Neither soak validates the NO_MEM retry path: nomem stayed at 0 across 1127 TX attempts, so the path this branch added was never reached. The peak line is also a sampled maximum rather than a true high-water mark, and is documented as a lower bound -- it crept from +568 to +672 B purely from sampling phase while the floor held exactly. Verified -------- fmt-check and unit-test pass. Both examples build on xiao-esp32c3, xiao-esp32s3 and esp32-mini32. Signed-off-by: deadprogram --- README.md | 103 ++++++++++++ examples/soak-traffic/main.go | 305 ++++++++++++++++++++++++++++++++++ examples/soak/main.go | 254 ++++++++++++++++++++++++++++ 3 files changed, 662 insertions(+) create mode 100644 examples/soak-traffic/main.go create mode 100644 examples/soak/main.go diff --git a/README.md b/README.md index bb3e05d..5c1ec91 100644 --- a/README.md +++ b/README.md @@ -357,6 +357,109 @@ AP: rems RSSI -59 AP: rems RSSI -79 ``` +### soak + +Long-running memory and scheduler soak test, driven by repeated scanning. +Exercises the radio for hours and reports whether the shared arena drifts, which +is how a leak in either the WiFi blob or the BT controller presents. + +Needs no AP and no network, and scan is the allocation-heaviest single operation +the blob has, so this is the soak to run first: + +``` +$ tinygo flash -target xiao-esp32c3 -monitor ./examples/soak +soak: scan mode +soak 00:00:30 warmup 1/4 arena 30176/49144 B out 29 +soak 00:01:00 warmup 2/4 arena 30384/49144 B out 31 +soak 00:01:30 warmup 3/4 arena 30024/49144 B out 28 +soak 00:02:00 warmup 4/4 arena 30024/49144 B out 28 +soak 00:02:30 BASELINE arena 30024/49144 B out 28 passes/s 1197 hwisr/s 2 +soak 00:03:00 arena 30024/49144 B out 28 drift +0 B / +0 per hr +0 B / +0 work 13/0 +... +soak 00:05:30 arena 30384/49144 B out 31 drift +360 B / +3 per hr +7200 B / +60 work 23/0 + peak arena 30384 B (+360) out 31 (+3) +soak 00:06:00 arena 30592/49144 B out 33 drift +568 B / +5 per hr +9737 B / +85 work 25/0 + peak arena 30592 B (+568) out 33 (+5) +soak 00:06:30 arena 30024/49144 B out 28 drift +0 B / +0 per hr +0 B / +0 work 28/0 + peak arena 30592 B (+568) out 33 (+5) +``` + +Interpreting it: + +- The first four samples are discarded, then a baseline is latched. Bring-up + allocates once, and counting that as growth would report a leak on every run. +- `drift` is arena bytes and outstanding allocations (`AllocCount - FreeCount`) + relative to that baseline, and `per hr` is the same figures extrapolated. +- **Expect a sawtooth, not a flat line.** A scan in flight holds a few hundred + bytes, so a sample reads anywhere from +0 to +672 depending on where the 30s + tick lands. The pass condition is that the troughs return to the *same* floor — + above, exactly 30024 B and 28 outstanding every time across 19 minutes. A leak + raises the floor; a busy allocator only moves the teeth. Ignore `per hr` on an + elevated sample, since it is extrapolating a tooth. +- Watch both drift figures: the outstanding count catches a leak of many small + blocks that barely moves `ArenaUsed`, and `ArenaUsed` catches a leak that + reuses a block but grows it. +- The `peak` line is a sampled maximum, not a true high-water mark — the largest + value seen at a 30s boundary. It understates the real peak, and can creep for a + while purely because a later sample landed nearer the top of a tooth. +- A `QUIET COUNTERS MOVED` line appears only when a counter that should stay at + zero moves — cap hits, ring drops, queue-full, oversize frames, a leaked + critical section. Any of those is a finding on its own, whatever the arena did. + It never appeared in the run above. + +Leave it running for at least an hour; overnight is better, since a slow leak in +a 48 KB arena can take a long time to become visible. + +### soak-traffic + +The same soak driven by real network traffic instead of scans: connects to an AP +and fetches a URL on a loop, so frames go through the TX and RX paths. Run +`./examples/soak` first — this one adds an AP and a server to whatever it is +you are trying to measure. + +Point it at a LAN host rather than a public endpoint, which is what a multi-hour +run wants: + +``` +$ tinygo flash -target xiao-esp32c3 \ + -ldflags="-X main.ssid=yourssid -X main.password=YourPasswordHere -X main.url=http://192.168.1.10/" \ + -monitor ./examples/soak-traffic +soak: traffic mode, ssid yourssid url http://192.168.1.10/ +soak 00:02:30 BASELINE arena 30808/49144 B out 34 passes/s 1211 hwisr/s 24 +soak 00:03:00 arena 30808/49144 B out 34 drift +0 B / +0 per hr +0 B / +0 work 18/0 + tx att 170 nomem 0 retry 0 busy 0 done 172 rx cb 795 drop 208 (26%) ingress-err 364 +... +soak 00:19:30 arena 30808/49144 B out 34 drift +0 B / +0 per hr +0 B / +0 work 116/0 + tx att 1127 nomem 0 retry 0 busy 0 done 1129 rx cb 4796 drop 1361 (28%) ingress-err 1959 +``` + +Output is read the same way as `soak`, with two additions: + +- An extra `tx` line, because this is the mode where the TX path does anything. + `retry` counts NO_MEM rejections the driver retried rather than dropped. +- The trailing `work` pair is completed fetches and failures. Check the failure + count before trusting flat drift — an idle radio leaks nothing, so a soak that + quietly stopped passing traffic looks identical to a clean one. + +Fetch failures are counted rather than fatal, so one DNS hiccup does not end a +run. + +Three things from the measured run above are worth knowing before you read your +own: + +- **The arena does not move at all here**, not even the sawtooth `soak` shows. + The HTTP path allocates on the Go heap and in the blob's own TX buffers, not + the shared arena, so this mode tests the TX/RX counters more than it tests the + arena. Run both. +- **`drop` is not zero and is not expected to be.** Roughly a quarter of inbound + frames were dropped on a full RX ring, steadily, on an ordinary LAN. Every + fetch still succeeded — TCP retransmits what the ring loses — so read it as a + capacity signal rather than a fault. It is reported as a share here instead of + in the quiet-counter list precisely because it fires constantly. +- **`nomem 0, retry 0` means the retry path never ran.** A clean run at this + traffic level is not evidence that NO_MEM handling works, only that it was not + needed. + ### starting Starts the ESP32 radio. diff --git a/examples/soak-traffic/main.go b/examples/soak-traffic/main.go new file mode 100644 index 0000000..41ad559 --- /dev/null +++ b/examples/soak-traffic/main.go @@ -0,0 +1,305 @@ +// This example is a long-running soak test for the driver's memory and scheduler +// counters, driven by real network traffic. It connects to an AP and fetches a +// URL on a loop for hours, reporting whether the arena and the quiet counters +// drift. +// +// This is the counterpart to examples/soak, which drives the same measurement +// with repeated scans and needs no AP. Run that one first: it is the simpler +// setup and scan is the allocation-heaviest single operation the blob has. Run +// this one to put frames through the TX and RX paths, which is what exercises the +// netif ring, the TX retry path and the TX-done callback. +// +// The four arena fields in espradio.Stats -- AllocCount, FreeCount, ArenaUsed and +// ArenaCapacity -- cover both users of the shared pool, WiFi and the BT +// controller. A leak shows up here as outstanding allocations (AllocCount minus +// FreeCount) or ArenaUsed climbing monotonically against a steady workload, which +// is why this reports drift from a post-warmup baseline rather than absolute +// values: the baseline absorbs the one-time allocations of bring-up and DHCP, and +// anything after it is growth. +// +// Point it at a LAN host rather than a public endpoint, which is what a +// multi-hour run wants: +// +// tinygo flash -target xiao-esp32c3 \ +// -ldflags="-X main.ssid=yourssid -X main.password=yourpassword -X main.url=http://192.168.1.10/" \ +// -monitor ./examples/soak-traffic +// +// Fetch failures are counted, not fatal: a soak that dies on one DNS hiccup +// measures nothing. +// +// Reading the output. Every sample line carries the drift since baseline and +// that drift extrapolated to an hour: +// +// soak 00:19:30 arena 30808/49144 B out 34 drift +0 B / +0 per hr +0 B / +0 work 116/0 +// tx att 1127 nomem 0 retry 0 busy 0 done 1129 rx cb 4796 drop 1361 (28%) ingress-err 1959 +// +// That is a real sample from a 19-minute run on an ESP32-C3. The arena did not +// move at all -- not even the sawtooth the scan soak shows -- because the HTTP +// path allocates on the Go heap and the blob's TX buffers, not the shared arena. +// +// The trailing pair is completed fetches and failures. A rising failure count +// with flat drift means the soak stopped measuring anything -- an idle radio +// leaks nothing -- so check it before trusting a clean run. +// +// Flat drift over hours is the pass condition. A per-hour figure that stays +// positive and roughly constant is a leak, and its size tells you the allocation +// site: tens of bytes an hour is a small struct per operation, kilobytes is a +// buffer. Both drift figures matter -- outstanding count catches a leak of many +// small blocks that barely moves ArenaUsed, and ArenaUsed catches a leak that +// reuses a block but grows it. +// +// The QUIET line only appears when a counter that should stay at zero moves. +// Those are the regression detectors described in Stats: cap hits mean a drain +// loop ran out of passes, ring drops and queue-full mean something was thrown +// away, RxOversize means a frame arrived too big for the consumer buffer, and a +// non-zero IntsOffNesting on an idle radio means a blob critical section leaked. +// Any of them appearing is a finding on its own, whatever the arena did. +package main + +import ( + "fmt" + "io" + "net/http" + "time" + + "tinygo.org/x/drivers/netdev" + nl "tinygo.org/x/drivers/netlink" + "tinygo.org/x/espradio" + link "tinygo.org/x/espradio/netlink" +) + +// Linked in with -ldflags. +var ( + ssid string + password string + url = "http://httpbin.org/get" +) + +const ( + // sampleInterval is how often counters are read and reported. Long enough + // that the report is not itself the workload, short enough that an hour of + // run time is a readable series. + sampleInterval = 30 * time.Second + + // warmupSamples is how many samples to discard before latching the baseline. + // Bring-up allocates once -- ROM pointer latching, the supplicant, DHCP -- and + // counting that as drift would report a leak on every run. + warmupSamples = 4 + + // workInterval is the spacing between fetches. + workInterval = 10 * time.Second +) + +// baseline is the counter state that drift is measured against. +type baseline struct { + at time.Time + outstanding int64 + arenaUsed int64 + quiet []uint32 +} + +// quietCounter is a counter whose value is expected to stay at zero for the whole +// run. Anything here moving is a regression, not a measurement. +type quietCounter struct { + name string + read func(*espradio.Stats) uint32 +} + +var quietCounters = []quietCounter{ + {"sched-reentry", func(s *espradio.Stats) uint32 { return s.SchedReentries }}, + {"event-caphit", func(s *espradio.Stats) uint32 { return s.EventCapHits }}, + {"timer-caphit", func(s *espradio.Stats) uint32 { return s.TimerCapHits }}, + {"esptimer-caphit", func(s *espradio.Stats) uint32 { return s.ESPTimerCapHits }}, + {"ints-off-nesting", func(s *espradio.Stats) uint32 { return s.IntsOffNesting }}, + {"isr-ring-drop", func(s *espradio.Stats) uint32 { return s.ISRRingDrops }}, + {"isr-ring-sendfail", func(s *espradio.Stats) uint32 { return s.ISRRingSendFail }}, + {"queue-full", func(s *espradio.Stats) uint32 { return s.QueueSendFull }}, + {"rx-oversize", func(s *espradio.Stats) uint32 { return s.RxOversize }}, + {"rom-ptrs-unready", func(s *espradio.Stats) uint32 { return s.RomPtrsSavedUnready }}, + {"tx-fail-other", func(s *espradio.Stats) uint32 { return s.TxFailOther }}, +} + +// Counters deliberately absent from that list, because non-zero is correct for +// them: YieldsSuppressed and KicksSuppressed are the throttles working, +// RxIngressErrors is any frame the upper stack declines, TxFailNoMem is a +// rejection the retry path then handles, and TxRetries counts those retries. +// +// RxDrops is absent for a different reason, and it is a measurement rather than +// an assumption: a 19-minute run on an ordinary LAN dropped 1361 frames out of +// 4796 handed over by the blob, about 28%, at a steady rate from the first sample +// on. A full RX ring is a capacity limit, not a logic error -- every fetch in +// that run still succeeded, because TCP retransmits what the ring loses -- so +// treating it as a should-stay-zero counter just made the QUIET line fire on +// every single sample and buried the counters that do mean something. It is +// reported as a rate on the rx line below instead, where a rising share is +// visible without drowning out the rest. RxOversize stays in the quiet list: that +// one really should never fire, and it did not. + +// workOK and workErr track the load's progress. +// +// Plain increments rather than atomics: the writer is the work goroutine and the +// reader is the reporter, both cooperatively scheduled on one core, so neither +// can be preempted between the load and the store. +var workOK, workErr uint32 + +func main() { + time.Sleep(2 * time.Second) + + println("soak: traffic mode, ssid", ssid, "url", url) + + // NetConnect enables and starts the radio itself. + l := &link.Esplink{} + netdev.UseNetdev(l) + err := l.NetConnect(&nl.ConnectParams{ + Ssid: ssid, + Passphrase: password, + }) + if err != nil { + failure("WiFi connect failed: " + err.Error()) + } + + // The load runs in the background so a stalled fetch cannot delay a sample. + go work() + report() +} + +// work fetches the URL on a loop, draining each body so any per-request +// allocation on the RX path is completed rather than abandoned. +func work() { + for { + resp, err := http.Get(url) + if err != nil { + workErr++ + } else { + io.Copy(io.Discard, resp.Body) + resp.Body.Close() + workOK++ + } + time.Sleep(workInterval) + } +} + +// report samples the counters forever, latching a baseline once warmup is past +// and printing drift against it. +func report() { + start := time.Now() + var base *baseline + var stats espradio.Stats + var maxUsed, maxOut int64 + + for n := 0; ; n++ { + time.Sleep(sampleInterval) + espradio.ReadStats(&stats) + + out := int64(stats.AllocCount) - int64(stats.FreeCount) + used := int64(stats.ArenaUsed) + + if n < warmupSamples { + fmt.Printf("soak %s warmup %d/%d arena %d/%d B out %d\r\n", + elapsed(start), n+1, warmupSamples, used, stats.ArenaCapacity, out) + continue + } + + if base == nil { + base = &baseline{at: time.Now(), outstanding: out, arenaUsed: used} + for _, q := range quietCounters { + base.quiet = append(base.quiet, q.read(&stats)) + } + maxUsed, maxOut = used, out + fmt.Printf("soak %s BASELINE arena %d/%d B out %d passes/s %d hwisr/s %d\r\n", + elapsed(start), used, stats.ArenaCapacity, out, + stats.SchedPassesPerSec, stats.HWISRPerSec) + continue + } + + driftUsed := used - base.arenaUsed + driftOut := out - base.outstanding + if used > maxUsed { + maxUsed = used + } + if out > maxOut { + maxOut = out + } + + // Per-hour extrapolation from the baseline, in integer arithmetic to keep + // this usable on builds without float formatting. + secs := int64(time.Since(base.at).Seconds()) + if secs < 1 { + secs = 1 + } + fmt.Printf("soak %s arena %d/%d B out %d drift %+d B / %+d per hr %+d B / %+d work %d/%d\r\n", + elapsed(start), used, stats.ArenaCapacity, out, + driftUsed, driftOut, + driftUsed*3600/secs, driftOut*3600/secs, + workOK, workErr) + + // Peaks matter separately from drift: a sawtooth that returns to baseline + // still tells you the high-water mark the arena has to survive. This is a + // lower bound -- the maximum over sample boundaries, not over time. On the + // measured run it never printed at all: traffic left the arena untouched. + if maxUsed > base.arenaUsed || maxOut > base.outstanding { + fmt.Printf(" peak arena %d B (+%d) out %d (+%d)\r\n", + maxUsed, maxUsed-base.arenaUsed, maxOut, maxOut-base.outstanding) + } + + // TX and RX health, on the traffic soak only. + // + // Measured over 19 minutes of fetches on an ordinary LAN: att 1127, nomem 0, + // retry 0, busy 0, done 1129. Two things to take from that. TxDoneCB + // tracks TxAttempts almost exactly -- it ran two ahead for the whole run, + // presumably association and EAPOL at connect -- so it is not the + // far-ahead-of-attempts counter it is documented as; the blob evidently + // sends little of its own once associated. And nomem stayed at zero + // throughout, which means this workload never reaches the NO_MEM retry + // path: a clean run here is not evidence that retry works, only that it was + // not needed. + // RxCallbacks counts every frame the blob hands over, dropped ones included + // (espradio_sta_rxcb increments it before testing the ring), so it is the + // denominator on its own -- adding RxDrops to it would count those twice. + // Both counters are non-atomic by design, so treat the share as approximate. + drop := stats.RxDrops + pct := uint32(0) + if stats.RxCallbacks > 0 { + pct = drop * 100 / stats.RxCallbacks + } + fmt.Printf(" tx att %d nomem %d retry %d busy %d done %d rx cb %d drop %d (%d%%) ingress-err %d\r\n", + stats.TxAttempts, stats.TxFailNoMem, stats.TxRetries, stats.TxBusyWaits, + stats.TxDoneCB, stats.RxCallbacks, drop, pct, stats.RxIngressErrors) + + reportQuiet(base, &stats) + } +} + +// reportQuiet prints a line only when a should-stay-zero counter has moved since +// the baseline, so a clean run stays quiet and a regression is impossible to miss +// in a long scrollback. +func reportQuiet(base *baseline, stats *espradio.Stats) { + first := true + for i, q := range quietCounters { + now := q.read(stats) + if now == base.quiet[i] { + continue + } + if first { + fmt.Printf(" QUIET COUNTERS MOVED:") + first = false + } + fmt.Printf(" %s %d->%d", q.name, base.quiet[i], now) + } + if !first { + fmt.Printf("\r\n") + } +} + +// elapsed formats a duration as hh:mm:ss. +func elapsed(since time.Time) string { + d := int64(time.Since(since).Seconds()) + return fmt.Sprintf("%02d:%02d:%02d", d/3600, (d/60)%60, d%60) +} + +func failure(msg string) { + for { + println("soak failure:", msg) + time.Sleep(5 * time.Second) + } +} diff --git a/examples/soak/main.go b/examples/soak/main.go new file mode 100644 index 0000000..88dd1b8 --- /dev/null +++ b/examples/soak/main.go @@ -0,0 +1,254 @@ +// This example is a long-running soak test for the driver's memory and scheduler +// counters, driven by repeated scanning. It does not test the network: it +// exercises the radio for hours and reports whether the arena and the quiet +// counters drift. +// +// Scan is the allocation-heaviest operation the blob has and it needs no AP and +// no network, which makes this the soak to run first. See examples/soak-traffic +// for the same measurement with frames actually moving through the TX and RX +// paths. +// +// The four arena fields in espradio.Stats -- AllocCount, FreeCount, ArenaUsed and +// ArenaCapacity -- cover both users of the shared pool, WiFi and the BT +// controller. A leak shows up here as outstanding allocations (AllocCount minus +// FreeCount) or ArenaUsed climbing monotonically against a steady workload, which +// is why this reports drift from a post-warmup baseline rather than absolute +// values: the baseline absorbs the one-time allocations of bring-up, and anything +// after it is growth. +// +// No configuration is needed: +// +// tinygo flash -target xiao-esp32c3 -monitor ./examples/soak +// +// Reading the output. Every sample line carries the drift since baseline and +// that drift extrapolated to an hour: +// +// soak 00:18:30 arena 30024/49144 B out 28 drift +0 B / +0 per hr +0 B / +0 work 78/0 +// soak 00:19:00 arena 30384/49144 B out 31 drift +360 B / +3 per hr +1728 B / +14 work 80/0 +// peak arena 30696 B (+672) out 34 (+6) +// +// The trailing pair is completed scans and failures. +// +// Flat drift over hours is the pass condition. A per-hour figure that stays +// positive and roughly constant is a leak, and its size tells you the allocation +// site: tens of bytes an hour is a small struct per operation, kilobytes is a +// buffer. Both drift figures matter -- outstanding count catches a leak of many +// small blocks that barely moves ArenaUsed, and ArenaUsed catches a leak that +// reuses a block but grows it. +// +// Expect a sawtooth here rather than a flat line, as in the sample above: a scan +// in flight holds a few hundred bytes and half a dozen allocations, so whether a +// sample reads +0 or +672 depends on where the 30 s tick lands relative to the +// scan. What matters is that the troughs return to the *same* floor -- 30024 B +// and 28 outstanding, exactly, over a measured 19 minutes on an ESP32-C3. A leak +// raises the floor; a busy allocator just moves the teeth. +// +// The peak line is a sampled maximum, not a true high-water mark: it is the +// largest value seen at a 30 s boundary, so it understates the real peak and can +// creep upward for a while purely because a later sample happened to land closer +// to the top of a tooth. Read it as a lower bound. +// +// The QUIET line only appears when a counter that should stay at zero moves. +// Those are the regression detectors described in Stats: cap hits mean a drain +// loop ran out of passes, ring drops and queue-full mean something was thrown +// away, RxOversize means a frame arrived too big for the consumer buffer, and a +// non-zero IntsOffNesting on an idle radio means a blob critical section leaked. +// Any of them appearing is a finding on its own, whatever the arena did. +package main + +import ( + "fmt" + "time" + + "tinygo.org/x/espradio" +) + +const ( + // sampleInterval is how often counters are read and reported. Long enough + // that the report is not itself the workload, short enough that an hour of + // run time is a readable series. + sampleInterval = 30 * time.Second + + // warmupSamples is how many samples to discard before latching the baseline. + // Bring-up allocates once -- ROM pointer latching, the supplicant -- and + // counting that as drift would report a leak on every run. + warmupSamples = 4 + + // workInterval is the spacing between scans. + workInterval = 10 * time.Second +) + +// baseline is the counter state that drift is measured against. +type baseline struct { + at time.Time + outstanding int64 + arenaUsed int64 + quiet []uint32 +} + +// quietCounter is a counter whose value is expected to stay at zero for the whole +// run. Anything here moving is a regression, not a measurement. +type quietCounter struct { + name string + read func(*espradio.Stats) uint32 +} + +var quietCounters = []quietCounter{ + {"sched-reentry", func(s *espradio.Stats) uint32 { return s.SchedReentries }}, + {"event-caphit", func(s *espradio.Stats) uint32 { return s.EventCapHits }}, + {"timer-caphit", func(s *espradio.Stats) uint32 { return s.TimerCapHits }}, + {"esptimer-caphit", func(s *espradio.Stats) uint32 { return s.ESPTimerCapHits }}, + {"ints-off-nesting", func(s *espradio.Stats) uint32 { return s.IntsOffNesting }}, + {"isr-ring-drop", func(s *espradio.Stats) uint32 { return s.ISRRingDrops }}, + {"isr-ring-sendfail", func(s *espradio.Stats) uint32 { return s.ISRRingSendFail }}, + {"queue-full", func(s *espradio.Stats) uint32 { return s.QueueSendFull }}, + {"rx-drop", func(s *espradio.Stats) uint32 { return s.RxDrops }}, + {"rx-oversize", func(s *espradio.Stats) uint32 { return s.RxOversize }}, + {"rom-ptrs-unready", func(s *espradio.Stats) uint32 { return s.RomPtrsSavedUnready }}, + {"tx-fail-other", func(s *espradio.Stats) uint32 { return s.TxFailOther }}, +} + +// Counters deliberately absent from that list, because non-zero is correct for +// them: YieldsSuppressed and KicksSuppressed are the throttles working, +// RxIngressErrors is any frame the upper stack declines, TxFailNoMem is a +// rejection the retry path then handles, and TxRetries counts those retries. + +// workOK and workErr track the load's progress. Reported so a run that silently +// stopped doing anything is not mistaken for a run with flat drift -- an idle +// radio leaks nothing. +// +// Plain increments rather than atomics: the writer is the work goroutine and the +// reader is the reporter, both cooperatively scheduled on one core, so neither +// can be preempted between the load and the store. +var workOK, workErr uint32 + +func main() { + time.Sleep(2 * time.Second) + + println("soak: scan mode") + if err := espradio.Enable(espradio.Config{}); err != nil { + failure("could not enable radio: " + err.Error()) + } + if err := espradio.Start(); err != nil { + failure("could not start radio: " + err.Error()) + } + + // The load runs in the background so a slow scan cannot delay a sample. + go work() + report() +} + +// work scans on a loop, discarding the results. What matters is the allocation +// the blob does to produce them, not the APs. +func work() { + for { + if _, err := espradio.Scan(); err != nil { + workErr++ + } else { + workOK++ + } + time.Sleep(workInterval) + } +} + +// report samples the counters forever, latching a baseline once warmup is past +// and printing drift against it. +func report() { + start := time.Now() + var base *baseline + var stats espradio.Stats + var maxUsed, maxOut int64 + + for n := 0; ; n++ { + time.Sleep(sampleInterval) + espradio.ReadStats(&stats) + + out := int64(stats.AllocCount) - int64(stats.FreeCount) + used := int64(stats.ArenaUsed) + + if n < warmupSamples { + fmt.Printf("soak %s warmup %d/%d arena %d/%d B out %d\r\n", + elapsed(start), n+1, warmupSamples, used, stats.ArenaCapacity, out) + continue + } + + if base == nil { + base = &baseline{at: time.Now(), outstanding: out, arenaUsed: used} + for _, q := range quietCounters { + base.quiet = append(base.quiet, q.read(&stats)) + } + maxUsed, maxOut = used, out + fmt.Printf("soak %s BASELINE arena %d/%d B out %d passes/s %d hwisr/s %d\r\n", + elapsed(start), used, stats.ArenaCapacity, out, + stats.SchedPassesPerSec, stats.HWISRPerSec) + continue + } + + driftUsed := used - base.arenaUsed + driftOut := out - base.outstanding + if used > maxUsed { + maxUsed = used + } + if out > maxOut { + maxOut = out + } + + // Per-hour extrapolation from the baseline, in integer arithmetic to keep + // this usable on builds without float formatting. + secs := int64(time.Since(base.at).Seconds()) + if secs < 1 { + secs = 1 + } + fmt.Printf("soak %s arena %d/%d B out %d drift %+d B / %+d per hr %+d B / %+d work %d/%d\r\n", + elapsed(start), used, stats.ArenaCapacity, out, + driftUsed, driftOut, + driftUsed*3600/secs, driftOut*3600/secs, + workOK, workErr) + + // Peaks matter separately from drift: a sawtooth that returns to baseline + // still tells you the high-water mark the arena has to survive. This is a + // lower bound -- the maximum over sample boundaries, not over time -- so it + // can creep for a while just from sampling phase. Measured on a C3: the + // floor held exactly while this reached +672 B. + if maxUsed > base.arenaUsed || maxOut > base.outstanding { + fmt.Printf(" peak arena %d B (+%d) out %d (+%d)\r\n", + maxUsed, maxUsed-base.arenaUsed, maxOut, maxOut-base.outstanding) + } + + reportQuiet(base, &stats) + } +} + +// reportQuiet prints a line only when a should-stay-zero counter has moved since +// the baseline, so a clean run stays quiet and a regression is impossible to miss +// in a long scrollback. +func reportQuiet(base *baseline, stats *espradio.Stats) { + first := true + for i, q := range quietCounters { + now := q.read(stats) + if now == base.quiet[i] { + continue + } + if first { + fmt.Printf(" QUIET COUNTERS MOVED:") + first = false + } + fmt.Printf(" %s %d->%d", q.name, base.quiet[i], now) + } + if !first { + fmt.Printf("\r\n") + } +} + +// elapsed formats a duration as hh:mm:ss. +func elapsed(since time.Time) string { + d := int64(time.Since(since).Seconds()) + return fmt.Sprintf("%02d:%02d:%02d", d/3600, (d/60)%60, d%60) +} + +func failure(msg string) { + for { + println("soak failure:", msg) + time.Sleep(5 * time.Second) + } +} From fd3dd04145361a4def4f25f9fcde5452fca05dea Mon Sep 17 00:00:00 2001 From: deadprogram Date: Thu, 30 Jul 2026 19:57:31 +0200 Subject: [PATCH 9/9] wifi: distinguish a failed Enable from an already-enabled radio Review feedback on #59 pointed out that wifiEnabled is set by the CAS at the top of Enable, so a failure in espradio_wifi_init leaves it at 1 and every later Enable returns ErrAlreadyEnabled. That much is correct: wifiEnabled was written in exactly one place and never reset, and there is no Disable or deinit anywhere in the tree. Neither suggested fix works here, though. Setting the flag only after a successful init would open a hole rather than close one. The CAS is not just recording state, it is the mutual-exclusion guard, and Enable yields partway through -- the ticker settle is a real scheduling point under cooperative scheduling. Move the latch to the end and a second caller arriving during that sleep runs the whole body concurrently, re-registering the CPU interrupt and re-entering blob init. Both NetConnect and the AP path call Enable, so that is a reachable state, and it is worse than a stuck flag. Reverting the partial setup on the error path is the right shape but has nothing to build on. By the time the blob init can fail, the ISR tables are zeroed, the arena is laid out, the ticker goroutine is running with no way to stop it, the CPU interrupt is registered and prioritised, the routing is prewired, the event callback is registered and the HAL clocks are up. None of that has teardown code, and without an esp_wifi_deinit binding the blob cannot be put back either. A partial unwind would leave a half-initialised radio that reports itself ready. So the failure stays terminal, and what changes is that it says so. wifiEnabled becomes three-state -- off, on, failed -- and every error return in Enable goes through enableFailed(), which records the terminal state on the way out. A caller that retries now gets ErrEnableFailed, "earlier Enable failed, reset required", instead of being told the radio is already enabled and sent looking in the wrong place. The CAS stays exactly where it was. enableFailed is a package-level function rather than a closure inside Enable, so the init path does not allocate where it does not have to. Also here: Enable now checks initHardware's error instead of discarding it, matching BLEInit, which has always checked it. Every target returns nil today, so this is a guard against a future one that does not rather than a fix for an observed failure. Verified -------- fmt-check, unit-test and smoke-test (13 examples x 3 targets) pass. On hardware, ESP32-C3: scan and apwebserver, plus heartrate and heartrate-monitor on the BLE side, since Enable shares initHardware and the arena with BLEInit. Signed-off-by: deadprogram --- radio.go | 59 +++++++++++++++++++++++++++++++++++++++++++++++++------- 1 file changed, 52 insertions(+), 7 deletions(-) diff --git a/radio.go b/radio.go index 3103de8..29e82eb 100644 --- a/radio.go +++ b/radio.go @@ -483,19 +483,60 @@ func ArenaStats() (used, capacity uint32) { return uint32(u), uint32(c) } -// wifiEnabled guards Enable against a second call. Re-running it would -// re-initialise the arena under the blob's live pointers, start a second ticker -// goroutine and re-register the ISR. +// Enable state, held in wifiEnabled. +// +// The transition off -> on is a CAS, and it does double duty: it rejects a second +// Enable, and it excludes a concurrent one. Both matter. Re-running Enable +// would re-register the ISR and re-enter blob init, and Enable yields partway +// through -- the ticker settle below is a real scheduling point under cooperative +// scheduling -- so a second caller can arrive mid-init. Both NetConnect and the +// AP path call Enable, so that is not hypothetical. Latching the state only on +// success would leave that window open, which is why the CAS stays at the top. +// +// wifiStateFailed exists because Enable cannot be retried. By the time the blob +// init below can fail, the ISR tables are zeroed, the arena is laid out, the +// ticker goroutine is running with no way to stop it, the CPU interrupt is +// registered and prioritised, the interrupt routing is prewired, the event +// callback is registered and the HAL clocks are up. None of that has teardown +// code, and there is no esp_wifi_deinit binding to put the blob back either. So +// the failure is terminal, and the state records that rather than pretending the +// radio is merely already enabled. +const ( + wifiStateOff uint32 = iota + wifiStateOn + wifiStateFailed +) + var wifiEnabled uint32 // ErrAlreadyEnabled is returned by Enable when the radio is already enabled. var ErrAlreadyEnabled = errors.New("espradio: radio already enabled") +// ErrEnableFailed is returned by Enable when an earlier call to it failed. That +// failure is not recoverable in software: the driver has no teardown path, so the +// device has to be reset before the radio can be brought up again. +var ErrEnableFailed = errors.New("espradio: earlier Enable failed, reset required") + +// enableFailed marks the Enable state terminal on the way out. Every error +// return in Enable goes through it, so a caller that retries gets +// ErrEnableFailed rather than the misleading ErrAlreadyEnabled. A package-level +// function rather than a closure inside Enable: nothing in the driver's init path +// should allocate when it does not have to. +func enableFailed(err error) error { + atomic.StoreUint32(&wifiEnabled, wifiStateFailed) + return err +} + // Enable and configure the radio for WiFi. // -// Enable is not idempotent and returns ErrAlreadyEnabled on a second call. +// Enable is not idempotent and returns ErrAlreadyEnabled on a second call. If an +// earlier call failed, every later one returns ErrEnableFailed: a partially +// initialised radio cannot be unwound, so the device must be reset. func Enable(config Config) error { - if !atomic.CompareAndSwapUint32(&wifiEnabled, 0, 1) { + if !atomic.CompareAndSwapUint32(&wifiEnabled, wifiStateOff, wifiStateOn) { + if atomic.LoadUint32(&wifiEnabled) == wifiStateFailed { + return ErrEnableFailed + } return ErrAlreadyEnabled } @@ -521,7 +562,11 @@ func Enable(config Config) error { startSchedTicker() } time.Sleep(schedTickerMs * time.Millisecond) - initHardware() + // Checked rather than discarded, matching BLEInit. Every target returns nil + // today, so this is a guard against a future one that does not. + if err := initHardware(); err != nil { + return enableFailed(err) + } C.espradio_ensure_osi_ptr() wifiISR = interrupt.New(wifiCPUInterrupt, wifiISRHandler) @@ -539,7 +584,7 @@ func Enable(config Config) error { errCode := C.espradio_wifi_init() if errCode != 0 { - return makeError(errCode) + return enableFailed(makeError(errCode)) } C.espradio_wifi_init_completed() C.espradio_wifi_int_to_level()