diff --git a/CLAUDE.md b/CLAUDE.md index a1fe42e..663e186 100644 --- a/CLAUDE.md +++ b/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: . = 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 diff --git a/README.md b/README.md index 6ae227b..4c0cb63 100644 --- a/README.md +++ b/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 ``` diff --git a/demo/main.cpp b/demo/main.cpp index a6dcc4c..cd5116e 100644 --- a/demo/main.cpp +++ b/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::steady_clock::now() - g_proc_start) + .count(); +} + /* DEVOURER_TX_STATUS=1: surface chip-side C2H frames (TX status reports, * various diagnostic pings) on `` 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("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("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 qd_emitter_stop{false}; std::thread qd_emitter; diff --git a/src/EepromManager.cpp b/src/EepromManager.cpp index 8137a0b..f3dfca9 100644 --- a/src/EepromManager.cpp +++ b/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), diff --git a/src/HalModule.cpp b/src/HalModule.cpp index a4210e6..4e37309 100644 --- a/src/HalModule.cpp +++ b/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,9 +180,11 @@ bool HalModule::rtl8812au_hal_init(uint8_t init_channel) { } _InitHardwareDropIncorrectBulkOut_8812A(); + timer.stage("llt"); auto fwManager = std::make_unique(_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 @@ -183,8 +192,10 @@ bool HalModule::rtl8812au_hal_init(uint8_t init_channel) { * 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; } diff --git a/src/InitTimer.h b/src/InitTimer.h new file mode 100644 index 0000000..0261c93 --- /dev/null +++ b/src/InitTimer.h @@ -0,0 +1,48 @@ +#ifndef INIT_TIMER_H +#define INIT_TIMER_H + +#include +#include + +#include "logger.h" + +/* Stage timer for init-path profiling. Emits one info line per checkpoint: + * + * init-timing: . = 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(to - from) + .count(); + } + + Logger_t _logger; + const char *_scope; + clock::time_point _start; + clock::time_point _last; +}; + +#endif /* INIT_TIMER_H */ diff --git a/src/RadioManagementModule.cpp b/src/RadioManagementModule.cpp index 6c83401..9531fb8 100644 --- a/src/RadioManagementModule.cpp +++ b/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 diff --git a/tests/bench_init.py b/tests/bench_init.py new file mode 100644 index 0000000..0da6380 --- /dev/null +++ b/tests/bench_init.py @@ -0,0 +1,337 @@ +#!/usr/bin/env python3 +"""bench_init.py — init/startup-time benchmark: devourer vs kernel driver. + +Measures, per plugged DUT, how long it takes from process start until the +driver can actually move frames: + + * devourer RX — `WiFiDriverDemo` until `init-timing: demo.first_rx_frame` + (exec → first 802.11 frame delivered). + * devourer TX — `WiFiDriverTxDemo` until `init-timing: txdemo.first_tx_submit` + (exec → first bulk-OUT submitted; includes txdemo's settle + sleep, deliberately — that's the user-visible latency). + * kernel — VM mode only (`--vm-name`/`--vm-ssh`, same rig as + regress.py): virsh attach → wlan iface appears (driver + probe + fwdl) → monitor-mode setup → first tcpdump frame. + +Per-stage breakdown comes from the `init-timing:` lines emitted by the +devourer library (src/InitTimer.h); this script only parses and aggregates. + +A/B variants isolate extrinsic overheads (libusb log level, USB reset, +TX-power loop). Each (cell, variant) is repeated --reps times with a USB +port power-cycle in between so every rep is a cold init. + +Usage: + sudo python3 tests/bench_init.py # devourer cells only + sudo python3 tests/bench_init.py --vm-name devourer-testrig \ + --vm-ssh user@VM-IP # + kernel cells + sudo python3 tests/bench_init.py --variants debug,quiet,quiet+skipreset +""" + +from __future__ import annotations + +import argparse +import os +import re +import statistics +import subprocess +import sys +import time +from pathlib import Path + +# Reuse regress.py's rig plumbing: DUT discovery, VM routing, monitor setup, +# process-group hygiene. +sys.path.insert(0, str(Path(__file__).resolve().parent)) +import regress # noqa: E402 +from regress import ( # noqa: E402 + CANONICAL_SA, + Dut, + KernelHost, + detach_from_host_kernel, + discover_duts, + usb_port_power_cycle, +) + +INIT_TIMING_RE = re.compile(r"init-timing: ([\w.]+) = (\d+) ms") + +# Variant name → env deltas applied on top of the demo defaults. +# "quiet" (libusb WARNING) is the demo default; "debug" opts into libusb +# DEBUG logging via DEVOURER_USB_DEBUG=1. +VARIANTS: dict[str, dict[str, str]] = { + "debug": {"DEVOURER_USB_DEBUG": "1"}, + "quiet": {}, + "quiet+skipreset": {"DEVOURER_SKIP_RESET": "1"}, + "quiet+skiptxpwr": {"DEVOURER_SKIP_TXPWR": "1"}, +} +DEFAULT_VARIANTS = ["debug", "quiet"] + + +# --------------------------------------------------------------------------- +# Devourer cells. +# --------------------------------------------------------------------------- + + +def _devourer_env(dut: Dut, channel: int, extra: dict[str, str]) -> dict: + env = dict(os.environ) + env["DEVOURER_VID"] = f"0x{dut.vid}" + env["DEVOURER_PID"] = f"0x{dut.pid}" + env["DEVOURER_CHANNEL"] = str(channel) + env.pop("DEVOURER_USB_QUIET", None) # variant decides + env.pop("DEVOURER_USB_DEBUG", None) + env.update(extra) + return env + + +def run_devourer_cell( + devourer_root: Path, + dut: Dut, + channel: int, + variant: str, + mode: str, # "rx" | "tx" + timeout_s: float, + log_path: Path, +) -> dict[str, int] | None: + """One cold-init run. Returns {stage: ms} or None on timeout/failure. + + The end-marker stage is `demo.first_rx_frame` (rx) / + `txdemo.first_tx_submit` (tx); the process is killed as soon as the + marker appears, or at timeout. + """ + binary = "WiFiDriverDemo" if mode == "rx" else "WiFiDriverTxDemo" + end_marker = "demo.first_rx_frame" if mode == "rx" else "txdemo.first_tx_submit" + + detach_from_host_kernel(dut) + usb_port_power_cycle(dut) + + fh = open(log_path, "w") + proc = regress._register_local_proc(subprocess.Popen( + [str(devourer_root / "build" / binary)], + env=_devourer_env(dut, channel, VARIANTS[variant]), + stdout=fh, stderr=subprocess.DEVNULL, + preexec_fn=regress._child_preexec, + )) + try: + deadline = time.monotonic() + timeout_s + while time.monotonic() < deadline: + if proc.poll() is not None: + break # crashed / exited early + if end_marker in log_path.read_text(errors="replace"): + break + time.sleep(0.2) + finally: + regress._terminate(proc) + regress._unregister_local_proc(proc) + fh.close() + + stages: dict[str, int] = {} + for m in INIT_TIMING_RE.finditer(log_path.read_text(errors="replace")): + # First occurrence wins: the second channel_set (from mlme init) + # re-emits channel_set.* — keep init-order stages stable. The + # end-marker only ever appears once. + stages.setdefault(m.group(1), int(m.group(2))) + if end_marker not in stages: + return None + return stages + + +# --------------------------------------------------------------------------- +# Kernel cells (VM mode only — aircrack-ng 88XXau doesn't build on modern +# host kernels, and 8814AU kernel-side work is VM-only on this rig). +# --------------------------------------------------------------------------- + + +def run_kernel_cell( + kh: KernelHost, + dut: Dut, + channel: int, + timeout_s: float, + log_path: Path, +) -> dict[str, int] | None: + """One kernel-driver bring-up, timed in three stages: + + kernel.probe virsh attach → wlan iface appears (enumeration + + driver probe incl. fwdl) + kernel.monitor_setup ip link down/monitor/up + iw set channel + kernel.first_frame tcpdump start → first captured frame on channel + kernel.total attach → first frame + """ + # Cold start: make sure the DUT is host-side and power-cycled, then move + # it into the VM. + kh.release_dut(dut) + time.sleep(1.0) + usb_port_power_cycle(dut) + + t0 = time.monotonic() + kh.take_dut(dut) + try: + iface = kh.wait_for_wlan_iface(dut, timeout=timeout_s) + except RuntimeError as e: + sys.stderr.write(f" kernel probe failed: {e}\n") + kh.release_dut(dut) + return None + t_probe = time.monotonic() + + try: + kh.iface_to_monitor(iface, channel) + except RuntimeError as e: + sys.stderr.write(f" kernel monitor setup failed: {e}\n") + kh.release_dut(dut) + return None + t_mon = time.monotonic() + + # First frame on air = RX actually works. No SA filter — any traffic + # proves the RX path (same standard the devourer cell is held to: + # demo.first_rx_frame counts any frame). + fh = open(log_path, "w") + proc = kh.popen( + ["sh", "-c", f"tcpdump -i {iface} -nn -l -c 1 2>/dev/null"], + stdout=fh, stderr=subprocess.DEVNULL, + ) + t_frame = None + deadline = time.monotonic() + timeout_s + while time.monotonic() < deadline: + if proc.poll() is not None: + t_frame = time.monotonic() + break + time.sleep(0.1) + regress._terminate(proc) + fh.close() + kh.release_dut(dut) + if t_frame is None: + return None + + return { + "kernel.probe": int((t_probe - t0) * 1000), + "kernel.monitor_setup": int((t_mon - t_probe) * 1000), + "kernel.first_frame": int((t_frame - t_mon) * 1000), + "kernel.total": int((t_frame - t0) * 1000), + } + + +# --------------------------------------------------------------------------- +# Aggregation + report. +# --------------------------------------------------------------------------- + + +def median_stages(runs: list[dict[str, int]]) -> dict[str, int]: + out: dict[str, int] = {} + for k in {k for r in runs for k in r}: + vals = [r[k] for r in runs if k in r] + if vals: + out[k] = int(statistics.median(vals)) + return out + + +def emit_report(results: dict, reps: int, channel: int) -> str: + lines = [ + f"# Init-time benchmark (median of {reps}, channel {channel})", + "", + "| DUT | cell | variant | ready (ms) | runs ok |", + "|---|---|---|---|---|", + ] + for (chipset, cell, variant), runs in sorted(results.items()): + ok = [r for r in runs if r is not None] + med = median_stages(ok) if ok else {} + key = { + "rx": "demo.first_rx_frame", + "tx": "txdemo.first_tx_submit", + "kernel": "kernel.total", + }[cell] + ready = med.get(key, "—") + lines.append( + f"| {chipset} | {cell} | {variant} | {ready} | {len(ok)}/{len(runs)} |" + ) + lines.append("") + # Per-stage detail for each (DUT, cell, variant) that has data. + for (chipset, cell, variant), runs in sorted(results.items()): + ok = [r for r in runs if r is not None] + if not ok: + continue + med = median_stages(ok) + lines.append(f"## {chipset} / {cell} / {variant} — stage medians (ms)") + lines.append("") + for k in sorted(med, key=med.get, reverse=True): + lines.append(f"- `{k}` = {med[k]}") + lines.append("") + return "\n".join(lines) + + +def main() -> None: + ap = argparse.ArgumentParser(description=__doc__, + formatter_class=argparse.RawDescriptionHelpFormatter) + ap.add_argument("--reps", type=int, default=3) + ap.add_argument("--channel", type=int, default=6) + ap.add_argument("--timeout", type=float, default=45.0, + help="per-run ready-marker timeout (s)") + ap.add_argument("--variants", default=",".join(DEFAULT_VARIANTS), + help=f"comma list from {sorted(VARIANTS)} or 'all'") + ap.add_argument("--pids", default="", + help="restrict to comma list of PIDs (e.g. 8812,8813)") + ap.add_argument("--vm-name", default="", help="libvirt domain for kernel cells") + ap.add_argument("--vm-ssh", default="", help="user@ip of the VM") + ap.add_argument("--skip-tx", action="store_true", + help="skip devourer TX cells") + ap.add_argument("--out", default="/tmp/devourer-bench-init.md") + args = ap.parse_args() + + devourer_root = Path(__file__).resolve().parent.parent + variants = (sorted(VARIANTS) if args.variants == "all" + else [v.strip() for v in args.variants.split(",") if v.strip()]) + for v in variants: + if v not in VARIANTS: + ap.error(f"unknown variant {v!r}; pick from {sorted(VARIANTS)}") + + kh = (KernelHost.via_ssh(args.vm_ssh, args.vm_name) + if args.vm_name and args.vm_ssh else None) + + duts = discover_duts() + if args.pids: + wanted = {p.strip().lower().removeprefix("0x") + for p in args.pids.split(",")} + duts = [d for d in duts if d.pid in wanted] + if not duts: + sys.exit("no supported DUTs found (or all filtered by --pids)") + + regress._install_cleanup_handlers() + logdir = Path("/tmp/devourer-bench-init-logs") + logdir.mkdir(exist_ok=True) + + results: dict[tuple, list] = {} + for dut in duts: + cells: list[tuple[str, str]] = [] + for v in variants: + cells.append(("rx", v)) + if not args.skip_tx: + cells.append(("tx", v)) + if kh: + cells.append(("kernel", "-")) + + for cell, variant in cells: + key = (dut.chipset, cell, variant) + results[key] = [] + for rep in range(args.reps): + tag = f"{dut.pid}-{cell}-{variant.replace('+','_')}-{rep}" + log = logdir / f"{tag}.log" + print(f"[{dut.chipset}] {cell}/{variant} rep {rep + 1}/{args.reps} ...", + flush=True) + if cell == "kernel": + r = run_kernel_cell(kh, dut, args.channel, args.timeout, log) + else: + r = run_devourer_cell(devourer_root, dut, args.channel, + variant, cell, args.timeout, log) + ready = None + if r: + ready = r.get("demo.first_rx_frame") or \ + r.get("txdemo.first_tx_submit") or r.get("kernel.total") + print(f" -> {'%d ms' % ready if ready else 'FAILED/timeout'}", + flush=True) + results[key].append(r) + + report = emit_report(results, args.reps, args.channel) + Path(args.out).write_text(report) + print() + print(report) + print(f"\nlogs: {logdir}/ report: {args.out}") + + +if __name__ == "__main__": + main() diff --git a/tests/regress.py b/tests/regress.py index ad24493..353e3aa 100755 --- a/tests/regress.py +++ b/tests/regress.py @@ -636,7 +636,6 @@ def _devourer_env(dut: Dut, channel: int, env["DEVOURER_VID"] = f"0x{dut.vid}" env["DEVOURER_PID"] = f"0x{dut.pid}" env["DEVOURER_CHANNEL"] = str(channel) - env["DEVOURER_USB_QUIET"] = "1" if tx_encoding: # DEVOURER_TX_* knobs are read by txdemo/main.cpp to patch the # radiotap MCS info bytes before the TX loop. Only meaningful when diff --git a/txdemo/main.cpp b/txdemo/main.cpp index 4126913..d9fe750 100644 --- a/txdemo/main.cpp +++ b/txdemo/main.cpp @@ -39,6 +39,17 @@ static constexpr uint16_t kRealtekProductIds[] = { 0x8812, 0x0811, 0xa811, 0xb811, 0x8813, }; +/* Process-start reference for the init-timing lines (see src/InitTimer.h). + * `init-timing: txdemo.first_tx_submit` is the end-to-end "ready to TX" mark: + * exec → first bulk-OUT submitted. */ +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::steady_clock::now() - g_proc_start) + .count(); +} + static int g_rx_count = 0; static void packetProcessor(const Packet &packet) { ++g_rx_count; @@ -141,9 +152,11 @@ int main(int argc, char **argv) { if (rc != 0) logger->error("libusb_detach_kernel_driver: {}", rc); } + logger->info("init-timing: txdemo.open_device = {} ms", ms_since_start()); if (!termux_mode && !std::getenv("DEVOURER_SKIP_RESET")) { libusb_reset_device(handle); } + logger->info("init-timing: txdemo.usb_reset = {} ms", ms_since_start()); rc = libusb_claim_interface(handle, 0); assert(rc == 0); @@ -255,6 +268,7 @@ int main(int argc, char **argv) { WiFiDriver wifi_driver{logger}; auto rtlDevice = wifi_driver.CreateRtlDevice(handle); + logger->info("init-timing: txdemo.create_device = {} ms", ms_since_start()); int channel = 161; if (const char *ch_env = std::getenv("DEVOURER_CHANNEL")) { @@ -292,8 +306,7 @@ int main(int argc, char **argv) { .ChannelWidth = CHANNEL_WIDTH_20}); write_sentinel(0xBEEF, "post-init/pre-TX"); - - sleep(5); + logger->info("init-timing: txdemo.init_write = {} ms", ms_since_start()); std::thread usb_thread(usb_event_loop, logger, context); uint8_t beacon_frame[] = { @@ -419,6 +432,10 @@ int main(int argc, char **argv) { long tx_count = 0; while (true) { + if (tx_count == 0) { + logger->info("init-timing: txdemo.first_tx_submit = {} ms", + ms_since_start()); + } rc = rtlDevice->send_packet(tx_buf.data(), tx_buf.size()); ++tx_count; if (tx_count <= 10 || tx_count % 500 == 0) { diff --git a/txdemo/stream_duplex_demo/main.cpp b/txdemo/stream_duplex_demo/main.cpp index 1cb70f3..400cfe1 100644 --- a/txdemo/stream_duplex_demo/main.cpp +++ b/txdemo/stream_duplex_demo/main.cpp @@ -253,12 +253,12 @@ int main(int argc, char **argv) { } else { rc = libusb_init(&context); if (rc < 0) return rc; - /* Match WiFiDriverDemo's libusb log level convention — DEVOURER_USB_QUIET - * drops to WARNING so a long-running duplex doesn't flood the harness. */ + /* Match WiFiDriverDemo's libusb log level convention — WARNING by + * default, DEVOURER_USB_DEBUG=1 opts into DEBUG. */ libusb_set_option(context, LIBUSB_OPTION_LOG_LEVEL, - std::getenv("DEVOURER_USB_QUIET") - ? LIBUSB_LOG_LEVEL_WARNING - : LIBUSB_LOG_LEVEL_INFO); + std::getenv("DEVOURER_USB_DEBUG") + ? LIBUSB_LOG_LEVEL_DEBUG + : LIBUSB_LOG_LEVEL_WARNING); uint16_t target_pid = 0; if (const char *pid_env = std::getenv("DEVOURER_PID")) { target_pid = static_cast(std::strtoul(pid_env, nullptr, 0));