Init-time investigation: per-stage instrumentation, bench harness, TX-ready −5s, libusb WARNING default

CLAUDE.md

@@ -79,6 +79,14 @@ Three specialised modes layered on top of the default 4-cell matrix:
   `--encoding-matrix` are NOT authoritative for LDPC/STBC asymmetries
   (MCS index + HT/VHT distinction do survive).
 
+Init/startup-time benchmarking lives in `tests/bench_init.py`: per-DUT
+cold-init timing of devourer RX (`exec → first RX frame`), devourer TX
+(`exec → first bulk-OUT`), and — with `--vm-name`/`--vm-ssh` — the kernel
+driver (`virsh attach → monitor up → first frame`). Per-stage numbers come
+from the `init-timing: <scope>.<stage> = N ms` lines the library emits
+(`src/InitTimer.h`); A/B variants isolate libusb log level, USB reset, and
+the TX-power loop.
+
 DUTs are routed between host and VM per cell via `virsh attach-device`.
 Re-run with `--keep-logs` to inspect per-cell logs (and per-cell pcaps
 when `--sniffer-iface` is active) at `/tmp/devourer-regress-last/`. See
@@ -98,8 +106,10 @@ Both `WiFiDriverDemo` and `WiFiDriverTxDemo` honour:
 - `DEVOURER_SKIP_TXPWR=1` — skip the per-rate TX-power loop during channel
   switch (runs by default on every chip; escape hatch for RX-only
   experiments).
-- `DEVOURER_USB_QUIET=1` — downgrade libusb log level from DEBUG to WARNING
-  (DEBUG produces ~7 MB per 15 s and has filled `/tmp` mid-capture).
+- `DEVOURER_USB_DEBUG=1` — raise libusb log level from the default WARNING to
+  DEBUG (produces ~7 MB per 15 s — has filled `/tmp` mid-capture and adds
+  0.5-0.8 s to init even with stderr discarded). `DEVOURER_USB_QUIET` is
+  accepted as a no-op for backwards compatibility.
 
 `WiFiDriverTxDemo` additionally honours radiotap-encoding knobs that
 patch the beacon's MCS info field (or, with `_VHT=1`, replace it with a

README.md

@@ -119,8 +119,9 @@ Common to both demos:
 - `DEVOURER_DUMP_CANARY=1` — emit a canonical post-channel-set dump of
   BB/MAC/RF anchor registers. Feeds the `tests/canary_diff.py`
   cross-validation tool against `tools/canary_kernel_dump.sh` output.
-- `DEVOURER_USB_QUIET=1` — downgrade libusb log level from DEBUG to
-  WARNING (DEBUG produces ~7 MB per 15 s and can fill `/tmp` mid-capture).
+- `DEVOURER_USB_DEBUG=1` — raise libusb log level from the default WARNING
+  to DEBUG (produces ~7 MB per 15 s, can fill `/tmp` mid-capture, and slows
+  init measurably). `DEVOURER_USB_QUIET` is accepted as a no-op.
 
 `WiFiDriverTxDemo`-only knobs patch the canonical beacon's radiotap
 header before the TX loop:
@@ -175,6 +176,15 @@ on the kernel-TX path, so the `kernel`-TX rows of `--encoding-matrix`
 are not authoritative for LDPC/STBC asymmetries — devourer-TX rows
 ARE).
 
