diff --git a/docs/logging.md b/docs/logging.md index 327d135f..9806044f 100644 --- a/docs/logging.md +++ b/docs/logging.md @@ -76,7 +76,7 @@ Emitters: L = library, RX/TX/... = demo. Optional fields in [brackets]; ### Init / infrastructure | ev | emitter | fields | |---|---|---| -| `init.timing` | L (`src/InitTimer.h`) + demos | stage ("scope.stage", e.g. "demo.first_rx_frame", "txdemo.first_tx_submit"), ms | +| `init.timing` | L (`src/InitTimer.h`) + demos | stage ("scope.stage", e.g. "demo.first_rx_frame", "txdemo.first_tx_submit"), ms, [xfers] (register transfers the stage spent on that adapter's transport, USB only — present on the Jaguar3 `j3hal.*` / `j3init.*` stages) | | `adapter.caps` | RX, TX, doctor, txpower (`examples/common/caps_event.h`) | supported, chip, names, chip_id "0x..", gen, variant, transport, tx_chains, rx_chains, n_ss, stbc, ldpc, sgi, bw_max, bw[] (MHz), txpwr_max, txpwr_step_qdb, txpwr_step_measured, txpwr_min_qdb, txpwr_max_qdb, txpwr_rate_diffs, txpwr_rate_diffs_hw, txpwr_rate_diffs_measured, tune_2g4[]\|null, tune_5g[]\|null, char_2g4[]\|null, char_5g[]\|null, ldpc_rx_ht, ldpc_rx_vht, ldpc_rx_flag, vht_2g4, per_pkt_txpwr, per_pkt_txpwr_steps, per_pkt_txpwr_step_qdb, per_pkt_txpwr_min_qdb, per_pkt_txpwr_max_qdb, per_pkt_txpwr_measured, narrowband, fastretune, ack_responder, tx_retry_limit, he_er_su, per_chain_rssi, hw_rx_tsf, hw_beacon_txtsf, tsf_write, xtal_cap_max, xtal_cap_default | | `debug.wreg` | L (`DEVOURER_LOG_WRITES`) | addr "0x0nnn", width, val "0x…" | | `hop.prof` | L (`DEVOURER_HOP_PROF`) | gen, ch, `_us`…, total_us | diff --git a/examples/chipstate/main.cpp b/examples/chipstate/main.cpp index 0e3ea62d..e47ebcf5 100644 --- a/examples/chipstate/main.cpp +++ b/examples/chipstate/main.cpp @@ -49,7 +49,7 @@ namespace { /* Same list the other demos' open loop iterates; --pid narrows to one. */ const uint16_t kRealtekPids[] = {0x8812, 0x8813, 0x881a, 0x0811, 0xa811, 0x0820, 0x0821, 0x8822, 0x0120, 0x012d, - 0xb82c, 0xc811, 0xc812, 0xa81a}; + 0xb82c, 0xb812, 0xc811, 0xc812, 0xa81a}; /* One --peek/--poke, kept in argv order so a poke-then-peek verifies the * write inside a single claim. */ @@ -58,7 +58,7 @@ struct RegOp { uint16_t addr = 0; uint16_t end = 0; /* peek range: inclusive last addr (== addr if single) */ uint32_t val = 0; /* poke */ - int width = 1; /* poke: 1/2/4 */ + int width = 1; /* poke: 1/2/4; peek: 1 (bytes) or 4 (aligned words) */ }; struct Args { @@ -74,13 +74,16 @@ void usage() { std::fprintf(stderr, "usage: chipstate [--vid 0xNNNN] [--pid 0xNNNN] [--init] " "[--channel N]\n" - " [--peek 0xA[-0xB]]... [--poke 0xA=0xV[:W]]...\n" + " [--peek 0xA[-0xB][:4]]... [--poke 0xA=0xV[:W]]...\n" " default: attach read-only, no USB reset, no bring-up.\n" " --init : run a full bring-up first (for a healthy reference\n" - " dump on a freshly power-cycled adapter).\n" + " dump on a freshly power-cycled adapter). With\n" + " --peek/--poke the ops run AFTER the bring-up.\n" " --peek : dump register byte(s) over the vendor-control path\n" " (range inclusive, 16 bytes/row) instead of the\n" " canary set. Bypasses chip dispatch — any die.\n" + " `:4` reads aligned 32-bit words instead (the BB/RF\n" + " windows answer 32-bit reads only).\n" " --poke : write a register (width W = 1/2/4, default from the\n" " value magnitude). The bench-bisection intervention\n" " lever; ops run in argv order, so a trailing --peek\n" @@ -111,6 +114,14 @@ bool parse_peek(const char *s, RegOp &op) { if (!parse_reg_addr(end + 1, &end, op.end) || op.end < op.addr) return false; } + if (*end == ':') { + if (end[1] != '4' || end[2] != '\0') + return false; + op.width = 4; + op.addr &= ~3u; + op.end |= 3u; + return true; + } return *end == '\0'; } @@ -145,20 +156,43 @@ int run_reg_ops(libusb_device_handle *handle, Logger_t logger, libusb_context *ctx, std::shared_ptr lock, const std::vector &ops) { - RtlAdapter adapter(handle, logger, ctx, lock); /* A failed vendor-control read throws (UsbTransport::ctrl_read) — on a * powered-down or wedged chip that is a real answer about the chip, so - * report which op died and exit nonzero instead of terminating. */ + * report which op died and exit nonzero instead of terminating. The + * adapter is built inside the try too: its constructor already reads a + * register, and after --init that read is the first thing that can fail. */ try { + RtlAdapter adapter(handle, logger, ctx, lock); for (const RegOp &op : ops) { if (op.write) { + bool ok; if (op.width == 4) - adapter.rtw_write32(op.addr, op.val); + ok = adapter.rtw_write32(op.addr, op.val); else if (op.width == 2) - adapter.rtw_write16(op.addr, static_cast(op.val)); + ok = adapter.rtw_write16(op.addr, static_cast(op.val)); else - adapter.rtw_write8(op.addr, static_cast(op.val)); + ok = adapter.rtw_write8(op.addr, static_cast(op.val)); + if (!ok) { + /* A write the chip did not take must not print as a poke, or a + * following peek reads as a verdict about bits that were never + * written. */ + std::fflush(stdout); + logger->error("poke 0x{:04x} (width {}) FAILED — vendor-control " + "write rejected", op.addr, op.width); + return 4; + } std::printf("poke 0x%04x = 0x%0*x\n", op.addr, op.width * 2, op.val); + } else if (op.width == 4) { + for (uint32_t row = op.addr & ~0xfu; row <= op.end; row += 16) { + std::printf("0x%04x:", row); + for (uint32_t i = row; i < row + 16; i += 4) { + if (i < op.addr || i > op.end) + std::printf(" "); + else + std::printf(" %08x", adapter.rtw_read32(static_cast(i))); + } + std::printf("\n"); + } } else { for (uint32_t row = op.addr & ~0xfu; row <= op.end; row += 16) { std::printf("0x%04x:", row); @@ -254,9 +288,11 @@ int main(int argc, char **argv) { * need the interface, so peeks/pokes work while another process (a live * armed rxdemo) owns it — the concurrent-intervention mode. */ if (a.no_claim) { - if (a.ops.empty()) { - logger->error("--no-claim is peek/poke-only (the canary dump needs the " - "claimed device)"); + if (a.ops.empty() || a.init) { + logger->error(a.init ? "--init needs the claimed-device path; drop " + "--no-claim" + : "--no-claim is peek/poke-only (the canary dump " + "needs the claimed device)"); session.adopt_handle(handle); return 2; } @@ -281,7 +317,7 @@ int main(int argc, char **argv) { /* --peek/--poke: raw transport-level register access, no device * construction at all — the chip is not even identified, let alone * configured, so this works mid-experiment on any die. */ - if (!a.ops.empty()) + if (!a.ops.empty() && !a.init) return run_reg_ops(handle, logger, ctx, lock, a.ops); devourer::DeviceConfig cfg; @@ -303,6 +339,16 @@ int main(int argc, char **argv) { dev->InitWrite(SelectedChannel{.Channel = static_cast(a.channel), .ChannelOffset = 0, .ChannelWidth = CHANNEL_WIDTH_20}); + /* --init + ops: the question is what the bring-up left in a register, + * so the ops run on the configured chip. The device object is released + * first: its destructor joins the Jaguar3 coex thread (and does not + * de-init the chip — that is Stop(), which this tool never calls), so + * the raw-adapter ops below cannot interleave with a background + * register write. Same handle, interface still claimed. */ + if (!a.ops.empty()) { + session.adopt_device(nullptr); + return run_reg_ops(handle, logger, ctx, lock, a.ops); + } } else { logger->info("chipstate: read-only attach (no USB reset, no bring-up) — " "the chip is being read exactly as the last session left it"); diff --git a/src/InitTimer.h b/src/InitTimer.h index 133c36b8..b7904205 100644 --- a/src/InitTimer.h +++ b/src/InitTimer.h @@ -5,11 +5,19 @@ #include #include +#include + #include "logger.h" /* Stage timer for init-path profiling. Emits one event per checkpoint: * - * {"ev":"init.timing","stage":".","ms":N} + * {"ev":"init.timing","stage":".","ms":N[,"xfers":K]} + * + * `xfers` is emitted only when the timer was given a transfer counter: the + * number of register transfers (reads + writes) that stage spent on that one + * adapter's transport (ITransport::ctrl_xfers, via RtlAdapter::ctrl_xfers), + * which is the unit a USB bring-up is actually paid in. Per adapter, so two + * devices brought up in one process do not cross-attribute; 0 on PCIe. * * `stage()` reports time since the previous checkpoint (or construction); * `total()` reports time since construction. Always-on: a handful of events @@ -19,25 +27,53 @@ 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} {} + using XferCounter = std::function; + using Drain = std::function; + + /* `drain`, when given, runs at the start of every checkpoint: a transport + * that queues writes (ITransport::write_batch_begin) completes the stage's + * own writes before the stage is measured, so their tail latency is billed + * to the stage that issued them, not to the next one. */ + InitTimer(Logger_t logger, const char *scope, XferCounter xfers = {}, + Drain drain = {}) + : _logger{std::move(logger)}, _scope{scope}, _xfers{std::move(xfers)}, + _drain{std::move(drain)}, _start{clock::now()}, _last{_start}, + _x_start{count()}, _x_last{_x_start} {} void stage(const char *name) { + if (_drain) + _drain(); const auto now = clock::now(); - emit(name, ms(_last, now)); + const auto x = count(); + emit(name, ms(_last, now), static_cast(x - _x_last)); _last = now; + _x_last = x; } - void total() { emit("total", ms(_start, clock::now())); } + /* Reports the total once. An early return or a throw out of the timed + * scope still gets its total from the destructor, so a failed bring-up + * carries its cost too; a scope that called total() emits exactly one. */ + void total() { + if (_finalized) + return; + _finalized = true; + if (_drain) + _drain(); + emit("total", ms(_start, clock::now()), + static_cast(count() - _x_start)); + } + ~InitTimer() { total(); } private: - void emit(const char *name, long long millis) { + uint64_t count() const { return _xfers ? _xfers() : 0; } + + void emit(const char *name, long long millis, long long nx) { char stage[96]; std::snprintf(stage, sizeof(stage), "%s.%s", _scope, name); - devourer::Ev(_logger->events(), "init.timing") - .f("stage", stage) - .f("ms", millis); + devourer::Ev ev(_logger->events(), "init.timing"); + ev.f("stage", stage).f("ms", millis); + if (_xfers) + ev.f("xfers", nx); } static long long ms(clock::time_point from, clock::time_point to) { @@ -47,8 +83,13 @@ class InitTimer { Logger_t _logger; const char *_scope; + XferCounter _xfers; + Drain _drain; clock::time_point _start; clock::time_point _last; + uint64_t _x_start; + uint64_t _x_last; + bool _finalized = false; }; #endif /* INIT_TIMER_H */ diff --git a/src/RtlAdapter.h b/src/RtlAdapter.h index 74efa7f3..e6cd7428 100644 --- a/src/RtlAdapter.h +++ b/src/RtlAdapter.h @@ -88,6 +88,11 @@ class RtlAdapter { /* Pre-power-on HCI programming (rtw88 rtw_hci_setup slot): PCIe TRX ring * registers; no-op on USB. Call per bring-up attempt, before power-on. */ void hci_setup() { _transport->hci_setup(); } + /* Pipelined register writes — see ITransport::write_batch_begin. */ + void write_batch_begin() { _transport->write_batch_begin(); } + bool write_batch_end() { return _transport->write_batch_end(); } + void flush_writes() { _transport->flush_writes(); } + uint64_t ctrl_xfers() const { return _transport->ctrl_xfers(); } /* Kernel-style async RX: keep n_urbs concurrent bulk-IN transfers in flight * (USB) or reap the RX buffer-descriptor ring (PCIe), invoking diff --git a/src/Transport.h b/src/Transport.h index 82c63154..4e1c451f 100644 --- a/src/Transport.h +++ b/src/Transport.h @@ -68,6 +68,30 @@ class ITransport { return read32(static_cast(addr)); } + /* ---- pipelined register writes ---- + * Inside a write batch, register writes are submitted as asynchronous + * in-order transfers and only a read (or a bulk transfer, or flush_writes) + * waits for them. The Jaguar3 bring-up is ~14k EP0 round trips; on the + * one unit and host measured (an RTL8812EU on an ssc338q) a synchronous + * write cost ~80 us and a pipelined one ~27 us at depth >= 8 — one device, + * one host, so a scale rather than a number to plan by; the measured + * bring-up figures and their limits are in src/jaguar3/CLAUDE.md. + * Correctness rests on EP0 completing URBs in submission order, so a read + * that follows a write still sees it. Single-threaded by contract: open a + * batch only while no other thread touches the transport (the Jaguar3 + * InitWrite/Init bring-up), and close it before any worker thread starts. + * write_batch_end drains and reports whether every queued write completed + * (a failed or short completion is only known after the fact); the caller + * decides what an incomplete batch means. Defaults are no-ops (PCIe). */ + virtual void write_batch_begin() {} + virtual bool write_batch_end() { return true; } + virtual void flush_writes() {} + /* Register transfers (reads + writes) this transport instance has issued + * so far — the unit a USB bring-up is paid in. InitTimer differences it + * per stage. Per instance, never process-wide. 0 where the notion does + * not apply (PCIe MMIO). */ + virtual uint64_t ctrl_xfers() const { return 0; } + /* ---- frame plane ---- */ /* Fire-and-forget data TX (the send_packet hot path). `ep` is the USB * bulk-OUT endpoint choice; the PCIe transport ignores it (the ring is diff --git a/src/UsbTransport.cpp b/src/UsbTransport.cpp index 4cf2aece..31dcc57a 100644 --- a/src/UsbTransport.cpp +++ b/src/UsbTransport.cpp @@ -336,6 +336,55 @@ UsbTransport::UsbTransport(libusb_device_handle *dev_handle, Logger_t logger, } UsbTransport::~UsbTransport() { + flush_writes(); + /* Last chance while the handle and context are still valid: a queue that + * was retired earlier gets one more cancel + bounded reap here, in case + * the event loop has come back. What is still submitted after this is + * leaked deliberately — the alternative is freeing a transfer libusb + * owns, and the caller's libusb_exit will report it rather than crash. */ + if (_aw->inflight > 0) { + for (auto *w : _aw_all) + if (w->inflight) + libusb_cancel_transfer(w->t); + const auto deadline = + std::chrono::steady_clock::now() + std::chrono::seconds(2); + while (_aw->inflight > 0 && std::chrono::steady_clock::now() < deadline) + if (!pump_once(100)) + break; + } + int leaked = 0; + for (auto *w : _aw_all) { + for (;;) { + std::unique_lock lk(_aw->mu); + /* libusb forbids freeing an active transfer, and its callback still + * writes through `w`. If the drain above could not reap it (dead + * event loop / yanked device), leaking the slot is the lesser evil: + * a callback that somehow fires later touches leaked memory, whereas + * freeing here hands libusb a dangling transfer it is still holding. + * Checked first: a slot seen in flight is kept whatever a concurrent + * callback does. */ + if (w->inflight) { + ++leaked; /* keeps its shared AsyncPool alive for a late callback */ + break; + } + /* Seen not in flight and, under the pool mutex, not busy: its + * callback has completed the handoff (busy-clear + free-list push + * happen inside this same mutex), so nothing can publish `w` after + * we free it. Pull it off the free list first. */ + if (!w->cb_busy) { + auto &fr = _aw->free; + fr.erase(std::remove(fr.begin(), fr.end(), w), fr.end()); + lk.unlock(); + libusb_free_transfer(w->t); + delete w; + break; + } + lk.unlock(); /* a callback is inside the slot on another thread */ + std::this_thread::yield(); + } + } + if (leaked) + _logger->error("USB: leaked {} unreaped pipelined transfer slot(s)", leaked); /* Backstop only. The device's Stop()/destructor quiesces TX while every * owner is alive, which is the path that makes teardown safe; reaching the * transport destructor with transfers still in flight means the caller tore @@ -352,7 +401,321 @@ UsbTransport::~UsbTransport() { quiesce_tx(); } +/* ---- pipelined register writes ------------------------------------------ + * Submission order == completion order on EP0, so a pending queue of writes + * followed by a read behaves exactly like the synchronous sequence; the win + * is that the host does not sit through a full URB round trip per write. */ +void UsbTransport::write_batch_begin() { + if (_batch_depth++ > 0) + return; /* nested: the outermost batch owns the verdict and the close */ + /* The caller's batch opens whatever happens below: with pipelining off + * the writes go synchronously and a failed one still counts, so + * write_batch_end reports it — a radio with a register unprogrammed is + * the same problem whichever path the write took. */ + _batch_open = true; + _aw->write_errors = 0; + _aw->generation++; + /* A session that already failed to reap its transfers has a short pool and + * a suspect event loop; stay synchronous rather than pipeline into it. */ + if (_aw_abandoned) + return; + if (_aw_all.empty()) { + /* Built transactionally: a slot whose transfer allocation failed must + * never reach fill/submit, so on any failure the pool is torn back + * down and the session stays synchronous. */ + std::vector slots; + for (int i = 0; i < kAsyncWriteDepth; ++i) { + auto *w = new AsyncWrite{}; + w->t = libusb_alloc_transfer(0); + if (!w->t) { + delete w; + for (auto *s : slots) { + libusb_free_transfer(s->t); + delete s; + } + _logger->error("USB: libusb_alloc_transfer failed; register writes " + "stay synchronous (the batch verdict still applies)"); + return; + } + w->pool = _aw; + slots.push_back(w); + } + _aw_all = slots; + std::lock_guard lk(_aw->mu); + _aw->free = slots; + } + _batch = true; +} + +bool UsbTransport::write_batch_end() { + if (!_batch_open) + return true; + if (--_batch_depth > 0) + return true; /* an inner end: pipelining stays on, the outer end reports */ + flush_writes(); + /* Failed and short completions are only known here, after the fact: a + * write reported true at submission. The count covers failed/short + * write completions, failed synchronous fallbacks and retired slots — + * kept even when a drain already disabled pipelining (`_batch`), which is + * exactly the case with the most to report. */ + const int errors = _aw->write_errors.load(); + if (errors) + _logger->error("USB: {} pipelined register write(s) failed in this batch", + errors); + _batch = false; + _batch_open = false; + return errors == 0; +} + +void LIBUSB_CALL UsbTransport::async_write_cb(libusb_transfer *t) { + auto *w = static_cast(t->user_data); + /* Only the shared pool is touched here — never the transport, which a + * leaked slot can outlive (AsyncPool). A local reference keeps the pool + * alive past the slot too: the free-list push below is this callback's + * last act, after which `w` may be freed (destructor) or reused (a later + * submission) at any moment. */ + std::shared_ptr pool = w->pool; + w->cb_busy = true; + /* Order matters. The result and every piece of accounting are final + * before the slot becomes visible again: `done` is published after + * status/actual so a waiter that sees it sees the result. `cb_busy` + * clears BEFORE the free-list push, so the push — which touches only + * the pool, never `w` — is the last access, and no later submission's + * callback can have its own busy flag cleared by this one. A taker + * (always the batch's own thread) cannot see the slot before the push; + * the destructor cannot free it while cb_busy is set. A reader that is + * waiting on this very slot copies its data out before it submits + * anything else, so the buffer is intact when it does. */ + w->status = t->status; + w->actual = t->actual_length; + if (!w->is_read && w->gen == pool->generation && + (t->status != LIBUSB_TRANSFER_COMPLETED || + t->actual_length != t->length - LIBUSB_CONTROL_SETUP_SIZE)) + pool->write_errors++; /* a stale generation was counted when retired */ + w->inflight = false; + w->done = true; + pool->inflight--; + pool->completed++; + { + /* The busy-clear and the free-list push are one critical section: a + * taker (under the same mutex) can only see the slot after both, so + * no later submission's callback can be inside it while this flag + * store lands; and the destructor decides under this mutex too, so it + * cannot free the slot between the clear and the push. After the + * unlock nothing here touches `w`. */ + std::lock_guard lk(pool->mu); + w->cb_busy = false; + pool->free.push_back(w); + } +} + +UsbTransport::AsyncWrite *UsbTransport::async_take_slot() { + auto take = [this]() -> AsyncWrite * { + std::lock_guard lk(_aw->mu); + if (_aw->free.empty()) + return nullptr; + AsyncWrite *w = _aw->free.back(); + _aw->free.pop_back(); + return w; + }; + /* Snapshot first, then look: a callback on another adapter's pump thread + * that returns a slot between the look and the wait moves the counter + * past the snapshot, so the wait returns at once instead of sitting out + * its deadline over an available slot. */ + uint64_t before = _aw->completed; + AsyncWrite *w = take(); + while (!w) { + if (!async_wait_progress(before)) { + flush_writes(); /* recovers the pool on a stuck queue */ + /* A recovery that retired slots closed the batch: hand out nothing, + * even if some cancellations did return a slot, so the caller takes + * the synchronous path instead of queueing behind the stuck ones. */ + if (_aw_abandoned || !_batch) + return nullptr; + } + before = _aw->completed; + w = take(); + } + w->done = false; + w->inflight = false; + w->status = -1; + w->actual = 0; + return w; +} + +bool UsbTransport::async_read(uint16_t wvalue, uint16_t windex, void *data, + size_t n) { + if (n > kAsyncMaxPayload) + return false; + AsyncWrite *w = async_take_slot(); + if (!w) + return false; + w->is_read = true; + libusb_fill_control_setup(w->buf, REALTEK_USB_VENQT_READ, 5, wvalue, windex, + static_cast(n)); + libusb_fill_control_transfer(w->t, _dev_handle, w->buf, async_write_cb, w, + USB_TIMEOUT); + if (!async_submit(w)) { + _logger->error("USB: pipelined read submit failed"); + return false; + } + for (;;) { + const uint64_t before = _aw->completed; /* snapshot, then look */ + if (w->done) + break; + if (!async_wait_progress(before)) { + flush_writes(); /* cancels + recovers; w->done is set by the cancel */ + break; + } + } + if (!w->done || w->status != LIBUSB_TRANSFER_COMPLETED || + w->actual != static_cast(n)) + return false; + std::memcpy(data, w->buf + LIBUSB_CONTROL_SETUP_SIZE, n); + return true; +} + +bool UsbTransport::async_wait_progress(uint64_t before) { + /* Pumps until THIS pool's completion counter moves past `before`, a real + * 2 s deadline passes, or the event loop errors. Elapsed time, not a turn + * count: on a shared libusb context another adapter's RX/TX completions + * make each handle_events return at once, and counting those turns would + * declare a healthy queue stuck and cancel it. */ + const auto deadline = std::chrono::steady_clock::now() + std::chrono::seconds(2); + while (_aw->completed == before) { + if (std::chrono::steady_clock::now() >= deadline) + return false; + if (!pump_once(250)) + return false; + } + return true; +} + +bool UsbTransport::pump_once(int ms) { + struct timeval tv {0, ms * 1000}; + const int rc = libusb_handle_events_timeout_completed(_ctx, &tv, nullptr); + /* A signal landing in the wait is a wake-up, not a broken loop; the + * caller's elapsed-time deadline still bounds it. */ + if (rc == LIBUSB_ERROR_INTERRUPTED) + return true; + if (rc < 0) { + _logger->error("USB: event loop error {} while draining pipelined writes", + rc); + return false; + } + return true; +} + +void UsbTransport::flush_writes() { + /* Retired slots keep the in-flight count positive for good; draining + * them again would only repeat the timeout + cancel turns on every later + * flush (bulk sends, batch close, destruction). */ + if (_aw_abandoned) + return; + while (_aw->inflight > 0) { + if (async_wait_progress(_aw->completed)) + continue; + /* No completion in ~2 s of pumping. USB_TIMEOUT is 500 ms, so libusb + * itself times a stuck transfer out and completes it through the + * callback long before this; reaching here means the event loop is not + * delivering completions at all (context torn down, device gone). + * Cancel what is still submitted so the caller's next synchronous + * transfer is not queued behind it. */ + _logger->error("USB: pipelined write drain timed out ({} in flight)", + _aw->inflight.load()); + for (auto *w : _aw_all) + if (w->inflight) + libusb_cancel_transfer(w->t); + /* A cancellation still completes through the callback, which is what + * clears `inflight` and returns the slot. Keep pumping for it: the count + * must never be zeroed by hand, or a late callback decrements it below + * zero (silently disabling every later drain), pushes its slot onto the + * free list a second time, and races the destructor's free. */ + /* One absolute deadline for the whole post-cancel phase, pumped in + * short turns — not a fresh 2 s wait per slot, which would let an + * eight-deep dead queue hold the bring-up for the better part of 20 s. */ + const auto cancel_deadline = + std::chrono::steady_clock::now() + std::chrono::seconds(2); + while (_aw->inflight > 0 && + std::chrono::steady_clock::now() < cancel_deadline) + if (!pump_once(100)) + break; + if (_aw->inflight > 0) { + /* The event loop itself is gone (a yanked device reports the error + * immediately, so the turns above cost nothing). Leave the slots + * submitted and off the free list; the destructor leaks them. The + * batch is closed here too: with those slots never returning, the + * in-flight count can never reach zero again, and every later + * register access would otherwise walk take-slot -> wait -> drain + * (seconds each) for the rest of the bring-up. Synchronous from + * here on. */ + /* Only the writes among the retired slots are batch write errors; a + * stranded read already failed its caller (false / throw), and a + * caller that retried it synchronously and recovered must not see + * the batch fail for it. */ + for (auto *w : _aw_all) + if (w->inflight && !w->is_read) + _aw->write_errors++; + _aw_abandoned = true; + _batch = false; /* pipelining off; the caller's batch stays open so + * write_batch_end still returns this verdict */ + _logger->error("USB: {} pipelined transfer(s) could not be reaped; " + "their slots are retired for this session", + _aw->inflight.load()); + } + return; + } +} + +bool UsbTransport::async_write(uint16_t wvalue, uint16_t windex, + const void *data, size_t n) { + if (n > kAsyncMaxPayload) + return false; + AsyncWrite *w = async_take_slot(); + if (!w) + return false; + w->is_read = false; + libusb_fill_control_setup(w->buf, REALTEK_USB_VENQT_WRITE, 5, wvalue, windex, + static_cast(n)); + std::memcpy(w->buf + LIBUSB_CONTROL_SETUP_SIZE, data, n); + libusb_fill_control_transfer(w->t, _dev_handle, w->buf, async_write_cb, w, + USB_TIMEOUT); + if (!async_submit(w)) { + _logger->error("USB: pipelined write submit failed"); + return false; + } + return true; +} + +/* Accounts the slot as in flight BEFORE submitting it — the callback may run + * on another thread's event pump the moment libusb has it — and rolls the + * accounting back if libusb refuses the transfer. */ +bool UsbTransport::async_submit(AsyncWrite *w) { + w->gen = _aw->generation; + w->inflight = true; + _aw->inflight++; + const int rc = libusb_submit_transfer(w->t); + if (rc == 0) { + _ctrl_xfers.fetch_add(1, std::memory_order_relaxed); /* issued */ + return true; + } + _aw->inflight--; + w->inflight = false; + /* Not a batch write error yet: the caller retries a refused write + * synchronously and counts it only if that fails too. */ + { + std::lock_guard lk(_aw->mu); + _aw->free.push_back(w); + } + _logger->error("USB: libusb_submit_transfer rc={}", rc); + return false; +} + bool UsbTransport::write_bytes(uint16_t reg_num, const uint8_t *ptr, size_t n) { + /* A vendor control transfer like any other -- counted so an InitTimer stage + * that downloads firmware this way reports what it actually spent. */ + _ctrl_xfers.fetch_add(1, std::memory_order_relaxed); + flush_writes(); return libusb_control_transfer(_dev_handle, REALTEK_USB_VENQT_WRITE, 5, reg_num, 0, const_cast(ptr), n, USB_TIMEOUT) == static_cast(n); @@ -362,6 +725,7 @@ void UsbTransport::rx_loop( int buf_size, int n_urbs, const std::function &on_data, const std::function &should_stop) { + flush_writes(); /* bulk-IN behind queued register writes (batch contract) */ if (_rx_mode == RxMode::Sync) { rx_loop_sync(buf_size, on_data, should_stop); return; @@ -646,6 +1010,7 @@ void UsbTransport::rx_loop_sync( } int UsbTransport::rx_raw(uint8_t *buf, int len, int timeout_ms) { + flush_writes(); /* as rx_loop: the RX must not outrun queued configuration */ int actual = 0; int rc = libusb_bulk_transfer(_dev_handle, _info.bulk_in_ep, buf, len, &actual, timeout_ms); @@ -854,6 +1219,7 @@ void UsbTransport::quiesce_tx() { bool UsbTransport::tx_async(uint8_t tx_ep, uint8_t *packet, size_t length, unsigned timeout_ms) { + flush_writes(); /* Reap completed async-TX transfers before submitting the next one — in the * caller's own thread, so there is no background pump to race libusb * teardown. A non-blocking handle_events (timeout 0) processes every ready @@ -1001,6 +1367,7 @@ bool UsbTransport::tx_async(uint8_t tx_ep, uint8_t *packet, size_t length, int UsbTransport::tx_sync(uint8_t ep, uint8_t *packet, size_t length, int timeout_ms) { + flush_writes(); /* No libusb_clear_halt here. rtw88_8814au's usbmon shows the first bulk * OUT is preceded by 0 CLEAR_FEATUREs; later CLEAR_FEATUREs happen during * normal TX-queue operation, not the per-send hot path. Resetting the diff --git a/src/UsbTransport.h b/src/UsbTransport.h index 9bb02319..3524e96a 100644 --- a/src/UsbTransport.h +++ b/src/UsbTransport.h @@ -51,14 +51,42 @@ class UsbTransport final : public ITransport { /* Realtek USB register addressing: wValue = addr[15:0], wIndex = * addr[31:16]. Lets the BB/RF window (addr + 0x10000) reach wIndex=1 * instead of colliding with the MAC/system space at wIndex=0. */ - return libusb_control_transfer( + /* A pipelined write that cannot be submitted (no usable slot, submit + * rejected) falls through to the synchronous transfer below: EP0 keeps + * submission order, so it lands behind whatever is still queued and no + * register write is silently dropped. Transfers are counted where they + * are issued (async_submit / here), so a fallback counts as its own. */ + if (_batch && async_write(static_cast(addr & 0xFFFF), + static_cast(addr >> 16), &v, sizeof(v))) + return true; + _ctrl_xfers.fetch_add(1, std::memory_order_relaxed); + const bool ok = + libusb_control_transfer( _dev_handle, REALTEK_USB_VENQT_WRITE, 5, static_cast(addr & 0xFFFF), static_cast(addr >> 16), (uint8_t *)&v, sizeof(v), USB_TIMEOUT) == static_cast(sizeof(v)); + /* Only a fallback that ALSO failed is a batch write error; a refused + * async submit that the synchronous path completed is not. */ + if (!ok && _batch_open) + _aw->write_errors++; + return ok; } uint32_t read32_wide(uint32_t addr) override { uint32_t data = 0; + if (_batch) { + if (async_read(static_cast(addr & 0xFFFF), + static_cast(addr >> 16), &data, sizeof(data))) + return data; + /* A pipelined read that could not be submitted or completed is a + * queue problem, not a register problem: say so, then read it + * synchronously below — EP0 order still places that read behind + * whatever is queued — so only a real transfer failure yields the + * all-ones sentinel. */ + _logger->error("USB: pipelined read32_wide(0x{:05x}) failed; reading " + "synchronously", addr); + } + _ctrl_xfers.fetch_add(1, std::memory_order_relaxed); if (libusb_control_transfer(_dev_handle, REALTEK_USB_VENQT_READ, 5, static_cast(addr & 0xFFFF), static_cast(addr >> 16), @@ -68,6 +96,12 @@ class UsbTransport final : public ITransport { return 0xFFFFFFFFu; /* INVALID_RF_DATA-style sentinel on a failed read */ } bool write_bytes(uint16_t reg, const uint8_t *p, size_t n) override; + void write_batch_begin() override; + bool write_batch_end() override; + void flush_writes() override; + uint64_t ctrl_xfers() const override { + return _ctrl_xfers.load(std::memory_order_relaxed); + } bool tx_async(uint8_t ep, uint8_t *buf, size_t len, unsigned timeout_ms) override; @@ -85,6 +119,92 @@ class UsbTransport final : public ITransport { private: template T ctrl_read(uint16_t reg); template bool ctrl_write(uint16_t reg, T value); + /* Pipelined-write machinery (see ITransport::write_batch_begin). */ + /* Register transfers are 1/2/4 bytes; async_write/async_read refuse a + * larger payload rather than overrun the inline setup buffer. */ + static constexpr size_t kAsyncMaxPayload = 4; + /* Bookkeeping the completion callback writes to. It is owned jointly by + * the transport and every slot (shared_ptr), not by the transport alone: + * a slot that could not be reaped outlives the transport (see the + * destructor), and its callback may still fire later through a libusb + * context another adapter in the process keeps pumping. It then updates + * this block, which the leaked slot keeps alive, instead of a freed + * UsbTransport. */ + struct AsyncWrite; + /* The submitter and the completion callback are normally the same thread + * (this transport pumps its own events while it waits), but a second + * adapter sharing the libusb context can pump it from another thread and + * run the callback there, right after libusb_submit_transfer returns. So + * the counters are atomic, the free list is under a mutex, and a slot is + * marked in flight BEFORE it is submitted (rolled back if the submit is + * refused) — the callback never sees a completed slot that the submitter + * has not yet accounted for. */ + struct AsyncPool { + std::mutex mu; /* guards `free` */ + std::vector free; + std::atomic inflight{0}; + std::atomic completed{0}; + /* Failed/short WRITE completions, write submit refusals and retired + * slots: what write_batch_end reports. A failed read is reported to its + * caller directly (false / throw) and is NOT counted here — a read + * glitch that the caller retries and recovers must not fail the batch. */ + std::atomic write_errors{0}; + /* Bumped by every write_batch_begin; a slot carries the generation it + * was submitted under, and a completion from an older generation (a + * slot retired by a drain that finishes late) never touches the current + * batch's verdict — it was already counted when it was retired. */ + std::atomic generation{0}; + }; + struct AsyncWrite { + libusb_transfer *t; + uint8_t buf[LIBUSB_CONTROL_SETUP_SIZE + kAsyncMaxPayload]; + std::shared_ptr pool; + std::atomic done{false}; + /* Submitted and not yet reaped: libusb owns `t` and `buf` while set, so + * the slot must not be reused, freed, or handed back to the free list. */ + std::atomic inflight{false}; + /* The completion callback is inside the slot: set first thing on entry, + * cleared as its very last store. `inflight` has to clear before the + * free-list push (a taker must see a finished slot), so it cannot double + * as the destructor's "safe to free" signal — this is. */ + std::atomic cb_busy{false}; + bool is_read = false; /* set before submit; decides which failure it is */ + uint64_t gen = 0; /* batch generation the slot was submitted under */ + int status = -1; + int actual = 0; + }; + static constexpr int kAsyncWriteDepth = 8; + bool async_write(uint16_t wvalue, uint16_t windex, const void *data, + size_t n); + /* Read queued behind the pending writes (EP0 order) and waited for on its + * own completion only: a read-modify-write pair costs one wakeup, not two. + * Returns false on failure (data untouched). */ + bool async_read(uint16_t wvalue, uint16_t windex, void *data, size_t n); + AsyncWrite *async_take_slot(); + bool async_submit(AsyncWrite *w); /* in-flight accounting before submit */ + /* Pump until this pool's completion counter moves past `before` (a + * snapshot the caller took BEFORE checking whatever it is waiting for, + * so a completion landing in between is not missed); false on a 2 s + * deadline or an event-loop error. */ + bool async_wait_progress(uint64_t before); + bool pump_once(int ms); /* one bounded handle_events turn; false on error */ + static void LIBUSB_CALL async_write_cb(libusb_transfer *t); + /* `_batch`: pipelined submission is enabled right now. `_batch_open`: the + * caller's batch is open. They part when a drain retires slots — that + * disables pipelining at once but must keep the batch's verdict (its + * write errors) for write_batch_end to return. */ + bool _batch = false; + bool _batch_open = false; + int _batch_depth = 0; /* begin/end nest; the outermost pair owns the verdict */ + std::shared_ptr _aw = std::make_shared(); + std::vector _aw_all; + /* Set when a drain gave up with transfers still submitted: the destructor + * then leaks those slots instead of freeing a transfer libusb still owns. */ + bool _aw_abandoned = false; + /* Vendor control transfers (register reads + writes) this transport has + * issued; per instance, so two adapters in one process do not + * cross-attribute their InitTimer stage counts. */ + std::atomic _ctrl_xfers{0}; void discover_endpoints(); /* was InitDvObj */ const char *speed_str() const; static void transfer_callback(struct libusb_transfer *transfer); @@ -158,6 +278,15 @@ class UsbTransport final : public ITransport { template T UsbTransport::ctrl_read(uint16_t reg_num) { T data = 0; + if (_batch) { + if (async_read(reg_num, 0, &data, sizeof(T))) + return data; + /* Fall through to the synchronous read (see read32_wide): only a + * transfer that fails there too throws. */ + _logger->error("rtw_read({:04x}) pipelined failed; reading synchronously", + reg_num); + } + _ctrl_xfers.fetch_add(1, std::memory_order_relaxed); if (libusb_control_transfer(_dev_handle, REALTEK_USB_VENQT_READ, 5, reg_num, 0, (uint8_t *)&data, sizeof(T), USB_TIMEOUT) == sizeof(T)) { @@ -169,9 +298,17 @@ template T UsbTransport::ctrl_read(uint16_t reg_num) { } template bool UsbTransport::ctrl_write(uint16_t reg_num, T value) { - return libusb_control_transfer(_dev_handle, REALTEK_USB_VENQT_WRITE, 5, - reg_num, 0, (uint8_t *)&value, sizeof(T), - USB_TIMEOUT) == sizeof(T); + /* Unsubmittable pipelined write -> synchronous, in order (see write32_wide). */ + if (_batch && async_write(reg_num, 0, &value, sizeof(T))) + return true; + _ctrl_xfers.fetch_add(1, std::memory_order_relaxed); + const bool ok = + libusb_control_transfer(_dev_handle, REALTEK_USB_VENQT_WRITE, 5, reg_num, + 0, (uint8_t *)&value, sizeof(T), + USB_TIMEOUT) == sizeof(T); + if (!ok && _batch_open) + _aw->write_errors++; /* the fallback failed too (see write32_wide) */ + return ok; } } /* namespace devourer */ diff --git a/src/jaguar3/CLAUDE.md b/src/jaguar3/CLAUDE.md index e44ebee0..5f624cb7 100644 --- a/src/jaguar3/CLAUDE.md +++ b/src/jaguar3/CLAUDE.md @@ -36,6 +36,40 @@ narrowband dividers, RF18 encoding), strategy interfaces `Jaguar3Calibration` single-path 1SS TX, spur channels, LCK, the 2.4 GHz TX kernel-parity limitation) live in `docs/8822e-quirks.md`. +## Bring-up cost and the pipelined register writes + +`InitWrite` is ~14k USB register transfers and nothing else. The stage +timing shows it: `init.timing` events under the `j3hal.*` (HAL bring-up) +and `j3init.*` (`InitWrite`) scopes, field schema in `src/InitTimer.h` / +`docs/logging.md`; `bench_init.py` parses them but reports only `ms`. The +batching contract itself — ordering, what waits, single-threadedness, +failure propagation — is documented once, at `ITransport::write_batch_begin` +(`src/Transport.h`) and in `UsbTransport`; this file carries only how +Jaguar3 uses it: + +- `InitWrite` runs its whole bring-up inside one `WriteBatchScope` + (`RtlJaguar3Device.cpp`), ended before the coex thread starts because that + thread shares the transport. A queued write that completed failed or + short fails the batch close, and `InitWrite` throws there rather than + start the coex thread over an incompletely programmed chip. `Init` + (RX-only) opens no batch yet — not measured on a ground-station card. +- Every settle delay drains the queue first, µs ones included, on both + dies: the `write_bb` / `rf_writer` table delay markers, `delay_us` and + `delay_ms` on `Halrf8822c` and `Halrf8822e`, the efuse power-cut. A settle + that sleeps while its writes are still queued is no settle; the drain is + free on an empty queue and bounded by its depth otherwise. +- Measured: 1.30 → 0.65 s warm, 2.04 → ~0.7 s cold on one drone-side + 8812EU (ssc338q host). The transfer-count reduction is deterministic; the + wall-clock figure is one unit, one host. + +The RF radio-table load is write-only: bits [31:20] of the direct window +(`0x3c00`/`0x4c00 + addr*4`) are not storage, so the vendor's `MASK20BITS` +read-modify-write preserved nothing at the price of a synchronous read per +entry. Scope of that claim (`tests/j3_rf_window_readback.sh`): every one of +the 512 window words (both paths) poked with the high 12 bits set read back +0, on one 8812CU and one 8812EU; the post-bring-up histogram (all 512 words +0) is only a control, since the write-only load itself clears those bits. + ## TX power Both dies drive the SAME TXAGC block (`set_tx_power_ref` is the port of diff --git a/src/jaguar3/HalJaguar3.cpp b/src/jaguar3/HalJaguar3.cpp index ba938e18..f32e9a36 100644 --- a/src/jaguar3/HalJaguar3.cpp +++ b/src/jaguar3/HalJaguar3.cpp @@ -1,4 +1,5 @@ #include "HalJaguar3.h" +#include "InitTimer.h" #include #include @@ -41,12 +42,17 @@ void retry_cal(Logger_t &logger, const char *what, F &&step, int tries = 3) { * write. */ void write_bb(RtlAdapter &dev, uint32_t addr, uint32_t data) { switch (addr) { - case 0xfe: std::this_thread::sleep_for(std::chrono::milliseconds(50)); return; - case 0xfd: std::this_thread::sleep_for(std::chrono::milliseconds(5)); return; - case 0xfc: std::this_thread::sleep_for(std::chrono::milliseconds(1)); return; - case 0xfb: std::this_thread::sleep_for(std::chrono::microseconds(50)); return; - case 0xfa: std::this_thread::sleep_for(std::chrono::microseconds(5)); return; - case 0xf9: std::this_thread::sleep_for(std::chrono::microseconds(1)); return; + /* The table delays exist to let the preceding writes settle, so every + * one of them drains the pipelined-write queue before sleeping — a + * settle measured from a write that is still queued is no settle. The + * drain is free when the queue is empty and bounded by its depth when + * not. */ + case 0xfe: dev.flush_writes(); std::this_thread::sleep_for(std::chrono::milliseconds(50)); return; + case 0xfd: dev.flush_writes(); std::this_thread::sleep_for(std::chrono::milliseconds(5)); return; + case 0xfc: dev.flush_writes(); std::this_thread::sleep_for(std::chrono::milliseconds(1)); return; + case 0xfb: dev.flush_writes(); std::this_thread::sleep_for(std::chrono::microseconds(50)); return; + case 0xfa: dev.flush_writes(); std::this_thread::sleep_for(std::chrono::microseconds(5)); return; + case 0xf9: dev.flush_writes(); std::this_thread::sleep_for(std::chrono::microseconds(1)); return; default: dev.phy_set_bb_reg(static_cast(addr), MASKDWORD, data); } } @@ -87,11 +93,22 @@ void HalJaguar3::run_iqk(SelectedChannel channel) { * Every step is ported from vendor source. */ void HalJaguar3::rtw_hal_init(SelectedChannel channel) { ChannelWidth_t bw = channel.ChannelWidth; + /* The transfer counter is a USB notion (xfers is emitted only when a + * counter is attached); a PCIe transport gets none, and its timer omits + * the field instead of reporting 0. */ + InitTimer timer(_logger, "j3hal", + _device.is_usb() ? InitTimer::XferCounter{[this] { return _device.ctrl_xfers(); }} + : InitTimer::XferCounter{}, + [this] { _device.flush_writes(); }); _macinit.pre_init_system_cfg(); + timer.stage("pre_init_system_cfg"); power_on(); /* mac_power_switch(on) — card_en_flow */ + timer.stage("power_on"); read_chip_version(); /* needs MAC alive; supplies cut for system_cfg */ + timer.stage("chip_version"); cache_efuse_8822e(); /* one-shot OTP decode while access is reliable */ + timer.stage("efuse_cache"); if (_variant == ChipVariant::C8822E && _efuse_cache_valid) /* Efuse thermal baseline (0xd0/0xd1) + channel for pwr_track thermal tracking. */ _cal->set_pwr_track_ctx(_efuse_cache[0xd0], _efuse_cache[0xd1], @@ -109,35 +126,46 @@ void HalJaguar3::rtw_hal_init(SelectedChannel channel) { (_phy_ctx.rfe_type == 0 || _phy_ctx.rfe_type == 0xff)) _phy_ctx.rfe_type = 21; _logger->info("Jaguar3: rfe_type=0x{:02x}", _phy_ctx.rfe_type); + timer.stage("efuse_rfe"); _macinit.init_system_cfg(bw, _ver.cut); + timer.stage("init_system_cfg"); if (!_fw.download_default_firmware()) { _logger->error("Jaguar3: firmware download FAILED (structured)"); return; } _logger->info("Jaguar3: firmware booted (structured)"); + timer.stage("dlfw"); if (!_macinit.init_mac_cfg(bw)) { _logger->error("Jaguar3: init_mac_cfg FAILED (structured)"); return; } + timer.stage("init_mac_cfg"); /* Propagate the queue-init reserved-page boundary to the FW downloader — it * was 0 during the pre-queue-init FW stage, so a beacon rsvd-page download * would otherwise target page 0 instead of the real boundary. */ _fw.set_rsvd_boundary(_macinit.rsvd_boundary()); _macinit.init_usb_cfg(); /* USB RX-DMA mode — RX delivery to bulk-IN */ _macinit.enable_bb_rf(true); /* set_hw_value(EN_BB_RF) */ - apply_bb_rf_agc_tables(); /* init_phy: BB + AGC + RF tables */ + timer.stage("usb_cfg_bbrf"); + apply_bb_rf_agc_tables(&timer); /* init_phy: BB + AGC + RF tables */ config_pa_bias_8822e(); /* kfree: efuse PA-bias trim -> RF 0x60 */ + timer.stage("pa_bias"); config_phydm_parameter_init(); /* POST_SETTING: 3-wire + OFDM/CCK block + bb-reset */ + timer.stage("phydm_param_init"); init_rfk(); /* RF cal_init (0x1B00); IQK runs via run_iqk */ + timer.stage("rfk_init"); /* halrf DACK — DAC cal before IQK. Retry-wrapped: its status-poll loops issue * tens of thousands of USB reads and an intermittent glitch was aborting * bring-up (rtw_read iostream error, seen on 8822EU). */ retry_cal(_logger, "DACK", [this] { _cal->dac_calibrate(); }); + timer.stage("dack"); bf_init(); /* rtl8822c_phy_bf_init (rtl8822c_halinit.c) */ monitor_rx_cfg(); /* devourer monitor-mode RX enable */ enable_tx_path(); /* enable OFDM/CCK TX block (gates on-air TX) */ + timer.stage("bf_rx_tx_cfg"); + timer.total(); _logger->info("Jaguar3: bring-up complete"); } @@ -543,6 +571,7 @@ void HalJaguar3::efuse_pwr_cut_8822e(bool on) { if (on) { _device.rtw_write8(PMC, static_cast(_device.rtw_read8(PMC) | kWrMsk)); _device.rtw_write16(SYS_ISO, static_cast(_device.rtw_read16(SYS_ISO) | kPwcS)); + _device.flush_writes(); std::this_thread::sleep_for(std::chrono::milliseconds(1)); _device.rtw_write16(SYS_ISO, static_cast(_device.rtw_read16(SYS_ISO) | kPwcB)); _device.rtw_write16(SYS_ISO, static_cast(_device.rtw_read16(SYS_ISO) & ~kEbCore)); @@ -555,6 +584,7 @@ void HalJaguar3::efuse_pwr_cut_8822e(bool on) { _device.rtw_write32(EFC1, _device.rtw_read32(EFC1) & ~kBurst); _device.rtw_write16(SYS_ISO, static_cast(_device.rtw_read16(SYS_ISO) | kEbCore)); _device.rtw_write16(SYS_ISO, static_cast(_device.rtw_read16(SYS_ISO) & ~kPwcB)); + _device.flush_writes(); std::this_thread::sleep_for(std::chrono::milliseconds(1)); _device.rtw_write16(SYS_ISO, static_cast(_device.rtw_read16(SYS_ISO) & ~kPwcS)); _device.rtw_write8(PMC, static_cast(_device.rtw_read8(PMC) & ~kWrMsk)); @@ -578,6 +608,7 @@ uint8_t HalJaguar3::efuse_phys_read_8822e(uint16_t addr) { uint32_t v = _device.rtw_read32(EFC); v = (v & ~(kAddr | kData | kRdy)) | ((static_cast(addr) & 0x7ff) << 16); _device.rtw_write32(EFC, v); + _device.flush_writes(); /* the 50 µs settle counts from the trigger landing */ for (int i = 0; i < 1000; ++i) { std::this_thread::sleep_for(std::chrono::microseconds(50)); uint32_t t = _device.rtw_read32(EFC); @@ -965,7 +996,7 @@ void HalJaguar3::power_on() { _logger->info("Jaguar3: power-on sequence complete (card active)"); } -void HalJaguar3::apply_bb_rf_agc_tables() { +void HalJaguar3::apply_bb_rf_agc_tables(InitTimer *timer) { /* BB + AGC baseline via the validated halbb walker (src/jaguar3/ * PhyTableLoaderJaguar3). _phy_ctx must be populated from the chip-version + * EFUSE read (done earlier in rtw_hal_init) before the tables are walked. */ @@ -976,8 +1007,10 @@ void HalJaguar3::apply_bb_rf_agc_tables() { const auto agc_tab = _tables->agc_tab(); _logger->info("Jaguar3: applying BB phy_reg table ({} words)", phy_reg.len); PhyTableLoaderJaguar3::Load(phy_reg.data, phy_reg.len, _phy_ctx, bb); + if (timer) timer->stage("table_phy_reg"); _logger->info("Jaguar3: applying AGC table ({} words)", agc_tab.len); PhyTableLoaderJaguar3::Load(agc_tab.data, agc_tab.len, _phy_ctx, bb); + if (timer) timer->stage("table_agc"); /* RF radio tables. On 8822C an RF register write is a direct BB write to a * per-path window: BB[base + (rf_addr&0xff)*4], 20-bit mask, base 0x3c00 @@ -987,9 +1020,9 @@ void HalJaguar3::apply_bb_rf_agc_tables() { auto rf_writer = [this](uint16_t base) { return [this, base](uint32_t addr, uint32_t data) { switch (addr) { - case 0xffe: std::this_thread::sleep_for(std::chrono::milliseconds(50)); return; - case 0xfe: std::this_thread::sleep_for(std::chrono::microseconds(100)); return; - case 0xffff: std::this_thread::sleep_for(std::chrono::microseconds(1)); return; + case 0xffe: _device.flush_writes(); std::this_thread::sleep_for(std::chrono::milliseconds(50)); return; + case 0xfe: _device.flush_writes(); std::this_thread::sleep_for(std::chrono::microseconds(100)); return; + case 0xffff: _device.flush_writes(); std::this_thread::sleep_for(std::chrono::microseconds(1)); return; case 0x0: /* RF reg 0x0 (mode register) can't be written through the direct * window — it silently no-ops (hardware-observed on the 8822e). The @@ -1000,8 +1033,18 @@ void HalJaguar3::apply_bb_rf_agc_tables() { _device.rtw_write32(base == 0x4c00 ? 0x4108 : 0x1808, data & RFREG_MASK); return; default: - _device.phy_set_bb_reg(static_cast(base + ((addr & 0xff) << 2)), - RFREG_MASK, data); + /* Plain 20-bit write, not the vendor's read-modify-write under + * MASK20BITS: the direct window's bits [31:20] are not storage -- + * every one of the 512 window words (both paths) poked with those + * bits set reads back 0, on one 8812CU and one 8812EU + * (tests/j3_rf_window_readback.sh) -- so an RMW there writes + * exactly `data`, and preserving those bits was a no-op that cost a + * synchronous read per entry: about half the RF table stage (~80 ms + * on the one 8812EU + ssc338q host measured; x86 bench figures in + * src/jaguar3/CLAUDE.md). Write-only also pipelines + * (ITransport::write_batch_begin). */ + _device.rtw_write32(static_cast(base + ((addr & 0xff) << 2)), + data & RFREG_MASK); } }; }; @@ -1017,6 +1060,7 @@ void HalJaguar3::apply_bb_rf_agc_tables() { _device.phy_set_bb_reg(0x1c90, 1u << 8, 1); _device.phy_set_bb_reg(0x1830, 1u << 29, 1); _device.phy_set_bb_reg(0x4130, 1u << 29, 1); + if (timer) timer->stage("table_rf_ab"); _logger->info("Jaguar3: BB/AGC/RF tables applied"); } diff --git a/src/jaguar3/HalJaguar3.h b/src/jaguar3/HalJaguar3.h index c160356a..637aa9a7 100644 --- a/src/jaguar3/HalJaguar3.h +++ b/src/jaguar3/HalJaguar3.h @@ -14,6 +14,7 @@ #include "HalmacJaguar3MacInit.h" #include "PhyTableLoaderJaguar3.h" +class InitTimer; /* src/InitTimer.h — stage timer for the bring-up */ namespace jaguar3 { /* HalJaguar3 — Jaguar3 chip bring-up: power sequencing, queue/page/LLT init, BB / @@ -99,7 +100,7 @@ class HalJaguar3 { void power_off(); /* card-disable PWR_SEQ — reset from active state */ void power_on(); /* card-enable PWR_SEQ */ void init_rfk(); /* RF-calibration init (0x1B00 cal_init block) */ - void apply_bb_rf_agc_tables(); /* phydm BB/AGC/RF tables via PhyTableLoader */ + void apply_bb_rf_agc_tables(::InitTimer *timer = nullptr); /* phydm BB/AGC/RF tables via PhyTableLoader; stage checkpoints when given */ void bf_init(); /* rtl8822c_phy_bf_init: BF/MU + NDPA sounding */ void config_phydm_parameter_init(); /* POST_SETTING: 3-wire + OFDM/CCK block */ void enable_tx_path(); /* OFDM/CCK TX block + AGC/path enable (on-air TX) */ diff --git a/src/jaguar3/Halrf8822c.cpp b/src/jaguar3/Halrf8822c.cpp index 2ff581ef..d4409e4c 100644 --- a/src/jaguar3/Halrf8822c.cpp +++ b/src/jaguar3/Halrf8822c.cpp @@ -175,9 +175,14 @@ void Halrf8822c::restore_rf(const uint32_t rf[][2]) { } void Halrf8822c::delay_us(uint32_t us) { + /* A settle is measured from the write reaching the chip, so drain the + * pipelined queue first (free when it is empty; bounded by the queue + * depth when not). The µs sites include 2 ms and 10 ms waits. */ + _device.flush_writes(); std::this_thread::sleep_for(std::chrono::microseconds(us)); } void Halrf8822c::delay_ms(uint32_t ms) { + _device.flush_writes(); /* the settle time must follow the writes */ std::this_thread::sleep_for(std::chrono::milliseconds(ms)); } diff --git a/src/jaguar3/Halrf8822c.h b/src/jaguar3/Halrf8822c.h index 2c1e5df5..7f9e058a 100644 --- a/src/jaguar3/Halrf8822c.h +++ b/src/jaguar3/Halrf8822c.h @@ -110,8 +110,8 @@ class Halrf8822c : public Jaguar3Calibration { uint8_t mac_read8(uint16_t addr) { return _device.rtw_read8(addr); } uint32_t rf_read(uint8_t path, uint16_t addr, uint32_t mask); void rf_write(uint8_t path, uint16_t addr, uint32_t mask, uint32_t val); - static void delay_us(uint32_t us); - static void delay_ms(uint32_t ms); + void delay_us(uint32_t us); /* drains pipelined writes first */ + void delay_ms(uint32_t ms); /* drains pipelined writes first */ /* --- BTC/GNT indirect-register + IQK trigger/poll primitives --- */ uint32_t btc_wait_ready(); diff --git a/src/jaguar3/Halrf8822e.cpp b/src/jaguar3/Halrf8822e.cpp index b1c08b6f..4191ec0a 100644 --- a/src/jaguar3/Halrf8822e.cpp +++ b/src/jaguar3/Halrf8822e.cpp @@ -84,9 +84,14 @@ void Halrf8822e::rf_write(uint8_t path, uint16_t addr, uint32_t mask, /* --- calibration (Phase C: ported incrementally, hardware-iterated) --- */ void Halrf8822e::delay_us(uint32_t us) { + /* A settle is measured from the write reaching the chip, so drain the + * pipelined queue first (free when it is empty; bounded by the queue + * depth when not). The µs sites include 2 ms and 10 ms waits. */ + _device.flush_writes(); std::this_thread::sleep_for(std::chrono::microseconds(us)); } void Halrf8822e::delay_ms(uint32_t ms) { + _device.flush_writes(); /* the settle time must follow the writes */ std::this_thread::sleep_for(std::chrono::milliseconds(ms)); } diff --git a/src/jaguar3/Halrf8822e.h b/src/jaguar3/Halrf8822e.h index 7b5c2807..c7fe4ce9 100644 --- a/src/jaguar3/Halrf8822e.h +++ b/src/jaguar3/Halrf8822e.h @@ -52,8 +52,8 @@ class Halrf8822e : public Jaguar3Calibration { void mac_write8(uint16_t addr, uint8_t val) { _device.rtw_write8(addr, val); } uint32_t rf_read(uint8_t path, uint16_t addr, uint32_t mask); void rf_write(uint8_t path, uint16_t addr, uint32_t mask, uint32_t val); - static void delay_us(uint32_t us); - static void delay_ms(uint32_t ms); + void delay_us(uint32_t us); /* drains pipelined writes first */ + void delay_ms(uint32_t ms); /* drains pipelined writes first */ /* --- DAC calibration (port of halrf_dac_cal_8822e / halrf_8822e.c) --- * 8822e DACK uses the AFE S0/S1 banks (0x3800/0x3900) rather than 8822c's BB diff --git a/src/jaguar3/RtlJaguar3Device.cpp b/src/jaguar3/RtlJaguar3Device.cpp index e4af4531..f15b143a 100644 --- a/src/jaguar3/RtlJaguar3Device.cpp +++ b/src/jaguar3/RtlJaguar3Device.cpp @@ -1,4 +1,5 @@ #include "RtlJaguar3Device.h" +#include "InitTimer.h" #include #include /* INT_MIN — "no radiotap DBM_TX_POWER" sentinel */ @@ -55,10 +56,34 @@ RtlJaguar3Device::RtlJaguar3Device(RtlAdapter device, Logger_t logger, variant == jaguar3::ChipVariant::C8822E ? "8822E/EU" : "8822C/CU"); } +/* Pipelined register writes for the whole bring-up (ITransport:: + * write_batch_begin): ends on scope exit so a throw never leaves the + * transport in batch mode for the threads that start afterwards. */ +struct WriteBatchScope { + RtlAdapter &dev; + bool open = true; + explicit WriteBatchScope(RtlAdapter &d) : dev(d) { dev.write_batch_begin(); } + /* Closes once: after end() the destructor is a no-op, so it never touches + * the transport again once the coex thread (which shares it) is running. + * Returns whether every queued write completed; the destructor's close + * (unwinding) drops that result, an explicit end() must act on it. */ + bool end() { + bool ok = true; + if (open) + ok = dev.write_batch_end(); + open = false; + return ok; + } + ~WriteBatchScope() { end(); } +}; + void RtlJaguar3Device::Init(Action_ParsedRadioPacket packetProcessor, SelectedChannel channel) { _channel = channel; _rx_wanted = true; + /* No WriteBatchScope here (yet): the pipelined bring-up is validated on + * the TX path (InitWrite, cold + warm); the RX-only + * Init path has not been measured with it on a ground-station card. */ _hal.rtw_hal_init(channel); /* full vendor-source bring-up */ /* Tune the channel/bandwidth (5/10 MHz ChannelWidth re-clocks to narrowband), * then run IQK calibration (it reads RF18 for the tuned channel). @@ -735,7 +760,42 @@ void RtlJaguar3Device::InitWrite(SelectedChannel channel) { * race the running TX). */ const bool want_rx = _cfg.rx.enable_with_tx; _rx_wanted = want_rx; + /* A second bring-up on a live device: the coex thread of the previous + * one shares the transport, and the batch below is single-threaded by + * contract, so stop and join it before anything is queued. A running RX + * loop (and its phydm worker) cannot be stopped from here — that is the + * caller's thread — so it is refused outright. */ + if (_rx_loop_active.load()) + throw std::runtime_error( + "Jaguar3: InitWrite while the RX loop is running — stop it first"); + if (_coex_thread.joinable()) { + _coex_stop = true; + _coex_thread.join(); + _coex_stop = false; + } + /* Readiness is provisional from here until the batch closes clean: a + * throw from any bring-up step (a failed queued write is only known at + * the close) must not leave the runtime APIs believing the chip is + * programmed — including a re-init that fails after a successful one. */ + struct BroughtUpGuard { + bool &flag; + bool committed = false; + ~BroughtUpGuard() { + if (!committed) + flag = false; + } + } brought_up_guard{_brought_up}; + _brought_up = false; + /* The transfer counter is a USB notion (xfers is emitted only when a + * counter is attached); a PCIe transport gets none, and its timer omits + * the field instead of reporting 0. */ + InitTimer timer(_logger, "j3init", + _device.is_usb() ? InitTimer::XferCounter{[this] { return _device.ctrl_xfers(); }} + : InitTimer::XferCounter{}, + [this] { _device.flush_writes(); }); + WriteBatchScope batch(_device); _hal.rtw_hal_init(channel); /* full vendor-source bring-up */ + timer.stage("hal_init"); /* 8822C at 40/80 MHz: IQK at 20 MHz, then retune — see Init. */ const bool iqk_at_20 = _variant == jaguar3::ChipVariant::C8822C && (channel.ChannelWidth == CHANNEL_WIDTH_40 || @@ -746,7 +806,9 @@ void RtlJaguar3Device::InitWrite(SelectedChannel channel) { SelectedChannel iqk_ch = channel; if (iqk_at_20) iqk_ch.ChannelWidth = CHANNEL_WIDTH_20; /* IQK command set follows the RF */ + timer.stage("set_channel"); _hal.run_iqk(iqk_ch); + timer.stage("iqk"); if (iqk_at_20) _radioManagement.set_channel_bwmode(channel.Channel, channel.ChannelOffset, channel.ChannelWidth); @@ -755,6 +817,7 @@ void RtlJaguar3Device::InitWrite(SelectedChannel channel) { _hal.dpk_force_bypass_8822e(); /* 8822e rfe 21/22: kernel bypasses DPK (after IQK) */ _hal.config_rfe(channel.Channel); /* 8822e RFE/PAPE antenna-switch pins (PA enable) */ _hal.config_channel_8822e(channel.Channel); /* 8822e band TX scaling/backoff + shaping */ + timer.stage("rx_path_rfe_channel"); /* DEVOURER_CW_TONE — a bare RF LO carrier. Armed HERE (before the FW power-mode * / coex H2C steps below, which on the 8812EU at 5 GHz leave the chip NAKing @@ -783,6 +846,7 @@ void RtlJaguar3Device::InitWrite(SelectedChannel channel) { } _logger->error("CW tone arm: USB glitch ({}) — retry {}/3", ex.what(), attempt); + _device.flush_writes(); /* settle from a drained queue before retrying */ std::this_thread::sleep_for(std::chrono::milliseconds(150)); } } @@ -790,6 +854,12 @@ void RtlJaguar3Device::InitWrite(SelectedChannel channel) { _device.rtw_write(0x0040, v40 | 0x14030008u); _device.rtw_write(0x0064, v64 & ~0x02040000u); } + /* This return leaves InitWrite early: close the batch here so a + * failed completion during the CW arm fails the call, instead of the + * scope destructor draining it and dropping the verdict. */ + if (!batch.end()) + throw std::runtime_error( + "Jaguar3: pipelined register write(s) failed during CW-tone arm"); _logger->info("Jaguar3: CW tone hold (minimal bring-up, no coex thread)"); return; } @@ -801,10 +871,12 @@ void RtlJaguar3Device::InitWrite(SelectedChannel channel) { * re-apply at the end of this function; this early one just keeps the * intermediate bring-up steps on sane references. */ apply_tx_power_current(/*full=*/true); - _brought_up = true; + timer.stage("txpower_pre"); + _brought_up = true; /* provisional — see BroughtUpGuard above */ /* WiFi-only coex bring-up: disable the BT/LTE antenna arbitration and lock the * antenna to WLAN so on-air TX is not killed by the coex firmware. */ _hal.coex_wlan_only_init(); + timer.stage("coex_wlan_only_init"); /* RFE GPIO/pad pinmux — the HalMAC "Config PIN Mux" (halmac_init_8822e) that * devourer's hand-rolled MAC init skips: route + drive the RFE PA-enable / * antenna-switch control pins. Without it the 8822e's PA pins are never driven @@ -825,9 +897,13 @@ void RtlJaguar3Device::InitWrite(SelectedChannel channel) { _device.rtw_write(0x0064, v64 & ~0x02040000u); /* PAD_CTRL1: RFE pads */ } + timer.stage("rfe_pinmux"); _hal.fw_set_pwr_mode_active(); /* keep all FW power domains on (no auto-PS) */ + timer.stage("fw_pwr_mode"); _hal.fw_coex_query_bt_info(); /* make the FW confirm BT is absent */ + timer.stage("fw_coex_query"); _hal.fw_coex_tdma_off(); /* disable coex time-division (WL keeps antenna) */ + timer.stage("fw_coex_tdma_off"); /* DEVOURER_BF_ARM_SOUNDER=1 — beamforming self-sounding probe (beamformer * side): arm the MAC's hardware sounding engine so a TX-descriptor-marked * NDPA (DEVOURER_TX_NDPA=1) is followed by a hardware-generated NDP. The MAC @@ -892,6 +968,7 @@ void RtlJaguar3Device::InitWrite(SelectedChannel channel) { * Applied before the coex thread starts so the writes don't contend. */ if (_cfg.tuning.disable_cca) SetCcaMode(true); + timer.stage("filters_cca"); /* DEVOURER_XTAL_CAP — crystal-cap trim (issue #217); before the coex thread * so the AFE write doesn't contend with the periodic coex re-apply. */ if (_cfg.tuning.xtal_cap) @@ -902,6 +979,7 @@ void RtlJaguar3Device::InitWrite(SelectedChannel channel) { * TX-power state (flat override / offset) only sticks when applied after * them. The coex thread's ~2 s ticks do not rewrite the refs. */ apply_tx_power_current(/*full=*/true); + timer.stage("txpower_post"); /* Per-packet power banks: the BB init table reset 0x1e70 (0x00001000, all * banks disabled) and may have cleared the per-STA RAM — re-sync the * hardware to the planner state (a pre-bring-up SetTxPacketPowerOffsetQdb @@ -931,6 +1009,19 @@ void RtlJaguar3Device::InitWrite(SelectedChannel channel) { _device.rtw_read32(a), _device.rtw_read32(a + 4), _device.rtw_read32(a + 8), _device.rtw_read32(a + 12)); } + timer.stage("dpdt_ack_misc"); + /* Sync writes from here: the coex thread shares the transport. A queued + * write that completed failed or short is only known at this close, and + * a chip with one register unprogrammed is not one to start the coex + * thread over and announce ready. */ + if (!batch.end()) + throw std::runtime_error( + "Jaguar3: pipelined register write(s) failed during bring-up"); + brought_up_guard.committed = true; + /* The timing closes here, before the coex thread starts: it shares the + * adapter's transfer counter, so anything emitted after it would count + * that thread's register and H2C traffic as bring-up. */ + timer.total(); _coex_thread = std::thread([this] { coex_runtime_loop(); }); if (_cfg.rx.ack_responder && !SetAckResponder(*_cfg.rx.ack_responder)) /* DEVOURER_ACK_RESPONDER */ diff --git a/src/jaguar3/RtlJaguar3Device.h b/src/jaguar3/RtlJaguar3Device.h index b2573898..fd4b3035 100644 --- a/src/jaguar3/RtlJaguar3Device.h +++ b/src/jaguar3/RtlJaguar3Device.h @@ -382,7 +382,7 @@ class RtlJaguar3Device : public IRtlRadio { * active (_rx_loop_active) the coex thread skips its C2H drain — the RX async * loop sees the C2H reports as part of its stream. */ std::thread _coex_thread; - volatile bool _coex_stop = false; + std::atomic _coex_stop{false}; /* written by Stop/~/re-init, read by the coex loop */ void coex_runtime_loop(); /* Nominal beacon interval in TU while a beacon is active (0 = none); the * AdjustBeaconTiming one-shot tweak restores to this. */ diff --git a/tests/j3_rf_window_readback.sh b/tests/j3_rf_window_readback.sh new file mode 100755 index 00000000..bc839ec7 --- /dev/null +++ b/tests/j3_rf_window_readback.sh @@ -0,0 +1,105 @@ +#!/usr/bin/env bash +# Does the Jaguar3 RF direct window hold anything above bit 19? +# +# The RF radio tables are applied as plain 20-bit writes to BB[0x3c00/0x4c00 +# + (rf_addr & 0xff) * 4] instead of the vendor's MASK20BITS read-modify- +# write. That is bit-identical to the RMW only if bits [31:20] of every +# window word are not storage the RMW could have preserved. Two legs, per +# die, both through `chipstate --init` (ops run on the configured chip): +# +# 1. histogram: dump both path windows after a bring-up and histogram the +# high 12 bits of every word (expected all 0). On its own this proves +# little, because the write-only load itself clears those bits. +# 2. write-back: for every word in each window (SAMPLE=N narrows it), poke the word with +# its high 12 bits SET (low 20 bits unchanged, so the RF register keeps +# its value), read it back, then restore. If the bits are storage they +# read back set and the RMW was preserving real state; if they read back +# 0 the RMW could never have preserved anything. This leg is what +# decides, and it does not depend on which bring-up ran first. +# +# Exit 0 only when both legs say the bits are not storage: a non-zero +# histogram fails leg 1 outright (the write-back leg is not run), and any +# poked word reading back with its high bits set fails leg 2. +# +# sudo tests/j3_rf_window_readback.sh 0xc812 # 8812CU +# sudo tests/j3_rf_window_readback.sh 0xa81a # 8812EU +set -euo pipefail +PID=${1:?usage: $0 } +ROOT=$(cd "$(dirname "$0")/.." && pwd) +CS=$ROOT/build/chipstate +OUT=${OUT:-/tmp/j3_rf_window_readback}; mkdir -p "$OUT" +SAMPLE=${SAMPLE:-256} # words per path window for the write-back leg (256 = the whole window) +case $SAMPLE in ''|*[!0-9]*) echo "FAIL: SAMPLE must be an integer 1..256 (got '$SAMPLE')"; exit 2;; esac +if [ "$SAMPLE" -lt 1 ] || [ "$SAMPLE" -gt 256 ]; then echo "FAIL: SAMPLE must be 1..256 (got $SAMPLE) — a probe of zero words proves nothing"; exit 2; fi +dump=$OUT/pid${PID}.peek +"$CS" --pid "$PID" --init --peek 0x3c00-0x3fff:4 --peek 0x4c00-0x4fff:4 \ + >"$dump" 2>"$dump.err" || { echo "FAIL: chipstate exited non-zero (leg 1)"; tail -5 "$dump.err"; exit 1; } +# leg 1 + the op list for leg 2 (poke set / peek / poke restore per word) +ops=$(python3 - "$dump" "$PID" "$SAMPLE" <<'PY' +import re, sys, collections +words = {} +for line in open(sys.argv[1]): + m = re.match(r'^0x([0-9a-fA-F]{4}):((?:\s+[0-9a-fA-F]{8}){1,4})\s*$', line) + if not m: continue + base = int(m.group(1), 16) + for i, w in enumerate(m.group(2).split()): + words[base + 4 * i] = int(w, 16) +if not words: + print("FAIL: no register rows parsed", file=sys.stderr); sys.exit(1) +hi = collections.Counter(w >> 20 for w in words.values()) +print(f"leg1 pid={sys.argv[2]} words={len(words)} hi12_histogram={dict(sorted(hi.items()))}", file=sys.stderr) +if set(hi) != {0}: + print("FAIL leg1: some window words hold bits above 19 after the bring-up — " + "contradicts the no-storage premise; the write-back leg is not run", file=sys.stderr) + sys.exit(1) +n = int(sys.argv[3]); ops = []; restore = [] +for base in (0x3c00, 0x4c00): + for a in range(base, base + 4 * n, 4): + v = words[a] + ops += [f"--poke 0x{a:04x}=0x{(v | 0xFFF00000):08x}:4", f"--peek 0x{a:04x}-0x{a+3:04x}:4", f"--poke 0x{a:04x}=0x{v:08x}:4"] + restore.append(f"--poke 0x{a:04x}=0x{v:08x}:4") +print(" ".join(ops)); print(" ".join(restore)) +PY +) || exit 1 +restore_ops=$(tail -n1 <<<"$ops"); ops=$(head -n1 <<<"$ops") +# Whatever happens once the first high-bit poke is out, put every sampled +# word back to its dump value. The chip stays configured after chipstate +# exits (its device teardown does not de-init), so a plain attach suffices. +finish() { + local rc=$? + # shellcheck disable=SC2086 + if ! "$CS" --pid "$PID" $restore_ops >"$OUT/pid${PID}.restore" 2>&1; then + echo "FAIL: restore pass failed — window words may be left modified (see $OUT/pid${PID}.restore)" >&2 + [ "$rc" -ne 0 ] || rc=1 # an unrestored radio is not a passing run + fi + exit "$rc" +} +trap finish EXIT +wb=$OUT/pid${PID}.writeback +# shellcheck disable=SC2086 +"$CS" --pid "$PID" --init $ops >"$wb" 2>"$wb.err" || { echo "FAIL: chipstate exited non-zero (leg 2)"; tail -5 "$wb.err"; exit 1; } +python3 - "$wb" "$PID" "$SAMPLE" <<'PY' +import re, sys +# Each poke is followed by its own one-word peek, printed as a 16-byte row +# with the other three columns blank; a row may still carry 1-4 words, so +# every word on it is checked. The count must equal the pokes issued. +vals = [] +for l in open(sys.argv[1]): + m = re.match(r'^0x([0-9a-fA-F]{4}):((?:\s+[0-9a-fA-F]{8}){1,4})\s*$', l) + if m: + vals += [int(w, 16) for w in m.group(2).split()] +n = int(sys.argv[3]) +# The peeks were issued in this exact order (path A window, then path B), +# one word each, so the values pair with these addresses — not with the +# printed row base, which is the 16-byte row the word sits in. +addrs = [a for base in (0x3c00, 0x4c00) for a in range(base, base + 4 * n, 4)] +if len(vals) != len(addrs): + print(f"FAIL: parsed {len(vals)} read-back words, expected {len(addrs)} (one per poke)"); sys.exit(1) +rows = list(zip(addrs, vals)) +bad = [(a, v) for a, v in rows if v >> 20] +print(f"leg2 pid={sys.argv[2]} words_poked_with_hi_bits_set={len(rows)} read_back_nonzero_hi={len(bad)}") +for a, v in bad: print(f" 0x{a:04x} -> 0x{v:08x}") +if bad: + print("VERDICT: bits [31:20] ARE storage on this die — keep the MASK20BITS RMW"); sys.exit(1) +print("VERDICT: bits [31:20] are not storage (written 1s read back 0) — the write-only load is bit-identical to the RMW") +PY diff --git a/tests/j3_tx_flood_ab.sh b/tests/j3_tx_flood_ab.sh new file mode 100755 index 00000000..29bcc87a --- /dev/null +++ b/tests/j3_tx_flood_ab.sh @@ -0,0 +1,37 @@ +#!/usr/bin/env bash +# TX-side A/B of two devourer trees on one Jaguar3 DUT: N reps of a timed +# txdemo flood per tree, reporting per rep the frames submitted, the bulk-OUT +# failures and the failed synchronous register reads. Alternates trees rep by +# rep so a slow drift in the unit (warm state, ambient) lands on both sides. +# +# sudo tests/j3_tx_flood_ab.sh [reps] [secs] +set -euo pipefail +PID=${1:?pid}; CH=${2:?channel}; A=${3:?treeA}; B=${4:?treeB}; REPS=${5:-3}; SECS=${6:-15} +OUT=${OUT:-/tmp/j3_tx_flood_ab/pid${PID}_ch${CH}}; mkdir -p "$OUT" +run() { + # Logs and lines are keyed by side (A/B) so two checkouts that share a + # directory name cannot overwrite each other; the basename is context. + local side=$1 tree=$2 rep=$3 n; n="$side:$(basename "$tree")" + local log=$OUT/${side}_rep${rep} + local rc=0 + env DEVOURER_PID="$PID" DEVOURER_CHANNEL="$CH" DEVOURER_LOG_LEVEL=info \ + timeout -s INT "$SECS" "$tree/build/txdemo" >"$log.jsonl" 2>"$log.err" || rc=$? + # 124 = timeout fired (the normal end), 0/130 = txdemo took the INT itself. + case $rc in 0|124|130) ;; *) echo "$n rep$rep: txdemo exited rc=$rc"; tail -3 "$log.err"; failed=1;; esac + local submitted fail rd first + # Submitted frames: the final tx.stats event ("final":1) carries the + # cumulative tally; a run without one did not finish and is a failure. + submitted=$(grep -F '"ev":"tx.stats"' "$log.jsonl" | grep -F '"final":1' | tail -n1 \ + | grep -oE '"submitted":[0-9]+' | grep -oE '[0-9]+$' || true) + [ -n "$submitted" ] || { submitted='?'; echo "$n rep$rep: no final tx.stats event"; failed=1; } + fail=$(grep -c 'bulk_send EP .* FAIL' "$log.err" || true) + rd=$(grep -c 'rtw_read(' "$log.err" || true) + first=$(grep -F '"ev":"init.timing"' "$log.jsonl" | grep -F '"stage":"txdemo.first_tx_submit"' \ + | grep -oE '"ms":[0-9]+' | grep -oE '[0-9]+$' | head -n1 || true) + [ -n "$first" ] || { first='?'; echo "$n rep$rep: no txdemo.first_tx_submit event"; failed=1; } + echo "$n rep$rep: first_tx_ms=$first submitted=$submitted bulk_fail=$fail read_fail=$rd" +} +failed=0 +for r in $(seq 1 "$REPS"); do run A "$A" "$r"; run B "$B" "$r"; done +# Every rep is still reported, but a crashed or failed run fails the script. +exit "$failed" diff --git a/tests/regress.py b/tests/regress.py index 4b10f8d1..b18552c2 100755 --- a/tests/regress.py +++ b/tests/regress.py @@ -217,6 +217,7 @@ def _mediatek_duts() -> dict[str, str]: "0bda:b811": "RTL8811AU", "2357:012d": "RTL8822BU (TP-Link T3U, Jaguar2)", "0bda:b82c": "RTL8822BU (Jaguar2)", + "0bda:b812": "RTL8822BU (CF-924AC V2, Jaguar2)", "0bda:c811": "RTL8821CU (Jaguar2)", "0bda:c812": "RTL8812CU (Jaguar3)", "0bda:c82c": "RTL8822CU (Jaguar3)",