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/ble.go b/ble.go index c4370a4..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 } @@ -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..0ddc398 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; @@ -443,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; @@ -475,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); @@ -564,9 +575,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 +702,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..5dbcb13 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); @@ -107,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/examples/scan/main.go b/examples/scan/main.go index 8ca2a8b..ea41c09 100644 --- a/examples/scan/main.go +++ b/examples/scan/main.go @@ -39,6 +39,12 @@ 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. + var stats espradio.Stats + espradio.ReadStats(&stats) + stats.Print() println() time.Sleep(10 * time.Second) 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) + } +} 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/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()) +} 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..827cc35 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 ReadStats 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; ReadStats().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..c94602c 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, ReadStats 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..29e82eb 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,139 @@ func startSchedTicker() { var wifiInitDone uint32 -func schedOnce() { +// ─── Scheduler policy (runtime-switchable, for A/B on hardware) ────────────── + +// 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. 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. + // + // 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 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) + +// setSchedPolicy replaces the scheduler policy mask. Intended for bisecting +// behaviour on hardware; the default is the historical behaviour. +func setSchedPolicy(p schedPolicyMask) { atomic.StoreUint32(&schedPolicy, uint32(p)) } + +// getSchedPolicy returns the current scheduler policy mask. +func getSchedPolicy() schedPolicyMask { return schedPolicyMask(atomic.LoadUint32(&schedPolicy)) } + +func schedPolicyHas(p schedPolicyMask) 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: 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 + // ~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 +268,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 +286,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 +372,104 @@ 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. Not +// exported: a bisecting knob for this package's own bring-up, not public API. +func setKickThrottleUs(us uint32) { atomic.StoreUint32(&kickThrottleUs, us) } + +// 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 +// 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,19 +483,90 @@ func ArenaStats() (used, capacity uint32) { return uint32(u), uint32(c) } +// 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. 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 { - // Allocate arena pool from Go heap and hand it to C. - poolSize := arenaPoolSize - if config.ArenaPoolSize > 0 { - poolSize = config.ArenaPoolSize + if !atomic.CompareAndSwapUint32(&wifiEnabled, wifiStateOff, wifiStateOn) { + if atomic.LoadUint32(&wifiEnabled) == wifiStateFailed { + return ErrEnableFailed + } + 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() + // 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) @@ -227,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() @@ -281,9 +638,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 +668,244 @@ 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) +} + +// 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) + 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() +} + +// 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 +913,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 +982,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 +1123,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 +1139,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 +1208,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 -- 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 ( + 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 + } + 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)) } - interrupt.Restore(interrupt.State(tmp)) + _ = tmp } var wifiISR interrupt.Interrupt @@ -628,6 +1307,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 +1317,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 +1433,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 +1448,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 +1477,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 +1506,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 +1535,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 +1556,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 +1577,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() } 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) }