+### Startup time
+
+Devourer reaches ready-to-RX/TX faster than the `aircrack-ng/88XXau`
+kernel driver on every supported chip, in both directions (RTL8812AU
+~2s, RTL8814AU ~6s, RTL8821AU ~1s cold-init to first frame). Run your
+own numbers with `tests/bench_init.py` — it benchmarks cold init per
+adapter, devourer vs kernel driver, with a per-stage breakdown from the
+library's `init-timing:` log lines.
+
 ## Project layout
 
 ```

demo/main.cpp

@@ -31,6 +31,17 @@ static constexpr uint16_t kRealtekProductIds[] = {
 static int g_rx_count = 0;
 static RtlJaguarDevice *g_rtl_device = nullptr;
 
+/* Process-start reference for the init-timing lines (see src/InitTimer.h).
+ * `init-timing: demo.first_rx_frame` is the end-to-end "ready to RX" mark:
+ * exec → first 802.11 frame delivered to the packet processor. */
+static const std::chrono::steady_clock::time_point g_proc_start =
+    std::chrono::steady_clock::now();
+static long long ms_since_start() {
+  return std::chrono::duration_cast<std::chrono::milliseconds>(
+             std::chrono::steady_clock::now() - g_proc_start)
+      .count();
+}
+
 /* DEVOURER_TX_STATUS=1: surface chip-side C2H frames (TX status reports,
  * various diagnostic pings) on `<devourer-c2h>` with a raw hex dump, plus
  * a best-effort decode of the 8814A TX_RPT payload layout. The C2H
@@ -122,6 +133,12 @@ static void packetProcessor(const Packet &packet) {
 
   ++g_rx_count;
 
+  if (g_rx_count == 1) {
+    printf("<devourer>init-timing: demo.first_rx_frame = %lld ms\n",
+           ms_since_start());
+    fflush(stdout);
+  }
+
   if (g_rx_count <= 10 || g_rx_count % 100 == 0) {
     printf("<devourer>RX pkt #%d (len=%zu)\n", g_rx_count, packet.Data.size());
     fflush(stdout);
@@ -272,14 +289,16 @@ int main() {
     return rc;
   }
 
-  /* libusb log level: DEBUG by default (matches historic behaviour); a single
-   * DEVOURER_USB_QUIET=1 knob downgrades to WARNING to keep capture logs
-   * manageable. DEBUG output runs ~7 MB per 15s run, which has filled /tmp
-   * and wedged the harness on previous sessions. */
+  /* libusb log level: WARNING by default. DEBUG is opt-in via
+   * DEVOURER_USB_DEBUG=1 — it emits ~7 MB per 15s run (has filled /tmp and
+   * wedged the harness), and bench_init.py measured it adding 0.5-0.8s to
+   * time-to-first-RX-frame even with stderr discarded; on a slow sink
+   * (SSH/serial/embedded flash) the cost is unbounded. DEVOURER_USB_QUIET
+   * is accepted as a no-op for backwards compatibility with older scripts. */
   libusb_set_option(ctx, LIBUSB_OPTION_LOG_LEVEL,
-                    std::getenv("DEVOURER_USB_QUIET")
-                        ? LIBUSB_LOG_LEVEL_WARNING
-                        : LIBUSB_LOG_LEVEL_DEBUG);
+                    std::getenv("DEVOURER_USB_DEBUG")
+                        ? LIBUSB_LOG_LEVEL_DEBUG
+                        : LIBUSB_LOG_LEVEL_WARNING);
 
   /* DEVOURER_PID env var (hex, e.g. "0x8813") restricts the open loop to a
    * single PID. Useful when multiple Realtek adapters are plugged.
@@ -329,16 +348,19 @@ int main() {
   /* Skip USB reset if DEVOURER_SKIP_RESET=1. Used when picking up a chip
    * with firmware already running (e.g. after a patched-rtw88 sysfs unbind):
    * USB reset would clobber fw state and force us to re-run fwdl. */
+  logger->info("init-timing: demo.open_device = {} ms", ms_since_start());
   if (!std::getenv("DEVOURER_SKIP_RESET")) {
     libusb_reset_device(dev_handle);
   } else {
     logger->info("DEVOURER_SKIP_RESET set — skipping libusb_reset_device");
   }
+  logger->info("init-timing: demo.usb_reset = {} ms", ms_since_start());
   rc = libusb_claim_interface(dev_handle, 0);
   assert(rc == 0);
 
   WiFiDriver wifi_driver(logger);
   auto rtlDevice = wifi_driver.CreateRtlDevice(dev_handle);
+  logger->info("init-timing: demo.create_device = {} ms", ms_since_start());
   g_rtl_device = rtlDevice.get();
   std::atomic<bool> qd_emitter_stop{false};
   std::thread qd_emitter;

src/EepromManager.cpp

@@ -1,5 +1,6 @@
 #include "EepromManager.h"
 
+#include "InitTimer.h"
 #include "phydm_pre_define.h"
 #include "registry_priv.h"
 #include "rtl8812a_hal.h"
@@ -26,7 +27,9 @@ static int devourer_strcaseeq(const char *a, const char *b) {
 
 EepromManager::EepromManager(RtlUsbAdapter device, Logger_t logger)
     : _device{device}, _logger{logger} {
+  InitTimer timer(logger, "eeprom");
   read_chip_version_8812a(device);
+  timer.stage("chip_version");
 
   /* On 8814AU, defer all EFUSE access until AFTER firmware download. rtw88's
    * usbmon shows zero touches to EFUSE_CTRL (0x0031-0x0033) and EFUSE_ACCESS
@@ -43,6 +46,7 @@ EepromManager::EepromManager(RtlUsbAdapter device, Logger_t logger)
   } else {
     hal_InitPGData_8812A();
   }
+  timer.stage("efuse_read");
 
   Hal_EfuseParseIDCode8812A();
   EEPROMVersion = Hal_ReadPROMVersion8812A(_device, efuse_eeprom_data);
@@ -76,6 +80,8 @@ EepromManager::EepromManager(RtlUsbAdapter device, Logger_t logger)
   if (version_id.ICType != CHIP_8814A) {
     hal_ReadUsbType_8812AU();
   }
+  timer.stage("parse");
+  timer.total();
 }
 
 void EepromManager::LateInitFor8814A() {
@@ -87,8 +93,10 @@ void EepromManager::LateInitFor8814A() {
   if (version_id.ICType != CHIP_8814A) {
     return;
   }
+  InitTimer timer(_logger, "eeprom_late");
   _device.AutoloadFailFlag = false;
   hal_InitPGData_8812A();
+  timer.stage("efuse_read");
   Hal_EfuseParseIDCode8812A();
   EEPROMVersion = Hal_ReadPROMVersion8812A(_device, efuse_eeprom_data);
   EEPROMRegulatory = Hal_ReadTxPowerInfo8812A(_device, efuse_eeprom_data);
@@ -108,6 +116,8 @@ void EepromManager::LateInitFor8814A() {
                 "PA_2G/5G=0x{:X}/0x{:X} LNA_2G/5G=0x{:X}/0x{:X}",
                 rfe_type, crystal_cap, PAType_2G, PAType_5G,
                 LNAType_2G, LNAType_5G);
+  timer.stage("parse");
+  timer.total();
 }
 
 /* RTL8821AU is Jaguar-family silicon (CHIP_8821 = 7 in Realtek's HalVerDef),

src/HalModule.cpp

@@ -1,6 +1,7 @@
 #include "HalModule.h"
 
 #include "FirmwareManager.h"
+#include "InitTimer.h"
 #include "Hal8812PhyReg.h"
 #include "Hal8814_PhyTables.h"
 #include "Hal8821PhyReg.h"
@@ -73,11 +74,15 @@ HalModule::HalModule(
       _eepromManager{eepromManager}, _logger{logger} {}
 
 bool HalModule::rtw_hal_init(SelectedChannel selectedChannel) {
+  InitTimer timer(_logger, "hal");
   auto status = rtl8812au_hal_init(selectedChannel.Channel);
 
   if (status) {
+    timer.stage("chip_init");
     _radioManagementModule->init_hw_mlme_ext(selectedChannel);
     _radioManagementModule->SetMonitorMode();
+    timer.stage("mlme_monitor");
+    timer.total();
 
     /* Construct + start the phydm DM watchdog after chip init is
      * complete. Tick once synchronously so the first canary capture
@@ -109,6 +114,7 @@ bool HalModule::rtw_hal_init(SelectedChannel selectedChannel) {
 }
 
 bool HalModule::rtl8812au_hal_init(uint8_t init_channel) {
+  InitTimer timer(_logger, "hal_init");
   // Check if MAC has already power on. by tynli. 2011.05.27.
   auto value8 = _device.rtw_read8(REG_SYS_CLKR + 1);
   auto regCr = _device.rtw_read8(REG_CR);
@@ -159,6 +165,7 @@ bool HalModule::rtl8812au_hal_init(uint8_t init_channel) {
       return false;
     }
   }
+  timer.stage("power_on");
 
   /* LLT table init: 8812 needs it pre-fw download; 8814AU does NOT — rtw88
    * runs LLT init AFTER fw boot, and doing it pre-fw on 8814 breaks the
@@ -173,18 +180,22 @@ bool HalModule::rtl8812au_hal_init(uint8_t init_channel) {
   }
 
   _InitHardwareDropIncorrectBulkOut_8812A();
+  timer.stage("llt");
 
   auto fwManager = std::make_unique<FirmwareManager>(_device, _logger);
   fwManager->FirmwareDownload(_eepromManager->version_id.ICType);
+  timer.stage("fwdl");
 
   /* 8814AU: now that fw is running, the chip will accept EFUSE reads
    * without breaking RSVD-page fwdl (which is past). Read the board's
    * actual rfe_type, PA/LNA types, crystal cap, etc., so that
    * GetPhyContext() returns real values to PhyTableLoader instead of
    * the fallback rfe_type=1 used pre-EFUSE-read. */
   _eepromManager->LateInitFor8814A();
+  timer.stage("efuse_late");
 
   PHY_MACConfig8812();
+  timer.stage("mac_cfg");
 
   if (is_8814a) {
     /* 8814AU has its own TX FIFO page allocation: 2048 total pages vs 8812's
@@ -247,6 +258,7 @@ bool HalModule::rtl8812au_hal_init(uint8_t init_channel) {
       _InitTransferPageSize_8812AUsb();
     }
   }
+  timer.stage("queue_fifo");
 
   // Get Rx PHY status in order to report RSSI and others.
   _InitDriverInfoSize_8812A(DRVINFO_SZ);
@@ -292,6 +304,7 @@ bool HalModule::rtl8812au_hal_init(uint8_t init_channel) {
 
   _device.rtw_write16(REG_PKT_VO_VI_LIFE_TIME, 0x0400); /* unit: 256us. 256ms */
   _device.rtw_write16(REG_PKT_BE_BK_LIFE_TIME, 0x0400); /* unit: 256us. 256ms */
+  timer.stage("mac_misc");
 
   /* 8814AU BB/RF domain power-on. Without these writes, the chip's BB
    * register space (0x800-0xFFF) silently rejects writes via vendor
@@ -329,8 +342,10 @@ bool HalModule::rtl8812au_hal_init(uint8_t init_channel) {
   if (bbConfig8812Status == false) {
     return false;
   }
+  timer.stage("bb_config");
 
   PHY_RF6052_Config_8812();
+  timer.stage("rf_config");
 
   phydm_SetIgiFloor_Jaguar();
 
@@ -401,10 +416,12 @@ bool HalModule::rtl8812au_hal_init(uint8_t init_channel) {
   } else {
     _radioManagementModule->PHY_SwitchWirelessBand8812(init_band);
   }
+  timer.stage("band_switch");
 
   _radioManagementModule->rtw_hal_set_chnl_bw(
       init_channel, ChannelWidth_t::CHANNEL_WIDTH_20,
       HAL_PRIME_CHNL_OFFSET_DONT_CARE, HAL_PRIME_CHNL_OFFSET_DONT_CARE);
+  timer.stage("channel_set");
 
   // HW SEQ CTRL
   // set 0x0 to 0xFF by tynli. Default enable HW SEQ NUM.
@@ -634,6 +651,8 @@ bool HalModule::rtl8812au_hal_init(uint8_t init_channel) {
     _logger->info("8814A: trace-derived post-fwdl writes applied");
   }
 
+  timer.stage("post_init");
+  timer.total();
   return true;
 }
 

src/InitTimer.h

@@ -0,0 +1,48 @@
+#ifndef INIT_TIMER_H
+#define INIT_TIMER_H
+
+#include <chrono>
+#include <utility>
+
+#include "logger.h"
+
+/* Stage timer for init-path profiling. Emits one info line per checkpoint:
+ *
+ *   init-timing: <scope>.<stage> = <N> ms
+ *
+ * `stage()` reports time since the previous checkpoint (or construction);
+ * `total()` reports time since construction. Always-on: a handful of log
+ * lines per init, negligible next to the USB transfers being measured.
+ * tests/bench_init.py parses these lines. */
+class InitTimer {
+  using clock = std::chrono::steady_clock;
+
+public:
+  InitTimer(Logger_t logger, const char *scope)
+      : _logger{std::move(logger)}, _scope{scope}, _start{clock::now()},
+        _last{_start} {}
+
+  void stage(const char *name) {
+    const auto now = clock::now();
+    _logger->info("init-timing: {}.{} = {} ms", _scope, name, ms(_last, now));
+    _last = now;
+  }
+
+  void total() {
+    _logger->info("init-timing: {}.total = {} ms", _scope,
+                  ms(_start, clock::now()));
+  }
+
+private:
+  static long long ms(clock::time_point from, clock::time_point to) {
+    return std::chrono::duration_cast<std::chrono::milliseconds>(to - from)
+        .count();
+  }
+
+  Logger_t _logger;
+  const char *_scope;
+  clock::time_point _start;
+  clock::time_point _last;
+};
+
+#endif /* INIT_TIMER_H */

src/RadioManagementModule.cpp

@@ -1,5 +1,6 @@
 #include "RadioManagementModule.h"
 #include "Hal8812PhyReg.h"
+#include "InitTimer.h"
 #include "registry_priv.h"
 
 extern "C" {
@@ -265,15 +266,18 @@ void RadioManagementModule::PHY_HandleSwChnlAndSetBW8812(
 }
 
 void RadioManagementModule::phy_SwChnlAndSetBwMode8812() {
+  InitTimer timer(_logger, "channel_set");
   if (_swChannel) {
     phy_SwChnl8812();
     _swChannel = false;
   }
+  timer.stage("sw_chnl");
 
   if (_setChannelBw) {
     phy_PostSetBwMode8812();
     _setChannelBw = false;
   }
+  timer.stage("set_bw");
   /* 8814A uses a packed single-DWord write to BB 0x1998 per (path,rate)
    * instead of the 8812's per-rate per-byte register fanout (see the
    * CHIP_8814A branch at the top of PHY_SetTxPowerIndex_8812A). The
@@ -287,6 +291,7 @@ void RadioManagementModule::phy_SwChnlAndSetBwMode8812() {
   } else {
     PHY_SetTxPowerLevel8812(_currentChannel);
   }
+  timer.stage("tx_power");
 
   /* Run phydm thermal-meter pwrtrk once per channel-set. Mirrors the
    * upstream watchdog tick — reads RF[A][0x42], folds into the
@@ -411,6 +416,8 @@ void RadioManagementModule::phy_SwChnlAndSetBwMode8812() {
     }
   }
   _needIQK = false;
+  timer.stage("iqk");
+  timer.total();
 
   /* Canary dump runs LAST so it captures the post-IQK / post-pwrtrk
    * state — same observation order as kernel iface reads via