diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index 4e5f52b..2c12374 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -54,6 +54,10 @@ jobs: env: ${{ matrix.env }} version: ${{ steps.ver.outputs.version }} + # No dependency cache here on purpose: test_typed_store_iterator is a + # tripwire on a branch-pinned lib_dep, and platformio.ini's [env:native] + # comment says what caching .pio/libdeps would cost it and what key any + # cache added here would need. tests: name: unit tests (native) runs-on: ubuntu-latest diff --git a/data/index.html b/data/index.html index 016c4cb..24f7d07 100644 --- a/data/index.html +++ b/data/index.html @@ -99,6 +99,26 @@

Community bulletin board

function fmtAge(s) { return s < 60 ? s + " s" : s < 3600 ? Math.floor(s/60) + " min" : Math.floor(s/3600) + " h"; } +// Whether an empty path list means "nothing there" or "not read yet". +// +// The node's own rule, off the node's own two fields: the path rows are +// published only once a snapshot pass has been all the way round the table, +// and the node says so only while they are still a whole answer for it +// (diag.tables.snap_rows_whole), while path_count is the table's size and is +// exact from the first pass. So a node bigger than one pass serves a count +// with no rows under it, and this page used to render that as +// "Transport node - 500 known paths" over nothing at all. The same rule is +// Snapshot::stillReadingPaths() in src/rns/RnsTransport.h, which the display +// pages ask; if it sharpens there it has to sharpen here. +// +// Explicitly false rather than falsy: a document without the field is a page +// and a firmware from different builds, and that is the asset stamp's +// complaint to make, not a claim about the path table. +function stillReadingPaths(s) { + const t = s.transport, d = s.diag && s.diag.tables; + return !!(t && d && t.path_count > 0 && d.snap_rows_whole === false); +} + // What the card in the slot is, for the one line this page gives the store. // Whether it may be taken at all is the node's answer — sd.can_adopt, the same // one the settings page's button is drawn from — and this does not re-derive @@ -318,6 +338,12 @@

Community bulletin board

e.textContent = "<" + p.hash.slice(0, 12) + "…> " + p.hops + " hop" + (p.hops === 1 ? "" : "s") + " via " + p.via + " · " + fmtAge(p.age_s) + " ago"; tr.append(e); } + if (!(s.transport.paths || []).length && stillReadingPaths(s)) { + const e = document.createElement("div"); e.className = "post"; + e.textContent = "Still reading " + s.transport.path_count + " path" + (s.transport.path_count === 1 ? "" : "s") + + " — rows appear once a pass has been all the way round the table."; + tr.append(e); + } } const nb = $("neighbors"); nb.replaceChildren(); diff --git a/docs/api.md b/docs/api.md index 1ec4c41..64b173f 100644 --- a/docs/api.md +++ b/docs/api.md @@ -145,7 +145,10 @@ the ordinary reading on the shipped channel and needs no action. "stacks": { "loopTask": 3120, "rns": 6284, "radio": 2960, "gps": 1180 }, "stack_lowest": 1180, "stack_lowest_task": "gps", "tables": { "paths": 3, "links": 1, "links_active": 1, "links_pending": 0, - "destinations": 2, "announces": 0, "announces_held": 0, "rates": 4 } }, + "destinations": 2, "announces": 0, "announces_held": 0, "rates": 4, + "snap_walk_max_ms": 62, "snap_walk_pos": 3, + "snap_budget_stops": 0, "snap_rows_whole": true, + "snap_interval_ms": 5000 } }, "radio": { "online": true, "model": "SX1276", "freq_mhz": 868.1, "bw_khz": 125, "sf": 8, "cr": 5, "tx_dbm": 7, "sync_word": 18, "preamble": 18, "announce_interval": 600, "beacon_interval": 0, "callsign": "retimesh-8249CC", @@ -176,8 +179,10 @@ the ordinary reading on the shipped channel and needs no action. "interfaces": [ { "name": "LoRa", "mode": "full", "rx_bytes": 1234, "tx_bytes": 567 }, { "name": "WiFi/10.42.0.2:51022", "mode": "full", "rx_bytes": 0, "tx_bytes": 0 }, { "name": "Auto/fe80::2cdb:d4ff:fe82:1f20", "mode": "full", "rx_bytes": 9012, "tx_bytes": 3400 } ], - "path_count": 2, - "paths": [ { "hash": "5168bb90…", "hops": 1, "via": "WiFi/10.42.0.2:51022", "age_s": 40 } ] }, + "path_count": 3, "interface_count": 3, "snapshot_age_s": 2, + "paths": [ { "hash": "5168bb90…", "hops": 1, "via": "WiFi/10.42.0.2:51022", "age_s": 40 }, + { "hash": "a31c7d04…", "hops": 2, "via": "LoRa", "age_s": 112 }, + { "hash": "bf40e2a7…", "hops": 1, "via": "Auto/fe80::2cdb:d4ff:fe82:1f20", "age_s": 7 } ] }, "neighbors": [ { "name": "Anonymous Peer", "version": "", "kind": "announce", "hash": "5168bb90…", "aspect": "lxmf.delivery", "hops": 0, "via": "wifi", "rssi": 0, "snr": 0, "age_s": 40, "count": 3 } ] } @@ -258,10 +263,14 @@ catches up on the passes that follow. - **Zero** is the ordinary reading on any normal channel. - **A small total that stops growing** is that catch-up, and needs nothing. -- **Rising steadily** means frames are arriving faster than this node takes - them off the ring, for long stretches. Still nothing dropped: the counter to - read next to it is `rx_dropped_ring`, which is the radio finding no room left - in the ring, and that one *is* loss. +- **Rising steadily** — read `diag.tables.snap_budget_stops` first. A node whose + path-table walk is cut off on every pass opens that gap itself, every five + seconds, for as long as its table stays too big to read in one pass; the + `snap_*` fields under `diag.tables`, described below, are where a gap is + diagnosed, and this counter only shows what one cost. With `snap_budget_stops` + flat, frames really are arriving faster than this node takes them off the + ring. Either way nothing has been dropped by the cap: the counter that *is* + loss is `rx_dropped_ring`, the radio finding no room left in the ring. It is on the console's `STATUS` line as `rx_drain_capped=`, printed after the `rx=`/`tx=` pair it belongs with and before the two carrier-sense counters. @@ -392,6 +401,73 @@ SD card) are omitted rather than reported as zero. climbs and never falls is where a week-long run runs out of memory, and it is the part a heap figure alone will not explain. +The `snap_*` fields beside them describe the pass that reads the path table, +because on a large table that pass no longer sees all of it at once. It runs +every five seconds under a budget, reading path records back off the filesystem, +and carries a cursor from one pass to the next. + +- `snap_walk_max_ms` — the longest one pass has taken since boot, the walk plus + the removal of dead entries that follows it. Tens of milliseconds is ordinary. + A figure in the seconds means the Reticulum task is spending that long not + forwarding, on a filesystem or a table that has gone past what this node can + read in a pass. +- `snap_walk_pos` — how far the last pass got, as an offset into the table. A + pass ends in one of three ways and the offset reads differently in each, so + it means nothing read on its own: + - **at or past `paths`** — it reached the end of the table. (Past, on a pass + that went on to remove dead entries: `paths` is read after the removal.) + - **below `paths`, `snap_budget_stops` not moving** — the row cap of 64 rows + filled and nothing else wanted the rest of the table. This is the ordinary + end of a pass on any node holding more than 64 paths, `snap_rows_whole` is + `true` beside it, and the next pass starts again at the **front** rather + than from this offset. + - **below `paths`, `snap_budget_stops` climbing** — the budget cut the pass + off there, and the next one carries on from that offset. +- `snap_budget_stops` — how many passes the budget has ended since boot. Zero on + a node that walks its table comfortably. Climbing steadily means every pass is + being cut off: survivable, because the cursors resume where they stopped, but + it is the node saying its table has outgrown a single pass. +- `snap_rows_whole` — whether the `transport.paths` rows above are a complete + cycle **over the table as it now stands**. A pass cut off by the budget keeps + its partial list to itself rather than publishing a prefix that looks like the + whole table, so a published list is complete for the table the cycle that + built it closed over. It is not a latch: a cycle that closed below the row cap + of 64 stops counting as whole once `paths` has grown past what it covered, and + a cycle that closed **at** the cap stays whole whatever `paths` grows to, + because the cap and not the cycle is what ended that list. `false` beside a + non-zero `paths` is a node part-way through reading its own table — it has + never got all the way round, or its table has outgrown the last time it did. + The count is exact either way; the list is the older one rather than a + misleading prefix. A table the walk gets round inside one pass closes a cycle + on every pass and so never reads `false` at all; a bigger one reads `false` + for the passes of the cycle that follows the growth — four of the five a + cap-filling cycle takes at the per-record cost this firmware links — and a + table holding more than 64 renderable paths closes its cycles at the cap, so + it reads `true` from the first cycle that fills however much it grows + afterwards. +- `snap_interval_ms` — how long the node is currently leaving between two + passes, and the only field here that explains the others going stale. `5000` + on any node whose last pass cost less than a quarter of that, which is every + node under any cost this firmware has been measured at. A larger figure is the + node having measured its own pass and given itself room: a pass costing more + than a quarter of its window is scheduled four times its own cost out, up to a + ceiling of 60 s — the minute between dead-path sweeps, which is the slowest + clock a pass carries and so the least often passes may come. Read it before + concluding a reading is fresh: at anything above `5000`, `snapshot_age_s` and + the path rows are older than the five seconds they would otherwise imply, and + the node is telling you a pass has become expensive. `snap_walk_max_ms` beside + it says how expensive — with one exception: a pass that *failed* part-way buys + the same gap, off what it had spent before it failed, and it never reaches the + high-water mark. `diag.faults.contained` climbing beside a raised interval + with `snap_walk_max_ms` flat is that node. + +`tables.paths` and `transport.path_count` are the whole table on every pass +whatever the walk did: they are the table's own size and are never truncated. +`transport.paths` is a capped list of rows out of it — at most 32 here, out of +the 64 a pass collects — and on a table that takes several passes to walk it can +be a cycle older than `transport.snapshot_age_s`, which is the age of the +reading as a whole. + `airtime` reports channel use and the transmit budget: `{"short_pct":0.46,"long_pct":0.02,"band":"869.4-869.65 (10 %)", "band_limit_pct":10,"band_allocated":true,"duty_limit_pct":9.5, diff --git a/docs/development.md b/docs/development.md index 0059fb8..d24a24e 100644 --- a/docs/development.md +++ b/docs/development.md @@ -290,6 +290,8 @@ them on every push. | `test_telemetry` | what the node says about itself: sensor shapes, msgpack str against bin, and that a document too big is not sent half-written | | `test_nomadnet` | the node's own page: what it says, what it refuses to claim, and that a page never overruns the buffer a stranger asked it to fill | | `test_client_admit` | who gets one of the node's TCP client slots on :4242, and above all what a refusal costs: that a context which cannot be allocated or cannot be enrolled is given back and its client closed, rather than either being leaked or the node aborting | +| `test_snapshot_walk` | the bound on the path-table walk that keeps it from starving the task underneath it: that the budget covers every position and not just the sweep, that both cursors resume and never run backwards, that the sweep gets a share of each pass so its cursor always advances, that only a whole row cycle is published, and that a pass which outgrows its window schedules the next one further out | +| `test_typed_store_iterator` | not our code but the promise the path-table walk rests on: that stepping a microStore iterator reads nothing and dereferencing is the only thing that opens a file. Held on both halves — `TypedStore` over a counting fake, and a real `BasicFileStore` over a counting RAM filesystem. It goes red when the pinned upstream branch moves the wrong way, not when this repository changes | ### HDLC fuzzing and the sanitizer gate diff --git a/docs/troubleshooting.md b/docs/troubleshooting.md index f40a5fb..15b2378 100644 --- a/docs/troubleshooting.md +++ b/docs/troubleshooting.md @@ -30,7 +30,7 @@ ROM, and a power cycle boots whatever is in flash. | The `radio self-test:` line stopped appearing in the boot log | it passed once and the verdict is remembered against this exact image, so the transmission is not re-paid on every boot — the point being a node brown-out looping on a flat battery | expected, and a pass is **not** silent: later boots of that image say `radio self-test: skipped — this exact image already proved the IRQ line on GPIO n`. Flashing any different build runs it again, including a rebuild of the same version. See [hardware.md](hardware.md#the-radio-self-test-and-why-it-stops-appearing) | | No `radio self-test:` line at all — neither a result nor a `skipped` | either this board does not run the test (it is on only where the interrupt pin was in doubt: the five Heltecs, the two SX1280 T3-S3 variants and the ThinkNode M9 — the plain T3-S3, T-Beam, T-Deck and QSPI boards never print it), or the radio never came up, so `begin()` returned before it got there | **silence is not a pass** — read the line above it. `SX12xx online: …` means the chip answered and this board simply does not run the check; `No LoRa transceiver found` or `SX1262 init failed` means there was nothing to test yet. A *failure* is loud and is never remembered: `NO TxDone interrupt after …`, every boot, until the wiring is fixed | | The node is `radio=online` with rx/tx counting normally, but everything it sends goes out seconds late and throughput is a fraction of what it was | the carrier-sense probe is not being answered: `STATUS` shows `cad_timeouts=` climbing (or `cad_arm_errors=`), and `/api/status` the same two under `radio`. A probe that does not report is read as a busy channel — the safe direction, and the reason nothing else looks wrong — so every packet waits the whole CSMA deferral and none of them was ever measured against the air. Usually the interrupt line: the pin the board header names is not the one the chip raises, which the radio self-test proves for RxDone but not for the DIO the scan uses. It can also be a wedged part | on a healthy node both counters are **zero whatever the traffic**, so any sustained rise is a fault and not a busy channel. The log says which and how often (`CAD did not report within … ms` / `CAD could not be armed, code …` — the first immediately, then at most one a minute). Check `PIN_LORA_DIO1` (`PIN_LORA_DIO0` on an SX127x) against the board, and power-cycle to rule out a wedged chip; `cad_arm_errors` with a RadioLib code is a driver refusal, not wiring | -| `STATUS` shows `rx_drain_capped=` climbing on the radio line, and nothing else has changed | the Reticulum task takes frames off the RX ring a bounded batch at a time, and this counts the passes whose batch ended with frames still queued. It is **not a loss counter** — what a batch leaves stays in the ring and is taken on the next pass. The interval between two of those passes is not the task's ten-millisecond tick: the same pass goes on to refresh the status snapshots, and walking the path table there can spend 400 ms or more first — that figure is the walk's budget, and it is a floor under the gap rather than a ceiling over it — so on a fast channel (SF7 at the widest bandwidth the part offers) more than one batch of frames can arrive while it is away | expected, in small totals that stop growing — that is the node catching up after a sweep, and nothing was dropped. The counter to read beside it is `rx_dropped_ring` (`/api/status`: `radio.rx_dropped_ring`), which is the radio finding no room left in the ring; **that** one is real loss and means the Reticulum task is not keeping up at all. A steadily rising `rx_drain_capped` with `rx_dropped_ring` at zero is a busy channel the node is still handling. [api.md](api.md) has both in full | +| `STATUS` shows `rx_drain_capped=` climbing on the radio line, and nothing else has changed | the Reticulum task takes frames off the RX ring a bounded batch at a time, and this counts the passes whose batch ended with frames still queued. It is **not a loss counter** — what a batch leaves stays in the ring and is taken on the next pass. The interval between two of those passes is not the task's ten-millisecond tick: the same pass goes on to refresh the status snapshots, and walking the path table there can spend 400 ms or more first — that figure is the walk's budget, and it is a floor under the gap rather than a ceiling over it — so on a fast channel (SF7 at the widest bandwidth the part offers) more than one batch of frames can arrive while it is away | expected, and nothing was dropped — that is the node catching up on the following pass. A total that **keeps climbing** is expected too, and is the reading this row used to get wrong: the budget covers the whole walk, so every pass it ends opens that gap, and on a table too big to read in one pass it ends most passes, every five seconds, for as long as the table stays that big. Read `/api/status` `diag.tables.snap_budget_stops` before the radio: rising beside this counter, the node is producing its own gap. The counter to read beside it is `rx_dropped_ring` (`/api/status`: `radio.rx_dropped_ring`), which is the radio finding no room left in the ring; **that** one is real loss and means the Reticulum task is not keeping up at all. A steadily rising `rx_drain_capped` with `rx_dropped_ring` at zero is a node still handling everything it hears — whether that is a busy channel or its own path table is what `snap_budget_stops` says. [api.md](api.md) has both in full | | A client's traffic through the node is slow, nothing reports a drop, and every counter reads healthy | the node is being outrun on the inbound side: `STATUS` shows `tcp_drain_capped=` climbing beside `tcp_clients=`, and `/api/status` the same figure as `peers.tcp_drain_capped`. Packets from Reticulum TCP clients and from AutoInterface peers share one inbound ring, which the Reticulum task drains a bounded batch at a time; this counts the passes whose batch ended with traffic still queued. The cap is also why nothing else looks wrong — it is what keeps a flooded ring from holding that task past its watchdog, and what it defers is drained on the following pass, so it loses nothing and this counter is the only outward sign | zero is the normal reading, so any sustained rise means a peer is sending faster than this node can route: the node stays online, keeps its clients and simply routes late. Whether it has gone as far as a real drop is in the log rather than in a counter — `TCP-in ring full, dropping …-byte packet` from a Reticulum TCP client, `AutoInterface: inbound ring full, dropping … bytes` from an AutoInterface peer, both the producer giving up after waiting 20 ms for room. [api.md](api.md) has the counter in full | | OLED shows the previous firmware's screen | panel never re-initialised | ≥ v0.0.2 re-inits at boot | | A message to a peer you have definitely seen fails, or sits queued for about fifteen seconds first | Reticulum will not send to a destination it has no *route* to, and a route expires long before the peer does. The node now asks for one — `lxmf: no path to yet; asked for one` — waits up to 15 s, and sends the moment it arrives. Before this it did not ask at all, so the message was spent on a send that could not leave | the wait is normal on a peer whose path has aged out; the announce that refreshes it comes at whatever interval that peer chose, up to 12 hours. If it fails, the glass now says which: **no path** (asked, nobody answered), **no key** (its identity was never learned — you need one of its announces first), **node busy** (this node's own outbound queue was full), **could not build** (the message would not fit or sign). Only the first two are about the mesh | diff --git a/platformio.ini b/platformio.ini index 7cd27c0..32a7712 100644 --- a/platformio.ini +++ b/platformio.ini @@ -595,6 +595,42 @@ lib_deps = ; family's mask against the library's own constants and its own IRQ map. ; Same version the firmware links, above. jgromes/RadioLib @ ^7.7.1 + ; The same microStore the firmware links, for test_typed_store_iterator. + ; That suite asserts on the library itself the property the path-table + ; walk in refreshSnapshots() is built on — that stepping an iterator does + ; not read a record, only dereferencing one does. The dep is pinned to a + ; branch, not a commit, so the property can move under us; asserting it + ; here is how we find out at `pio test` rather than on a pole. + ; + ; Which only works while CI re-resolves that branch every run, and it + ; does: a git lib_dep is not installed into ~/.platformio, it is cloned per + ; project into .pio/libdeps//. That directory is gitignored, a fresh + ; checkout starts without it, and no job in .github caches it — so every + ; run, firmware jobs included, clones the branch afresh. The ~/.platformio + ; cache those jobs do carry (.github/actions/build-firmware) holds + ; toolchains, platforms and registry downloads, not this clone; the `tests` + ; job not sharing that step is not what keeps the tripwire honest. + ; + ; What would blunt it is caching .pio or .pio/libdeps — the tempting + ; companion to the ~/.platformio step. Keyed on hashFiles('platformio.ini') + ; the key would not move when upstream commits, because an upstream commit + ; does not change this file: the clone would stick at whatever commit first + ; filled the cache and this suite would read green through the regression + ; it exists to find. A prefix restore-key of the kind that step already + ; carries (pio--) widens that — on a key miss it serves the + ; newest entry with the matching prefix, so even a key that did move can be + ; answered by an older tree. Any cache of the dependency tree here needs a + ; key that moves when the branch does. + ; + ; Header-only and host-clean: library.json builds no sources (srcFilter + ; -<*>), and neither header the suite includes reaches outside microStore's + ; own headers and the host C/C++ and POSIX ones. The library's only + ; is in Utility.h, behind #if defined(ARDUINO); without it that + ; header takes / and File.h takes the library's own + ; Stream.h. What does need Arduino is the Adapters/ directory + ; (LittleFSFileSystem.h and its siblings), which nothing on this path + ; includes. + microStore=https://github.com/dobrevit/microStore.git#retimesh/combined build_flags = -std=c++17 -I test/stubs diff --git a/src/Config.h b/src/Config.h index 7107c94..96da813 100644 --- a/src/Config.h +++ b/src/Config.h @@ -579,6 +579,14 @@ // through microStore (flash or SD), so this is deliberately unhurried. #define SNAPSHOT_INTERVAL_MS 5000 #define SNAPSHOT_MAX_PATHS 64 +// How often dead paths are swept out, which is a slower clock than the reading +// is refreshed on: the reading is capped and cheap, the sweep walks the whole +// table. It is also the ceiling the pass scheduler is held to — a pass carrying +// a minute's clock has to come round at least once a minute or that clock is +// not honoured at all (Rns::nextIntervalMs) — so the firmware and the host +// tests that drive that scheduler read the same figure from here rather than +// each writing 60000 out for itself. +#define SNAPSHOT_SWEEP_INTERVAL_MS 60000 #define SD_LOG_MAX_BYTES (1024UL * 1024UL) // --------------------------------------------------------------------------- @@ -1608,9 +1616,17 @@ struct NodeStats { // batch at a time (RingDrain.h) and what a batch leaves stays in the ring for // the next pass, so this counts passes rather than frames. It rises when // frames arrived faster than one pass could take them — the pass after a - // full-budget path-table sweep is the case to expect, since two drains can be - // 400 ms apart rather than 10. Real loss on this path is loraRxDropRing - // above, which is what the producer counts when the ring has no room left. + // full-budget path-table walk is the case to expect, since two drains can be + // 400 ms apart rather than 10. + // + // The walk, not the sweep: the budget covers the whole pass now, the rows + // included, so the gap is any pass the budget ends and not only one that was + // cleaning up. On a table too big to read in one pass that is most passes, + // for as long as the table stays that big, so a total that climbs steadily is + // this node getting round its own table rather than a channel fault — + // RnsTransport.h's snapBudgetStops is what tells the two apart. Real loss on + // this path is loraRxDropRing above, which is what the producer counts when + // the ring has no room left. volatile uint32_t loraRxDrainCapped = 0; // passes the batch cap ended with more queued // The other half of the radio's health, on the transmit side. A carrier-sense // probe that never reports is read as a busy channel — the only safe reading diff --git a/src/main.cpp b/src/main.cpp index 19c095c..4e2a2ac 100644 --- a/src/main.cpp +++ b/src/main.cpp @@ -592,9 +592,12 @@ void loop() { // (RingDrain.h). They are here because the cap is what keeps a full ring // from holding that task past the watchdog — so with it in place, a node // routing late has no other outward sign at all. On the radio side the pass - // after a full-budget path-table sweep is the case to expect, since two - // drains can be 400 ms apart rather than 10; what was really lost there is - // the "ring" figure in the line above. + // after a full-budget path-table walk is the case to expect, since two + // drains can be 400 ms apart rather than 10 — and on a table too big to + // read in one pass that is most passes rather than the odd one, so a total + // that climbs steadily is the `stops` figure in the tables line below + // rather than the channel. What was really lost is the "ring" figure in the + // line above. if (g_stats.loraRxDrainCapped || g_stats.tcpDrainCapped) log_i("drain cap: lora %u passes, tcp inbound %u passes ended with more " "queued (nothing dropped; the rest went on the following pass)", @@ -602,11 +605,24 @@ void loop() { // Reticulum's tables are the other thing that grows with traffic, and the // one a heap figure alone will not explain. RnsTransport::Tables t = RnsTransport::tables(); - log_i("tables: paths %lu links %lu (%lu active, %lu pending) dests %lu announces %lu (%lu held) rates %lu snap %lums", + // The five snapshot figures travel together on purpose. The worst pass on + // its own cannot tell a node that finished its table in 380 ms from one cut + // off at 400: `pos` against `paths` says how far the last pass actually + // got, `stops` says how often the budget has ended one, `rows` says whether + // what /api/status and the panels are showing is still a whole list for the + // table as it now stands — "partial" is a node that has never managed to + // build one, or one whose table has outgrown the last it did — and `every` + // is how often a pass happens at all — 5000 ms until a pass costs enough to + // buy itself room, and the only figure here that explains the rest going + // stale (RnsTransport.h). + log_i("tables: paths %lu links %lu (%lu active, %lu pending) dests %lu announces %lu (%lu held) rates %lu " + "snap %lums pos %lu stops %lu rows %s every %lums", (unsigned long)t.paths, (unsigned long)t.links, (unsigned long)t.activeLinks, (unsigned long)t.pendingLinks, (unsigned long)t.destinations, (unsigned long)t.announces, (unsigned long)t.heldAnnounces, (unsigned long)t.rates, - (unsigned long)t.snapWalkMaxMs); + (unsigned long)t.snapWalkMaxMs, (unsigned long)t.snapWalkPos, + (unsigned long)t.snapBudgetStops, t.snapRowsWhole ? "whole" : "partial", + (unsigned long)t.snapIntervalMs); #if HAS_GPS // The satellite count is the number that tells you whether the antenna // has a view of the sky; the sentence count tells you the receiver is diff --git a/src/net/WifiManager.cpp b/src/net/WifiManager.cpp index 93ba4f5..74804b4 100644 --- a/src/net/WifiManager.cpp +++ b/src/net/WifiManager.cpp @@ -1777,6 +1777,31 @@ void WifiManager::handleStatus(AsyncWebServerRequest* request) { doc["heap_min_free"] = g_stats.heapMinFree; doc["psram_free"] = ESP.getFreePsram(); + // One reading of the Reticulum tables for the whole document, taken here + // because the two halves of it are served four hundred lines apart: the + // `diag.tables` object below, and the interfaces, counts and path rows under + // `transport` near the end. Taken as tables() there and snapshot() here, they + // were two acquisitions of the snapshot lock with a refresh free to land + // between them — so this document could carry snap_rows_whole from one pass + // beside a path_count and rows from another, which is exactly the pair + // Snapshot::stillReadingPaths() combines (RnsTransport.h). A reply that + // contradicts its own predicate is worse than a stale one. + // + // Sized for every interface Transport can hold — the radio, the clients and + // the Auto peers. Sized for the clients alone, this listed the first five and + // quietly left the rest out. Off the stack because that is a kilobyte and a + // half on a task that has other things to do with it, and off the heap for + // the reason given at the peer list further down: asked for on every poll, it + // is the size that a long-running node can no longer find in one piece, and + // failing to find it aborted the node. Safe as statics because /api handlers + // all run on the one AsyncTCP service task, so no two are ever inside this at + // once (platformio.ini pins CONFIG_ASYNC_TCP_RUNNING_CORE and the library + // runs a single one). + static RnsTransport::IfaceInfo ifs[RNS_MAX_INTERFACES]; + static RnsTransport::PathInfo ps[32]; + const RnsTransport::Snapshot rnsSnap = + RnsTransport::snapshot(ps, 32, ifs, RNS_MAX_INTERFACES); + // Everything a soak run needs to read off a node it cannot reach a console // on: why it last restarted, how long that run lasted, and what it is // running out of. See Diag.h. @@ -1835,7 +1860,9 @@ void WifiManager::handleStatus(AsyncWebServerRequest* request) { dg["stack_lowest"] = lowest; dg["stack_lowest_task"] = lowestName ? lowestName : "none"; - RnsTransport::Tables t = RnsTransport::tables(); + // From the one reading taken at the top of this handler, not a second + // acquisition: Snapshot carries the same Tables tables() returns. + const RnsTransport::Tables& t = rnsSnap.tables; JsonObject tb = dg["tables"].to(); tb["paths"] = t.paths; tb["links"] = t.links; @@ -1845,6 +1872,23 @@ void WifiManager::handleStatus(AsyncWebServerRequest* request) { tb["announces"] = t.announces; tb["announces_held"] = t.heldAnnounces; tb["rates"] = t.rates; + // The snapshot walk's own health, which nothing served before. A soak run + // watching `paths` climb had no way to tell whether the node was still + // reading its own table: snap_walk_max_ms is the worst pass, snap_walk_pos + // against `paths` is how far the last one got, snap_budget_stops counts the + // passes the budget ended, and snap_rows_whole says whether the `paths` + // list this API serves is a complete cycle (RnsTransport.h). + // + // snap_interval_ms is the one that explains the others going stale: 5000 on + // any ordinary node, and more where the node measured a pass costing more + // than a quarter of its window and scheduled itself accordingly. Without it + // a reader has no way to know the age of everything above is not the five + // seconds it assumes. + tb["snap_walk_max_ms"] = t.snapWalkMaxMs; + tb["snap_walk_pos"] = t.snapWalkPos; + tb["snap_budget_stops"] = t.snapBudgetStops; + tb["snap_rows_whole"] = t.snapRowsWhole; + tb["snap_interval_ms"] = t.snapIntervalMs; } JsonObject radio = doc["radio"].to(); @@ -2250,34 +2294,20 @@ void WifiManager::handleStatus(AsyncWebServerRequest* request) { } } { - // Sized for every interface Transport can hold — the radio, the clients - // and the Auto peers. Sized for the clients alone, this listed the first - // five and quietly left the rest out. Off the stack because that is a - // kilobyte and a half on a task that has other things to do with it, and - // off the heap for the reason given at the peer list above: asked for on - // every poll, it is the size that a long-running node can no longer find - // in one piece, and failing to find it aborted the node. - static RnsTransport::IfaceInfo ifs[RNS_MAX_INTERFACES]; - static RnsTransport::PathInfo ps[32]; - // Interfaces, paths and the totals that describe them, out of one pass — - // otherwise this document can report a path_count from one refresh beside - // rows from another, which is a status page contradicting itself. - const RnsTransport::Snapshot snap = - RnsTransport::snapshot(ps, 32, ifs, RNS_MAX_INTERFACES); - const size_t k = snap.ifaceRows; + const size_t k = rnsSnap.ifaceRows; JsonArray ia = tr["interfaces"].to(); for (size_t i = 0; i < k; i++) { JsonObject o = ia.add(); o["name"] = ifs[i].name; o["mode"] = ifs[i].mode; o["rx_bytes"] = ifs[i].rxb; o["tx_bytes"] = ifs[i].txb; } - const size_t pk = snap.pathRows; - tr["path_count"] = snap.pathTotal; - tr["interface_count"] = snap.ifaceTotal; + const size_t pk = rnsSnap.pathRows; + tr["path_count"] = rnsSnap.pathTotal; + tr["interface_count"] = rnsSnap.ifaceTotal; // How old the reading is. A refresh that fails leaves the previous values // in place, and without this they are indistinguishable from current ones // — on exactly the node an operator is looking at to find out what is // wrong with it. - tr["snapshot_age_s"] = snap.ageMs / 1000; + tr["snapshot_age_s"] = rnsSnap.ageMs / 1000; JsonArray pa = tr["paths"].to(); for (size_t i = 0; i < pk; i++) { JsonObject o = pa.add(); diff --git a/src/rns/RnsTransport.cpp b/src/rns/RnsTransport.cpp index 79e9db3..7c03c02 100644 --- a/src/rns/RnsTransport.cpp +++ b/src/rns/RnsTransport.cpp @@ -37,6 +37,7 @@ #include "LxmfCommands.h" #include "Telemetry.h" #include "PathWait.h" +#include "SnapshotWalk.h" #include "NomadNet.h" #include "Diag.h" #include "Watchdog.h" @@ -226,9 +227,9 @@ class LoRaRnsInterface : public RNS::InterfaceImpl { // consecutive radio drains of the order of 410 ms apart rather than 10. // That figure is derived in RingDrain.h; what follows is a summary of that // derivation rather than a second one, and it goes stale with it: the short - // of it is that kWalkBudgetMs — 400 ms, declared further down this file — - // bounds only the part of the walk that runs after the snapshot's rows are - // full, so 410 ms is the least such a gap can be and not the most. + // of it is that Rns::kWalkBudgetMs — 400 ms, in SnapshotWalk.h — bounds the + // walk but is checked only between records, and the walk is one part of a + // pass, so 410 ms is the least such a gap can be and not the most. // // At the fastest channel the settings will accept — SF7, the floor on every // part in RadioCaps; 500 kHz sub-GHz or 1625 kHz on the SX1280; CR 4/5; the @@ -1904,7 +1905,9 @@ static void processEvents() { // See RingDrain.h. The feeds this takes are the first reporting after the RNS // task's own feed at the top of the pass (main.cpp): the radio drain feeds // again from inside reticulum.loop(), which runs next, and refreshSnapshots() -// three times after that. +// three times after that — either side of its path-table walk, and once more +// after the removal that follows it. That walk being bounded, and the removal +// now sharing its budget, is what makes three enough. static void drainTcp() { size_t sz = 0; const Sys::RingDrain::Pass pass = Sys::RingDrain::drain( @@ -1945,30 +1948,58 @@ static void drainTcp() { static uint32_t sSnapAtMs = 0; static uint32_t sSnapOkMs = 0; // last pass that actually published; the age readers see // Dead paths are cleaned up on a slower clock than the reading is refreshed: -// the reading is capped and cheap, the sweep walks the whole table. -static const uint32_t kStaleSweepMs = 60000; -// How long the sweep phase of one pass may spend reading path records back off -// the filesystem. +// the reading is capped and cheap, the sweep walks the whole table. The figure +// is Config.h's because test_snapshot_walk drives the scheduler this is the +// ceiling for, and a figure written out in both places is a figure that gets +// retuned in one. +static const uint32_t kStaleSweepMs = SNAPSHOT_SWEEP_INTERVAL_MS; +// How long one pass of the walk may spend reading path records back off the +// filesystem, and how often it gives the core up while it does. Both live in +// SnapshotWalk.h beside the per-position rule they parameterise, which is where +// their derivations are and where test/test_snapshot_walk asserts them: this +// file cannot be compiled for the host, so a rule that only exists here cannot +// be pinned by anything. What one pass does not get through, the next one does. // -// Not a tuning knob — a bound this walk did not have. Every record examined is -// one file opened, sought, read and closed, and on LittleFS that is a -// directory lookup plus several 512-byte reads, each of which disables the -// flash cache and stalls the other core while it runs. The sweep dereferenced -// the whole table in one pass, so its cost grew with the table, and on a node -// whose table had grown large enough the pass outlasted the 30-second -// watchdog. The node then rebooted every ninety seconds for two days without -// once saying why, because the watchdog's own report died on the way out (see -// Watchdog.h). Nothing here is allowed to be unbounded again. -// -// 400 ms is picked to be obviously survivable rather than optimal: two orders -// of magnitude inside the watchdog, and small next to the five seconds between -// passes. What it bounds is the sweep and not the whole walk — the check below -// is guarded on !wantRow, so the row phase ahead of it runs unbudgeted, and -// RingDrain.h works through what that leaves for the gap between two drains of -// a ring. What one pass does not get through, the next one does. -static const uint32_t kWalkBudgetMs = 400; +// The one part of that derivation the header cannot assert for itself, because +// SNAPSHOT_INTERVAL_MS is Config.h's: the budget has to leave the pass ending +// well inside the interval the pass is gated on. That is what returns this task +// to the 10 ms sleep in main.cpp hundreds of times per window, and it is what +// actually keeps loopTask running — a walk that outlasts the interval makes the +// gate below a no-op and the passes run back to back, which is the shape that +// took a T-Beam down. Raising kWalkBudgetMs past a quarter of the interval +// fails the build rather than the node. +static_assert(Rns::walkBudgetFitsInterval(SNAPSHOT_INTERVAL_MS), + "the walk's budget must stay well inside SNAPSHOT_INTERVAL_MS, or " + "snapshot passes run back to back and starve loopTask"); +// The ceiling on the gap the measured pass cost may buy itself, and the reason +// it is this figure: kStaleSweepMs is the slowest clock a pass carries, so +// passes have to come round at least that often or the minute between sweep +// cycles is not a minute (Rns::nextIntervalMs). A ceiling below the interval +// would be a misconfiguration, and the guard for it costs nothing here. +static_assert(kStaleSweepMs >= SNAPSHOT_INTERVAL_MS, + "the scheduler's ceiling cannot be shorter than the interval it " + "is a ceiling over"); static size_t sPathCount = 0; // full table size; sPaths is capped static uint32_t sSnapWalkMaxMs = 0; // worst snapshot walk since boot; see Tables +static uint32_t sSnapBudgetStops = 0; // passes the budget ended; see Tables +// What the last pass's cost bought: SNAPSHOT_INTERVAL_MS on any node whose +// passes cost less than a quarter of it, which is every node at every +// per-record figure this tree has measured, and more than that on one where a +// pass has come to cost more (Rns::nextIntervalMs, where the arithmetic is). +static uint32_t sSnapIntervalMs = SNAPSHOT_INTERVAL_MS; +// Whether the log has already said this node backed itself off, which is not +// the same question as whether it is backed off right now — see the transition +// test in refreshSnapshots(). Held separately so the published interval above +// stays the node's real answer while the log holds its tongue. +static bool sSnapBackOffSaid = false; +// How cheap a pass has to become before the log says the node is back on its +// configured interval: half the quarter nextIntervalMs() backs off at. This is +// the hysteresis, and it is the whole point of the pair — a cost oscillating +// either side of the quarter crosses the transition test on *every* pass, so +// without a margin the node reports backing off and recovering alternately, +// once every five seconds, while it is already struggling. +static const uint32_t kSnapBackOffClearMs = + SNAPSHOT_INTERVAL_MS / (Rns::kPassShareDiv * 2); static size_t sIfaceCount = 0; // likewise, so a capped list still counts true static Tables sTables = {}; // table sizes, for soak monitoring @@ -1976,18 +2007,53 @@ static void refreshSnapshots(bool allowSweep) { // Walking the path table reads every record back through microStore // (LittleFS or the SD card), so refresh it slowly and keep the list short — // the count is free, the rows are not. - if (millis() - sSnapAtMs < SNAPSHOT_INTERVAL_MS) return; + // Against the interval the last pass earned rather than the configured one. + // They are the same figure until a pass costs more than a quarter of it, at + // which point the gate is the only thing that can keep passes from running + // back to back — the budget bounds what this file chooses and not what a pass + // comes to (Rns::nextIntervalMs). + if (millis() - sSnapAtMs < sSnapIntervalMs) return; // Stamped on the way in, so a pass that throws does not come straight back // on the next 10 ms tick and spend the node's remaining memory logging about // it. What it must not do is imply the reading is current: sSnapOkMs, set // only after the publish below, is what /api/status reports the age from, so // a snapshot that stopped updating says so instead of looking fresh. sSnapAtMs = millis(); + // The other half of that, and it is the half the entry stamp cannot cover. + // sSnapIntervalMs is written at the end of this function, after the walk and + // the removal have both come back, so a pass that throws leaves the interval + // it was gated on standing — and a pass that had already run longer than that + // interval before it threw has the gate open again the moment it leaves. + // Repeated slow failures then run back to back, which is the shape the gate + // exists to prevent, on the sick filesystem that is the case it matters on. + // + // So the scheduler is asked however the pass leaves, off the same + // Rns::nextIntervalMs() the ordinary path uses rather than a second formula, + // and a pass that throws still costs the node a gap proportional to how long + // it ran before throwing. That gap runs from where the pass stopped rather + // than from where it started, which is what keeps a pass that outlasted its + // own interval — or the ceiling — from coming straight back. + // + // A destructor rather than a catch here: containment is Diag::guard's job and + // is one rule in one place (Diag.h), and this function is called from inside + // it (loop() below). The same reasoning as Sys::Lock at the publish. + struct PassBackOff { + bool done = false; + ~PassBackOff() { + if (done) return; // the pass reached its own scheduler + const uint32_t costMs = (uint32_t)(millis() - sSnapAtMs); // the entry stamp above + sSnapIntervalMs = Rns::nextIntervalMs(costMs, SNAPSHOT_INTERVAL_MS, kStaleSweepMs); + sSnapAtMs = millis(); + } + } backOff; // clear() keeps the capacity reserved at begin(), so the push_back()s below // write into memory this node already owns. + // + // The path staging list is *not* cleared here any more: it accumulates across + // passes now, and is emptied only when a cycle starts (below, once the row + // cursor has been checked against the table). std::vector& p = sPathsStaging; std::vector& i = sIfacesStaging; - p.clear(); i.clear(); double now = RNS::Utilities::OS::time(); // Paths live in the microStore-backed table (Transport::path_table() is the @@ -2020,8 +2086,58 @@ static void refreshSnapshots(bool allowSweep) { // that with an unbounded pass: reading a record back is a file opened on // LittleFS, so the pass cost whatever the table had grown to, and past a few // hundred entries it outlasted the watchdog and took the node down with it. - // A sweep now spends kWalkBudgetMs per pass and remembers where it stopped, - // which keeps both properties — every entry is reached, and no pass is long. + // A pass now spends Rns::kWalkBudgetMs and remembers where the sweep stopped, + // so no pass is long. + // + // Rows are collected across as many passes as it takes as well, and for the + // same reason. Bounding the row half left them being re-collected from the + // front on every pass: on a table slow enough that the budget runs out before + // the rows are full, the walk never got past that prefix, so the cursor never + // advanced, the cycle never closed and not one entry beyond the prefix was + // ever reached. Row collection now has a cursor of its own, resumed by the + // same two rules the sweep's is (Rns::resumeCursor, Rns::nextCursor), and a + // list reaches sPaths only when a cycle has been all the way round. + // + // And the two halves share the budget rather than the rows taking it and the + // sweep getting the remainder. Rows go back to the front of the table when + // their cycle closes and the sweep does not, so every pass afterwards spent + // its whole budget re-reading the front and stopped before it reached the + // sweep's cursor — which then moved only in the one pass per row cycle where + // the rows caught up to it, and on one arrangement of costs did not move at + // all. Rns::rowShareSpent() is the rule and carries the figures. + // + // What is deliberately not here: any cap on the table itself. Nothing bounds + // how many paths it holds — nothing on this node sets path_table_maxsize() + // (the sweep-cursor note below carries that argument in full, the library's + // own caller included), so microStore's policy_max_recs stays 0 and neither + // its eviction nor its dead-record compaction can run. + // + // Their age is bounded, though, and by the library rather than by this sweep. + // What is not set is a store-wide TTL *policy* — set_ttl_secs() has no caller + // in src/ — but every path carries a TTL of its own: Transport::inbound's + // announce handling passes AP_PATH_TIME (1 day), ROAMING_PATH_TIME (6 h) or + // DESTINATION_TIMEOUT (1 week) to _new_path_table.put() by the receiving + // interface's mode, and a record's own TTL is the one is_ttl_expired() uses + // (policy_ttl_secs is only the fallback for a record whose TTL is 0). So this + // sweep is not the only thing that removes a stored path: get() and exists() + // each drop an expired record from the index and report not-found + // (FileStore.h), and Transport::has_path() is exists(). + // + // What survives is that removal happens on *access*, never on a clock. + // Nothing scans for expired records — the store's own sweep() only clamps + // timestamps that lie in the future, and the iterator this walk uses reads a + // record without consulting its TTL at all. So an entry goes when something + // asks after that destination again, and a destination nobody asks after is + // exactly the one whose path has gone dead. The table is bounded by liveness + // rather than by size, then: paths still in use age out, paths whose + // interface went away are this sweep's job, and the never-asked-after + // remainder is what accumulates, at an estimated 70-90 B of internal DRAM + // apiece — a 16-byte key plus its vector header, a 16-byte IndexValue, the + // map node's link and cached hash, a bucket slot, and an allocator header on + // each of the two blocks — on every board, PSRAM ones included, because + // RNS_CONTAINER_ALLOCATOR is left at its ESP32 default of RNS_HEAP_ALLOCATOR, + // which is plain operator new. A smaller concern than "nothing ever removes a + // path", and still its own change rather than a cap smuggled in here. static std::vector stale; static uint32_t sSweptMs = 0; // Where the last sweep ran out of budget, and so where the next one starts. @@ -2029,13 +2145,97 @@ static void refreshSnapshots(bool allowSweep) { // // An offset rather than a saved iterator, because the table is mutated // between passes — by the removal at the end of this very function, among - // others — and no iterator survives that. The cost is that an entry inserted - // or dropped ahead of the cursor shifts everything after it by one, so that - // entry is examined twice or skipped once. For a cleanup sweep that is one - // more cycle, which is the right price for not holding an iterator across a - // deletion. + // others — and no iterator survives that. + // + // What an offset costs is that it is an *ordinal*, not an address: the number + // of ++it steps from begin(). The index behind NewPathTable is a + // std::unordered_map (microStore's FileStore.h) and the store's iterator + // walks it — operator++ is ++pos_ on the map's own iterator — so the position + // means the same place from one pass to the next only while nothing has + // shifted the count. Three things do: + // + // * An erase. It does not rehash and the survivors keep their buckets, but + // every element after the erased one loses an ordinal — an entry dropped + // ahead of the cursor shifts the whole tail behind it by one. This is the + // ordinary path, not an exotic one: the removal at the end of this + // function drops as many entries as what is left of the pass's budget + // allows — up to SNAPSHOT_MAX_PATHS on a pass whose walk finished early, + // and exactly one on a pass whose walk spent the whole of it. And a stale + // entry is collected on the Row step as well as the Examine step — that + // is, at the front of the table, behind a cursor that has already worked + // its way past it. + // * An insert that rehashes, which reorders the whole table rather than + // shifting a tail. + // * Segment-rotation compaction. A put() that fills the active segment + // calls rotate_segment_if_needed(), which on the last segment calls + // compact(); that ends in finalize_compaction(), which does _index.clear() + // and rebuilds the map by rescanning the compacted segment — a wholesale + // reorder (FileStore.h). Its sibling, the dead-record-threshold + // compaction, is *not* reachable on this store: compact_if_threshold() is + // gated on policy_max_recs > 0, that member defaults to + // USTORE_DEFAULT_MAX_RECS which is 0, and the only thing that would set + // it is Transport::path_table_maxsize(uint16_t), and nothing calls it. + // Not src/, and not the library in the image either — though the library + // is where its one caller lives: register_builtin_namespaces() exposes + // the setter as a provisioning field (Provisioning/BuiltinNamespaces.cpp) + // and that file is compiled. It is reached only from + // Provisioner::begin(), which Reticulum::start() calls under #ifdef + // RNS_USE_PROVISIONING — a macro no env in platformio.ini defines — so + // the call is compiled out, nothing references the registration and the + // linker drops it: the t3s3 firmware.elf carries no provisioning symbol + // at all, and no path_table_maxsize beyond the member it would write. + // Defining that macro is what would end the premise. + // + // So the cursor is an approximation between passes rather than an identity, + // and entries either side of a shift are examined twice or skipped for a + // cycle. For a cleanup sweep that is one more minute, which is the right + // price for not holding an iterator across a deletion. What it must not do is + // point outside the table altogether, which is resumeCursor() below. static size_t sSweepPos = 0; + // Row collection's own cursor, and it means the same thing under the same + // rules: where the next pass picks the list up, 0 for a fresh cycle. Every + // caveat above about an ordinal into a mutating table applies to it too — a + // shift under a part-built list drops or repeats a row for one cycle, which + // is a cosmetic wrong on a panel that corrects itself on the next one, and + // pathCount() beside it is the table's own size() and is never wrong. + static size_t sRowPos = 0; + // What the last cycle to publish a list covered, which is what decides + // whether that list is still a whole answer for the table (Rns::rowsWhole). + // + // A bool that latched true on the first closed cycle was wrong on every + // node's first boot: the empty table a node starts with closes a cycle on the + // first pass, and the empty list that published went on being called whole + // after the node had learned two hundred paths. The rule, what it deliberately + // does not call "still reading", and what a node pays for it are in + // SnapshotWalk.h beside the other row-cycle rules, where the host drives them. + static Rns::RowCycle sRowCycle; + // Whether the last pass got as far as writing the row cursor back. What that + // buys, and why a pass that did not gets its cycle started again rather than + // resumed, is Rns::resumeRowCursor() — the rule is there with the other two + // cursor rules, where the host can drive it. + static bool sRowPassClean = true; stale.clear(); + // A cursor the table has outgrown is not a cursor. `stale` is capped at + // SNAPSHOT_MAX_PATHS, so the removal at the end of a pass can take 64 entries + // out from under a cursor sitting beyond them — and nothing downstream would + // ever bring it back, because nextCursor() only moves forwards and no + // position at or past the stale value exists to end the pass anywhere else. + // The sweep would then be part-way through for ever: `sweeping` latched true, + // sSweptMs never stamped again, the cycle never closed (SnapshotWalk.h). + // Asked before `sweeping` is decided, so the pass that finds it stale is the + // one that starts the cycle afresh. + sSweepPos = Rns::resumeCursor(sSweepPos, pathTable.size()); + // And the row cursor by the same rule, against the same hazard: stranded + // beyond a shrunken table it would stop any cycle ever closing, so nothing + // would ever be published at all — plus the one condition that is the row + // cursor's alone, a previous pass that threw before writing it back + // (Rns::resumeRowCursor, where both are decided together). + sRowPos = Rns::resumeRowCursor(sRowPos, pathTable.size(), sRowPassClean); + // A fresh cycle starts an empty list; a resuming one keeps what earlier + // passes collected. This is the only clear(), which is why it is here and not + // at the top of the function with the interface list's. + if (sRowPos == 0) p.clear(); + sRowPassClean = false; // set again when the cursor is written back // A sweep begins on the minute clock, and once begun it continues on every // pass until it has been all the way round. Waiting a minute between slices // as well would put a full cycle on a large table hours away, which is not @@ -2044,40 +2244,113 @@ static void refreshSnapshots(bool allowSweep) { const bool sweeping = allowSweep && (sSweepPos != 0 || (uint32_t)(millis() - sSweptMs) >= kStaleSweepMs); const uint32_t walkStartMs = millis(); - size_t pos = 0; // position in the table, for the sweep cursor - size_t reads = 0; // records actually read back, for the feed clock - bool ranOut = false; // budget ended the walk before the table did + size_t pos = 0; // position in the table, and where the *sweep* stopped + size_t reads = 0; // records dereferenced this pass; see Rns::passMayStop + uint32_t lastYieldMs = 0; // walk time at the last yield, for the yield clock + bool ranOut = false; // budget ended the walk before the table did + // Row collection's own two, which used to be `pos` and `ranOut` as well. They + // are not the same figures any more: once the rows have spent their share of + // a sweeping pass the walk carries on to the sweep's cursor without them + // (Rns::rowShareSpent), so `pos` is where the *sweep* stopped and this is + // where the rows did. Writing `pos` into the row cursor there would skip + // every position between the two, which is the whole table's worth of rows on + // a node whose sweep is far ahead. + size_t rowStopPos = 0; // one past the last position the rows were served at + bool rowsCut = false; // the share ended the row half before the list did Watchdog::feed(); for (auto it = pathTable.begin(); it != pathTable.end(); ++it, ++pos) { // Incrementing reads the in-memory index and nothing else; only the // dereference below opens a file. So positions this pass has no use for // are stepped over for free, and the budget is spent entirely on records - // that are going to be looked at. - const bool wantRow = p.size() < SNAPSHOT_MAX_PATHS; - const bool wantSweep = sweeping && pos >= sSweepPos; - if (!wantRow && !sweeping) break; // rows are full and nothing else needs the rest - if (!wantRow && !wantSweep) continue; // ahead of the rows, behind the cursor - // The budget ends the sweep, never the rows. Rows are bounded already — - // there are at most SNAPSHOT_MAX_PATHS of them and the walk stops asking - // once they are full — so letting them finish costs a known amount. It - // also keeps the cursor honest: the only way to reach this line with the - // rows full is with wantSweep set, so pos is at or past sSweepPos and the - // cursor written below can only ever move forwards. - if (!wantRow && (uint32_t)(millis() - walkStartMs) >= kWalkBudgetMs) { ranOut = true; break; } - // kWalkBudgetMs ends the sweep, but it is only checked between records, and - // one record on a sick filesystem can take a long time on its own — so the - // walk keeps reporting while it runs rather than relying on finishing. The - // cadence is Sys::RingDrain::kFeedEvery rather than a 16 of this walk's - // own: one definition, so a retune cannot move the drains and leave this - // behind (RingDrain.h). - if (++reads % Sys::RingDrain::kFeedEvery == 0) Watchdog::feed(); + // that are going to be looked at. That is a promise of a dependency pinned + // to a branch rather than a commit, so it is not left as prose: + // test/test_snapshot_walk drives the rule below, and + // test/test_typed_store_iterator asserts the promise itself at both layers + // — TypedStore's and the file store's — against the microStore this build + // resolves. + Rns::WalkState w; + w.rowsCollected = p.size(); // this cycle's list, not this pass's share of it + w.rowCap = SNAPSHOT_MAX_PATHS; + w.rowPos = sRowPos; + w.sweeping = sweeping; + w.pos = pos; + w.sweepPos = sSweepPos; + w.elapsedMs = (uint32_t)(millis() - walkStartMs); + w.readAny = reads > 0; + // One budget, and it covers every position: the rows, the sweep and the + // free step-over alike (SnapshotWalk.h). Exempting the rows was the defect + // — the exemption was justified on their being bounded by count, which they + // are, and which is not the same as bounded by time. + const Rns::WalkStep step = Rns::walkStep(w); + if (step == Rns::WalkStep::StopRowsFull) break; // nothing else needs the rest + if (step == Rns::WalkStep::StopBudget) { ranOut = true; break; } + // Before the step-over below, because a position the share denied the rows + // comes back as a Skip when the sweep does not want it either — which is + // every position between the two cursors once the share is spent. + if (step == Rns::WalkStep::Row) rowStopPos = pos + 1; + else if (Rns::rowShareDenied(w)) rowsCut = true; + if (step == Rns::WalkStep::Skip) continue; // neither half wants this one + // No feed inside the loop, and that is a deliberate removal rather than an + // omission. This walk used to feed every Sys::RingDrain::kFeedEvery records + // on the drains' reasoning — a pass that cannot be stopped mid-item has to + // report while it runs — and here that reasoning is upside down. 16 records + // is 480 ms at the 30 ms a record this firmware links, and 1.5-2.6 s in the + // reopen-per-record regime; both are longer than the whole budget, so the + // sixteenth record is never reached and the feed never fired at either cost + // this tree has measured. The sicker the filesystem the fewer records fit + // in a pass, so the case it was justified by is the case it can do least + // for (the arithmetic is in SnapshotWalk.h). + // + // Nor is there anything for it to do. The loop is bounded to kWalkBudgetMs + // plus the record in hand — 400 ms plus the 162 ms that is the worst + // per-record cost anywhere in this tree — against a 30 s watchdog + // (WATCHDOG_TIMEOUT_S), and the feeds either side of the loop bracket it. + // The one thing that could still get near the timeout is a single record + // that takes for ever, and no between-record cadence covers that. + // + // What the walk does instead is yield, on a clock of its own, because + // feeding was never the problem. esp_task_wdt_reset() reports on behalf of + // the running task and there is no way to report for another, and the task + // being starved is Arduino's loopTask: priority 1 against this task's 3 on + // the same core, so it does not run at all while this one is runnable, and + // its watchdog is the one that fired. A yield is worth 0-3 ms of core 1 per + // pass and is a margin, not the rescue — the rescue is this walk ending + // inside its budget so the task reaches the sleep at the end of its loop. + // Both are derived in SnapshotWalk.h. + // + // Yielding here holds a live store iterator across the delay, which is safe + // because nothing another task calls can *mutate* this store. Transport is + // single-threaded and the RNS task owns every call into it (main.cpp), and + // no other translation unit in src/ names RNS:: at all. Nearly every entry + // point in this one that another task calls posts to a queue, sets an + // atomic, or copies an already-published value under sSnapLock. The + // exceptions are nomadAddress() and lxmf(), which do reach into RNS:: from + // loopTask (Maintenance.cpp), the AsyncTCP task (WifiManager.cpp) and the + // display task (UiHome.cpp, UiIdentity.cpp) — but only for + // Destination::hash(), which returns a Bytes cached on the destination + // object and touches no store at all. So nothing can put, remove or compact + // the store while this delay runs, which matters because microStore + // documents mutating a store during iteration as undefined (FileStore.h). + // That is a property held by convention and a grep rather than by the type + // system, so the checkable form of it is written down here: an interface + // that mutated a store from its own task would break this line first. + if (Rns::walkShouldYield(w.elapsedMs, lastYieldMs)) { + lastYieldMs = w.elapsedMs; + // A bare tick count, not pdMS_TO_TICKS(1): at any tick rate below 1 kHz + // that truncates to 0, and vTaskDelay(0) yields only to this priority and + // above — never to the priority-1 task this exists for (SnapshotWalk.h). + vTaskDelay(1); + } + reads++; // before, not after: the budget's + // forward-progress rule counts the + // record in hand (SnapshotWalk.h) RNS::Persistence::NewPathTable::Entry& e = *it; // reads the record off the filesystem if (!e.value.receiving_interface()) { if (sweeping && stale.size() < SNAPSHOT_MAX_PATHS) stale.push_back(e.key); continue; } - if (!wantRow) continue; // swept, not rendered + if (step != Rns::WalkStep::Row) continue; // swept, not rendered PathInfo pi = {}; strlcpy(pi.hash, e.key.toHex().c_str(), sizeof(pi.hash)); pi.hops = e.value._hops; @@ -2086,12 +2359,32 @@ static void refreshSnapshots(bool allowSweep) { p.push_back(pi); } Watchdog::feed(); + if (ranOut) sSnapBudgetStops++; + // Whether the list this cycle has been building is finished — the cap filled, + // or the table walked all the way to the end. Anything else is a prefix, and + // a prefix is kept in staging for the next pass rather than published + // (SnapshotWalk.h). The cursor follows the same two rules the sweep's does: + // forwards only within a cycle, back to the front when the cycle closes. + // + // Both figures are the row half's own: what cut the cycle short is the budget + // or the share, and where it stopped is where the rows stopped, not where the + // walk did. + const bool rowsShort = ranOut || rowsCut; + const bool rowsDone = Rns::rowCycleDone(p.size(), SNAPSHOT_MAX_PATHS, rowsShort); + // Read here rather than at the publish below, where p has been swapped away. + const size_t rowsCollected = p.size(); + sRowPos = rowsDone ? 0 : Rns::nextCursor(sRowPos, rowStopPos, rowsShort); + sRowPassClean = true; // list and cursor agree again if (sweeping) { // Reaching the end closes the cycle and puts the next one a minute out; // running out of budget leaves the cursor where it stopped, which is what // keeps the sweep coming back on the next pass rather than the next minute. const bool started = (sSweepPos == 0); - sSweepPos = ranOut ? pos : 0; + // Forwards only, and that is not decoration: the budget can now end the + // walk in the row half, which is at the front of the table and so behind + // the cursor. Writing pos in unconditionally would drag the sweep back + // there and leave the tail never examined (SnapshotWalk.h). + sSweepPos = Rns::nextCursor(sSweepPos, pos, ranOut); if (!ranOut) sSweptMs = millis(); // Once per cycle, not once per pass: a table that needs twenty passes // should say so, and then be quiet about it until the next minute. This is @@ -2101,18 +2394,107 @@ static void refreshSnapshots(bool allowSweep) { log_i("path table is %u entries; sweeping %u per pass at %u ms", (unsigned)pathTable.size(), (unsigned)pos, (unsigned)(millis() - walkStartMs)); } + if (!stale.empty()) { + // The removal is on the same clock and the same budget as the walk, and it + // was on neither. It is not free: every entry here is a + // BasicFileStore::remove() — a tombstone appended and flush_buffer()'d (a + // write and a flush of the segment file), then persist_index_entry(), a + // second write and an explicit flush of the index file (FileStore.h). All + // that bounded it was `stale` being capped at SNAPSHOT_MAX_PATHS, so up to + // 64 write-and-sync pairs ran with nothing watching the clock — which is + // "bounded by count is not bounded by time", the fallacy the walk's own + // budget exists to kill, one screen below the code that killed it. + // + // One at a time rather than Transport::remove_paths(), because a whole + // vector cannot be stopped part-way. + // + // What the budget leaves is not lost, but it is not free either, and the + // shape of that is worth being exact about because the obvious sentence — + // "the next sweeping pass finds it again" — is not true of the entries + // that matter. `stale` is cleared at the top of every pass, so an + // un-removed key is discarded and has to be *re-found* by a later walk; + // and both cursors have already been written past the positions the walk + // reached, so the next pass does not look there. An entry left behind is + // re-found when row collection comes round to the front of the table again + // — which is every row cycle, and so soon — if it lies within the stretch + // the rows reach. One beyond that stretch waits for the sweep cursor to + // come all the way round, which is a whole sweep cycle. + // + // Hence back to front. `stale` is in table order, so its tail is exactly + // the part the rows will not reach again this cycle, and its head is the + // part they will. Removing from the tail spends a short budget on the + // entries that would otherwise wait longest. It changes nothing else: every + // key here sits behind the cursor already, so each removal shifts the tail + // under it whichever order they go in (the ordinal paragraph above). + // + // On a pass whose walk spent the whole budget this removes one entry and + // stops — passMayStop()'s forward-progress rule is what makes it one rather + // than none. That is deliberate: the pass that is already at its limit is + // the last one that should be handed 64 flash syncs. A pass whose walk + // finished early hands the removal everything that is left, which on the + // tables this cleanup is for is the ordinary case. + const uint32_t removeStartMs = millis(); + size_t dropped = 0; + size_t attempts = 0; + for (size_t k = stale.size(); k-- > 0; ) { + // Attempts, not successes. passMayStop()'s second argument is "this pass + // has done something", and the walk answers it with reads attempted + // (SnapshotWalk.h). Answering it with removals that *succeeded* would + // mean a `stale` whose keys have all gone already — every remove_path() + // returning false — running all 64 iterations with the clock switched + // off. Harmless today, since BasicFileStore::remove() misses in the + // index and returns before it touches flash, but it is not what the rule + // says and the two must not drift. + if (Rns::passMayStop((uint32_t)(millis() - walkStartMs), attempts > 0)) break; + attempts++; + if (RNS::Transport::remove_path(stale[k])) dropped++; + } + log_i("dropped %u of %u stored path(s) whose interface is gone, in %u ms", + (unsigned)dropped, (unsigned)stale.size(), + (unsigned)(millis() - removeStartMs)); + Watchdog::feed(); + } // The high-water mark rather than the last reading, because the pass that // matters is the worst one and it is not the one an operator happens to be // looking at. The first pass after a boot is routinely several times the // cost of the ones after it — the filesystem has read nothing yet — so a // spot reading understates the exposure by exactly the amount that would // have mattered. + // + // Taken after the removal rather than before it, because the removal is now + // inside the same budget and is part of what the RNS task spends before it + // gets back to forwarding. Read before, this figure said 400 ms on a pass + // that had gone on to spend an unmeasured amount more. const uint32_t walkMs = millis() - walkStartMs; if (walkMs > sSnapWalkMaxMs) sSnapWalkMaxMs = walkMs; - if (!stale.empty()) { - uint16_t dropped = RNS::Transport::remove_paths(stale); - log_i("dropped %u stored path(s) whose interface is gone", (unsigned)dropped); + // And the next pass is scheduled against it. On every node this tree has + // measured this hands back SNAPSHOT_INTERVAL_MS unchanged; it is the pass + // that has come to cost more than a quarter of the window it runs in that + // this exists for, and the gate above is where it takes effect. + const uint32_t nextGapMs = + Rns::nextIntervalMs(walkMs, SNAPSHOT_INTERVAL_MS, kStaleSweepMs); + // Once when it starts and once when it stops, not once per pass — with a + // margin on the way back, because a bare "is it backed off now, was it last + // pass" transition is crossed on every pass by a cost that oscillates across + // the quarter, which is exactly the node this log is about: it would say + // both lines alternately, once every five seconds (kSnapBackOffClearMs). + // Backing off is reported the moment it happens; recovering is reported only + // once a pass has come in at half the quarter or less, which jitter around + // the threshold cannot reach. The reading itself is served as + // snap_interval_ms, which is what an operator watching a node go stale needs + // — the log is for the one who has a log. + const bool backedOff = nextGapMs > SNAPSHOT_INTERVAL_MS; + if (backedOff && !sSnapBackOffSaid) { + sSnapBackOffSaid = true; + log_w("snapshot pass cost %u ms of the %u ms between passes; backing off to " + "one every %u ms (%u paths)", (unsigned)walkMs, (unsigned)SNAPSHOT_INTERVAL_MS, + (unsigned)nextGapMs, (unsigned)pathTable.size()); + } else if (!backedOff && sSnapBackOffSaid && walkMs <= kSnapBackOffClearMs) { + sSnapBackOffSaid = false; + log_i("snapshot pass back to %u ms; one every %u ms again", + (unsigned)walkMs, (unsigned)nextGapMs); } + sSnapIntervalMs = nextGapMs; // Counted into locals and published below with the lists they describe. As // members they were written here, outside the lock every reader takes, and // sIfaceCount was zeroed and counted back up mid-scan — so a panel or a @@ -2141,6 +2523,17 @@ static void refreshSnapshots(bool allowSweep) { t.heldAnnounces = (uint32_t)RNS::Transport::held_announces().size(); t.rates = (uint32_t)RNS::Transport::announce_rate_table().size(); t.snapWalkMaxMs = sSnapWalkMaxMs; + // What the walk actually did this pass, which nothing reported before. A high + // water mark on its own cannot tell "finished the table in 380 ms" from "cut + // off at 400": the first is a healthy node, the second is a node that is only + // seeing part of its own table per pass, and on a solar node reachable over + // the TCP console there was no way to tell them apart at all. + t.snapWalkPos = (uint32_t)pos; + t.snapBudgetStops = sSnapBudgetStops; + // snapRowsWhole is not set here with the rest: it describes the list that is + // published below, and the two must not be able to disagree. It is written + // under the lock, beside the publish it is about. + t.snapIntervalMs = sSnapIntervalMs; // Sys::Lock, not a hand-written pair. Lock.h states the rule: this whole // function now runs under Diag::guard, so there is a way out of the scope @@ -2149,17 +2542,35 @@ static void refreshSnapshots(bool allowSweep) { // Nothing in here throws today; the point is that it no longer has to be // checked before anything is added. Sys::Lock held(sSnapLock); - sPaths.swap(p); sIfaces.swap(i); + // The rows are swapped in only when the cycle that built them finished. A + // budget-stopped pass has a valid prefix and nothing else, and a panel given + // four paths on a node holding eighty has no way to say which it is looking + // at — so what stays published is the last whole list, and t.snapRowsWhole + // says whether that list is still a whole answer for the table as it now + // stands (Rns::rowsWhole). The interface list, the counts and the table sizes + // are published every pass as before: they cost one pass each and are never + // partial. + // + // sPathCount is pathTable.size() and is untruncated whatever the rows did, so + // the figure beside the list is exact on every pass including this one. + if (rowsDone) { + sPaths.swap(p); + // Credited to the table it closed over, not to the run: this is what makes + // the flag go false again when the table grows past it (Rns::rowsWhole). + Rns::closeRowCycle(sRowCycle, rowsCollected, SNAPSHOT_MAX_PATHS, pathTotal); + } + t.snapRowsWhole = Rns::rowsWhole(sRowCycle, pathTotal); + sIfaces.swap(i); sPathCount = pathTotal; sIfaceCount = ifaceCount; sTables = t; + // Every pass that gets here published something — the interfaces, the counts + // and the tables at least — so this keeps meaning what it always did: the + // last pass that completed rather than the last one attempted. What it does + // not measure is the age of the path *rows*, which on a table that takes + // several passes to walk can be a cycle older than this; snapRowsWhole and + // snapWalkPos above are what describe that. sSnapOkMs = millis(); // only here: a pass that threw never reaches this -} - -size_t paths(PathInfo* out, size_t max) { - Sys::Lock held(sSnapLock); - size_t n = min(max, sPaths.size()); - for (size_t k = 0; k < n; k++) out[k] = sPaths[k]; - return n; + backOff.done = true; // and the back-off above is what a pass that did not costs } size_t interfaces(IfaceInfo* out, size_t max) { diff --git a/src/rns/RnsTransport.h b/src/rns/RnsTransport.h index dc3463d..c46e77b 100644 --- a/src/rns/RnsTransport.h +++ b/src/rns/RnsTransport.h @@ -73,7 +73,6 @@ void clientDisconnected(uint32_t id); // eye, and a truncated one makes two different peers read as the same. struct PathInfo { char hash[33]; char via[INTERFACE_NAME_MAX]; uint8_t hops; uint32_t ageS; }; struct IfaceInfo { char name[INTERFACE_NAME_MAX]; char mode[14]; uint32_t rxb, txb; }; -size_t paths(PathInfo* out, size_t max); size_t interfaces(IfaceInfo* out, size_t max); size_t pathCount(); size_t interfaceCount(); // whole list, even when a caller reads fewer @@ -91,14 +90,77 @@ struct Tables { uint32_t announces; // announce table awaiting retransmission uint32_t heldAnnounces; uint32_t rates; // per-destination announce rate table - // Longest the snapshot pass has taken to read path records back off the - // filesystem, since boot. Reported because it is the figure that decides - // whether this node is near the edge the V4 went over: the walk is bounded - // and feeds the watchdog now, but a record costs whatever the filesystem - // charges, and a table big enough or a filesystem slow enough still makes a - // pass long. A number here in the seconds means the RNS task is spending - // that long not forwarding. + // Longest one snapshot pass has taken, since boot: the path-table walk plus + // the removal that follows it, which share one budget. Reported because it is + // the figure that decides whether this node is near the edge the V4 went + // over: the pass is bounded and feeds the watchdog now, but a record costs + // whatever the filesystem charges, and a table big enough or a filesystem + // slow enough still makes a pass long. A number here in the seconds means the + // RNS task is spending that long not forwarding. uint32_t snapWalkMaxMs; + // The three below say what that high-water mark cannot: whether the node is + // getting through its own table. snapWalkMaxMs alone reads the same for a + // pass that finished the table in 380 ms and one that was cut off at 400. + // + // Where the last pass's walk stopped — an offset into the path table in + // iteration order. + // + // A pass ends in exactly one of three ways (SnapshotWalk.h: the end of the + // table, WalkStep::StopRowsFull, WalkStep::StopBudget) and this offset reads + // differently in each, so on its own it says nothing. This is the canonical + // statement of the three; docs/api.md follows it. + // + // * It reached the end of the table. The offset is at `paths` — positions + // run 0..size-1, so the size itself is one past the last — or past it on + // a pass that went on to remove dead entries, since `paths` is read + // after the removal and is the smaller table. + // * The row cap filled and no sweep wanted the rest of the table. The + // offset is one past the position that filled it, which on a table + // larger than SNAPSHOT_MAX_PATHS is below `paths` and is a healthy + // reading: snapRowsWhole is true, snapBudgetStops did not move, and the + // next pass starts again at the front rather than here, because a + // finished cycle returns the row cursor to 0. This is the ordinary end + // of a pass on any node holding more paths than the cap — a sweep runs + // on a minute's clock and a pass on five seconds, so most passes are not + // sweeping and stop this way. + // * The budget ended it. The offset is where it stopped, below `paths`, + // snapBudgetStops moved with it, and the next pass carries on from that + // offset. + // + // So "below `paths`" is the cap on a healthy node and the budget on a + // struggling one, and snapBudgetStops is what tells them apart. + uint32_t snapWalkPos; + // How many passes the budget has ended since boot. Zero on a node that walks + // its table comfortably; climbing by one every five seconds means every pass + // is being cut off, which is survivable (the cursors resume) but is the node + // saying its table has outgrown one pass. + uint32_t snapBudgetStops; + // Whether the published path rows are a whole cycle over the table as it now + // stands. A pass stopped by the budget keeps its prefix in staging rather + // than publishing it, so a published list is complete for the table the + // cycle that built it closed over — and this goes false again when the table + // has since grown past that, which beside a non-zero `paths` is a node + // part-way through reading its own table. False until the first cycle closes, + // and for ever on a node that can never close one. + // + // Not a latch: a list published over an empty table, which is every node's + // first pass, is not an answer for the two hundred paths it goes on to learn. + // The rule and what it costs are Rns::rowsWhole (SnapshotWalk.h). + bool snapRowsWhole; + // How long the node is currently leaving between two passes. + // + // SNAPSHOT_INTERVAL_MS — 5000 ms — on any node whose last pass cost less than + // a quarter of it, which is every node at every per-record cost this tree has + // measured. A larger figure is the node having measured its own pass and + // given itself room: a pass that costs more than a quarter of its window is + // scheduled four times its own cost out, up to a ceiling of the minute + // between sweep cycles (Rns::nextIntervalMs). + // + // Reported because it is the only field that explains the others going stale. + // Everything else here describes a pass; this says how often one happens, and + // on a node that has backed itself off, snapshot_age_s and the path rows are + // older than the five seconds a reader would otherwise assume. + uint32_t snapIntervalMs; }; Tables tables(); @@ -119,6 +181,26 @@ struct Snapshot { size_t pathRows; // rows actually written to the caller's arrays size_t ifaceRows; uint32_t ageMs; + + // Whether an empty path list means "nothing there" or "not read yet". + // + // Those are two different nodes and they render identically. The rows are + // published only once a pass has been all the way round the table, and only + // while they are still a whole answer for it (tables.snapRowsWhole), while + // pathTotal is the table's own size and is exact from the first pass — so a + // node whose table is bigger than one pass shows a count with no rows under + // it until the first cycle closes, or for ever if it can never close one, and + // a node whose table has outgrown its last closed cycle shows the older list + // until the next one closes. Every surface that draws that list has to tell + // the two apart, and the OLED's PEERS SEEN beside an empty list is exactly + // the contradiction an operator reads as a bug. + // + // Here rather than at each caller: the LVGL destinations page, the nav + // page's peer plot and the web portal all ask it, and when the rule sharpens + // it has to sharpen for all of them at once. It sharpened once already — + // snapRowsWhole is the table the last cycle covered rather than a latch + // (Rns::rowsWhole) — and that landed here, in one place, for all three. + bool stillReadingPaths() const { return !tables.snapRowsWhole && pathTotal > 0; } }; Snapshot snapshot(PathInfo* pathOut, size_t maxPaths, IfaceInfo* ifaceOut, size_t maxIfaces); diff --git a/src/rns/SnapshotWalk.h b/src/rns/SnapshotWalk.h new file mode 100644 index 0000000..becbe98 --- /dev/null +++ b/src/rns/SnapshotWalk.h @@ -0,0 +1,790 @@ +// SPDX-License-Identifier: GPL-3.0-or-later +// Copyright (C) 2026 Dobrev IT Ltd +// +// This file is part of RetiMesh Node. +// +// RetiMesh Node is free software: you can redistribute it and/or modify it +// under the terms of the GNU General Public License as published by the +// Free Software Foundation, either version 3 of the License, or (at your +// option) any later version. +// +// RetiMesh Node is distributed in the hope that it will be useful, but +// WITHOUT ANY WARRANTY; without even the implied warranty of +// MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the GNU General +// Public License for more details. +// +// You should have received a copy of the GNU General Public License along +// with RetiMesh Node. If not, see . + + +// ============================================================================ +// SnapshotWalk.h — one bounded position of the path-table walk +// +// refreshSnapshots() in RnsTransport.cpp walks the microStore-backed path +// table for two unrelated reasons at once: to collect the rows /api/status, +// the OLED and the LVGL pages render, and to find entries whose receiving +// interface has gone away so they can be dropped. What to do at any one +// position — read it for a row, read it for the sweep alone, step past it, or +// stop the pass — is decided here. +// +// It is a header of its own because RnsTransport.cpp cannot be compiled for +// the host: [env:native] has no framework, no microReticulum, no LittleFS and +// no FreeRTOS. This is the same seam RingDrain.h uses — a pure rule with no +// dependency of any kind, called by the firmware and asserted directly by +// test/test_snapshot_walk. +// +// Why the rule needed extracting at all +// ------------------------------------- +// The budget below used to be consulted only once the rows were full — the +// check was written `if (!wantRow && elapsed >= budget)`. "The budget ends the +// sweep, never the rows" was the stated rule, justified on the rows being +// bounded by count: there are at most SNAPSHOT_MAX_PATHS of them. +// +// Bounded by count is not bounded by time. A row costs whatever the +// filesystem charges for a record, and worse, `wantRow` is false only once a +// row has actually been *filled* — an entry whose interface has gone away is +// read off the filesystem and fills no row, so on a table of exactly the dead +// entries the sweep exists to remove, `wantRow` stayed true to the end of the +// table and no position was budgeted at all. Martin Dobrev measured the row +// half alone at 7.5 s on a T-Beam holding 87 paths, on a node that "rebooted +// every few minutes with the watchdog naming loopTask" (2026-09-06, on the +// abandoned branch fix/snapshot-walk-starves-loop). +// +// That walk runs on the RNS task: core 1, priority 3 (main.cpp). Arduino's +// loopTask is core 1, priority 1, and it is the task setup() subscribes to the +// watchdog. A priority-3 task that never blocks does not let a priority-1 task +// on the same core run at all, and Watchdog::feed() is esp_task_wdt_reset(), +// which the IDF header documents as resetting the watchdog "on behalf of the +// currently running task" and requires "each subscribed task" to call for +// itself — there is no call that feeds another task's subscription. So the +// feeds in the walk answered for the RNS task and did nothing for the task +// that was actually being starved — which is why the watchdog named loopTask +// and not "rns". +// +// Hence the two rules here: one budget that covers every position, and a +// cadence on which the walk gives the core up rather than merely reporting. +// ============================================================================ + +#pragma once + +#include +#include + +namespace Rns { + +// How long one pass of the walk may spend reading path records back off the +// filesystem. +// +// Not a tuning knob — a bound this walk did not have. Every record examined is +// one file opened, sought, read and closed, and on LittleFS that is a directory +// lookup plus several 512-byte reads, each of which disables the flash cache +// and stalls the other core while it runs. The sweep dereferenced the whole +// table in one pass, so its cost grew with the table, and on a node whose table +// had grown large enough the pass outlasted the 30-second watchdog. The node +// then rebooted every ninety seconds for two days without once saying why, +// because the watchdog's own report died on the way out (see Watchdog.h). +// Nothing here is allowed to be unbounded again. +// +// 400 ms is picked to be obviously survivable rather than optimal: 75x inside +// the 30 s watchdog (WATCHDOG_TIMEOUT_S), and well under a tenth of the five +// seconds between passes (SNAPSHOT_INTERVAL_MS). It is checked between records +// and never inside one, so a pass costs it plus however long the record in +// hand takes. +// +// It bounds the whole walk rather than only the part after the rows are full, +// and it bounds the removal that follows the walk as well — one budget on one +// clock over the whole pass (see passMayStop() below). The removal used to sit +// outside it on the grounds that what it removes is capped by count at +// SNAPSHOT_MAX_PATHS, which is the same "bounded by count is not bounded by +// time" the paragraph at the top of this file is about: each removal is a +// tombstone written and flushed to flash and an index entry written and flushed +// after it, so 64 of them is 128 write-and-sync pairs with nothing watching the +// clock. +// +// Bounding the rows cost the walk its ability to finish. Rows used to be +// collected from the front of the table on every pass, so on a table slow +// enough to spend the budget before the rows fill, every pass read the same +// short prefix and stopped in the same place: the published list was not late, +// it was permanently a prefix; the sweep cursor never got past that prefix; the +// cycle never closed; and a dead entry beyond it was never found at all. The +// regime is exactly rowCap x per-record cost > kWalkBudgetMs — with 64 rows, +// any store charging more than 6.25 ms a record, and lower still on a table +// with dead entries in it, which cost a read and fill no row. At the 30 ms a +// record measured on a 200-record store (platformio.ini), a pass reads +// fourteen. What that fourteen is not is a crossover: both per-record figures +// in this file were taken on a 200-record store, and nothing in this tree +// measures what a record costs on a table of ten, so the count a smaller table +// reads does not follow from either. +// +// Row collection now resumes across passes the way the sweep does, under the +// same two cursor rules (resumeCursor() and nextCursor() below), so a table in +// that regime is walked over several passes instead of the same prefix being +// re-read for ever — and rowCycleDone() below is what makes a list publishable +// only once it has been all the way round. +// +// What is bought for the bound: pathCount() is the whole table and is +// unaffected, no pass is long, and the node stays up. +// +// Other surfaces quote this figure as the gap between two drains of a ring. +// Which surfaces, and what else moves when it is retuned, is the registry in +// RingDrain.h — one copy, kept there because that is where the drain's own +// frames-per-gap arithmetic is derived. It was written out a second time here +// and the two disagreed on their first day about where that arithmetic lives, +// which is what a duplicated list of this kind always comes to. Retuning this +// figure means going through that registry. +// +// What those surfaces say about it is that it is a floor under the gap rather +// than a ceiling over it, and that stayed true when the removal was unbounded +// on top of it; now that the removal shares this budget it is closer to being +// the real figure, over by one record and one removal. +constexpr uint32_t kWalkBudgetMs = 400; + +// How much walk time may pass between two yields. +// +// Elapsed time and not a record count, and this is the whole of why. A record +// costs 30 ms in the regime this firmware links — platformio.ini records a +// 200-record walk at "about 6 s" once microStore held its segment file open +// across the iteration, and 6000/200 = 30 — and it cost 93-162 ms in the +// reopen-per-record regime before that, which is microStore's own measurement +// on the same store (FileStore.h). That is a factor of five between two shapes +// of the same library, before a worn or busy filesystem is considered, so any +// count of records is a cadence that means something different on every node. +// Elapsed time means the same thing on all of them. +// +// It also rules out the obvious shortcut of reusing Sys::RingDrain::kFeedEvery, +// which is 16, as the yield cadence: 16 x 30 ms = 480 ms is longer than the +// whole 400 ms budget, so a yield on that cadence fires *zero* times in a pass +// — at 30 ms a record the budget ends the walk before the sixteenth record is +// reached. That is not a cadence, it is a yield that never happens, and it is +// driven rather than argued in test/test_snapshot_walk. The same arithmetic is +// why the walk no longer *feeds* on that cadence either (RingDrain.h): a +// bounded pass needs no feed inside it, and this one could not have had one. +// +// 100 ms, which is three yields to a full budget: each lands at the first +// record at or past 100 ms *since the previous yield*, and a fourth would need +// the whole 400 ms, by which point the budget has already ended the pass. Since +// the previous yield and not since the start of the walk, because a yield costs +// a tick that is itself charged to the budget: at 30 ms a record the three land +// at 120, 241 and 362 ms of walk time rather than at 100, 200 and 300. Those +// three figures are driven in test_snapshot_walk rather than divided out here, +// which is how the divided-out version of this sentence was found to be wrong. +// +// So the core is given up several times per pass at every per-record cost this +// repository has measured — three yields at 30 ms a record, two at 162 — while +// a walk short enough to finish inside 100 ms never reaches one at all. It is +// bounded at the other end by the same arithmetic: three yields is the ceiling +// however cheap a record becomes, which is the property no count of records +// has. +// +// A yield is vTaskDelay(1), deliberately a bare tick count and not +// pdMS_TO_TICKS(1). CONFIG_FREERTOS_HZ is 1000 in the esp32 and esp32s3 +// sdkconfigs of framework-arduinoespressif32-libs, so today the two would +// compile to the same thing; at any lower tick rate pdMS_TO_TICKS(1) truncates +// to zero, and vTaskDelay(0) does not block at all — it yields to tasks of this +// task's priority and above, which is every task except the one the yield +// exists for. A bare 1 is one tick whatever a tick is worth. +// +// What one yield is worth, exactly: vTaskDelay(1) blocks until the *next tick +// interrupt*, so it hands the core down for anywhere between nearly nothing and +// 1 ms depending where in the tick period the call lands, and the priority-3 +// RNS task preempts loopTask again the moment that tick readies it. Three of +// them are therefore 0-3 ms of core 1 per pass, with a floor of nearly nothing. +// +// And a yield hands the core to the highest-priority *ready* task, which need +// not be the one it was meant for: the radio task is priority 5 on core 1 +// (main.cpp), above this one and far above loopTask, so a yield that lands +// while a frame is being drained is worth loopTask nothing at all. Which is +// another way of saying the same thing — the yields are a margin, not a +// guarantee, and nothing below should be read as one. +// +// So the yields are a margin inside the walk. They are not what stops loopTask +// starving — the budget is, and by a different mechanism entirely. +// refreshSnapshots() returns immediately unless SNAPSHOT_INTERVAL_MS (5000 ms) +// has passed since the *start* of the last pass, and the RNS task's own loop +// ends in vTaskDelay(pdMS_TO_TICKS(10)) (main.cpp). With the walk bounded, a +// pass is a fraction of that window and the task spends the rest of it going +// round its loop and sleeping those 10 ms, hundreds of times per window — and +// every one of those sleeps is core 1 for the tasks below it, loopTask among +// them. The walk that took the node down did not leave any: 7.5 s on the T-Beam +// is longer than the interval, so the gate was already open when the pass +// returned and the next walk began at once. Passes ran back to back, and +// loopTask got the one 10 ms sleep per 7.5 s of walking that separated them, +// against a watchdog of 30 s (WATCHDOG_TIMEOUT_S). +// +// Which on its own does not yet predict a reboot: a task that gets 10 ms every +// 7.5 s and fed at the top of its body would feed every 7.5 s, comfortably +// inside 30 s. The step that closes it is that a preempted task resumes +// *mid-body*, not at the top — Watchdog::feed() is the first statement of +// loop() (main.cpp), so loopTask has to accumulate a whole loop() body of CPU +// out of those 10 ms slices before it reaches the feed again, and each slice is +// 7.5 s from the next. That body is not small: Rns::Inbox::poll() writes a +// queued message to flash, Imu, Compass and Environment each poll a part on +// I2C, and ConsoleServer::poll() and Maintenance::poll() run before them. A +// body wanting more CPU than three or four slices carry is therefore 30 s or +// more between one feed and the next, and that is the reboot. +// +// Milliseconds per pass is what the yields add to that; seconds per +// five-second window is what the budget returns, and the second number is the +// rescue. +// +// Which is why kWalkBudgetMs must stay well inside SNAPSHOT_INTERVAL_MS. The +// hazard itself is budget + worst record reaching the interval: at that point +// the gate is open again the moment the pass returns, the back-to-back passes +// are back, and no yield cadence rescues that. Someone buying rows back with a +// 6 s budget would get 49 yields to a pass rather than three, and they would +// still be worth at most a millisecond each — under 50 ms of core 1 for every +// 6 s of walking, against a walk that once again never stops. (Forty-nine and +// not sixty: a yield costs a tick that is itself charged to the budget, so at +// 30 ms a record the yields land about 121 ms apart rather than 100. The figure +// is driven in test_snapshot_walk rather than divided out here, which is how it +// was found to be wrong.) +// +// The quarter walkBudgetFitsInterval() enforces is not that cliff edge; it is a +// deliberate 4x margin short of it, so the guard fires on a retune that is +// merely unwise rather than only on one that is already fatal. A 3 s budget +// fails it and should: 3 s of walking to 2 s of loop is a node spending most of +// its time in this function. But 3 s does not reproduce the failure — the pass +// ends 2 s before the gate reopens, and the RNS task still reaches the 10 ms +// sleep at the end of its loop about two hundred times in that remainder. +// +// So the relation is asserted rather than asked for (walkBudgetFitsInterval() +// below), and it is worth asserting because nothing else would catch a repeat: +// core 1's idle task is not watched (CONFIG_ESP_TASK_WDT_CHECK_IDLE_TASK_CPU1 +// is unset in both sdkconfigs, while CPU0's is set), so loopTask's own +// subscription in setup() is the only thing that would notice. +constexpr uint32_t kWalkYieldMs = 100; + +// The relation the choice above rests on. A cadence that does not fit strictly +// more than twice in a budget gives the core up at most once a pass: the second +// yield needs 2 x the interval to have elapsed, and elapsing the whole budget +// is a stop rather than a yield. +static_assert(kWalkYieldMs > 0 && kWalkYieldMs * 2 < kWalkBudgetMs, + "the yield cadence must fire more than once inside one budget"); + +// The share of the gap between two pass starts that the pass itself may take. +// +// One rule, asked two ways. walkBudgetFitsInterval() below applies it to the +// figure this file *chooses* — the budget — and nextIntervalMs() applies it to +// the figure only the node can *measure*, what a pass actually cost. They are +// the same statement about the same thing: a task that spends more than a +// quarter of its window in this function is a task that has stopped forwarding +// for the other three quarters, and at the limit stops leaving any window at +// all. +constexpr uint32_t kPassShareDiv = 4; + +// The relation the paragraph above rests on, for the caller to assert: a walk +// has to end well inside the interval its pass is gated on, or passes run back +// to back and the RNS task never reaches the sleep that is what lets loopTask +// run at all. A quarter is where the line is drawn — at 400 ms against 5000 ms +// the margin is 12.5x, and even at the limit a pass ends a quarter of the way +// into a window, plus the record and the removal in hand. +// +// A function rather than a static_assert here because SNAPSHOT_INTERVAL_MS is +// Config.h's and this header depends on nothing (see the top of the file). +// RnsTransport.cpp static_asserts it against the real figure beside the call, +// and test_snapshot_walk asserts the same thing on the host. +// +// Divided rather than multiplied. The two are the same relation for every pair +// of integers that does not overflow, and only one of them stays that way: an +// absurd budget makes kWalkBudgetMs * 4 wrap and the guard answer "fits". +constexpr bool walkBudgetFitsInterval(uint32_t intervalMs) { + return kWalkBudgetMs <= intervalMs / kPassShareDiv; +} + +// How long to wait before the next pass, given what this one cost. +// +// What this is for, since the guard above looks like it covers it +// ------------------------------------------------------------- +// walkBudgetFitsInterval() bounds the part of a pass this file chooses: the +// budget, static_asserted at the call site in every environment, so no build +// ships a budget that could fill its own window. What it cannot bound is what +// a pass *costs*, and the two are not the same number: +// +// * The budget is consulted between records and never inside one, so a pass +// costs the budget plus the record in hand. At the worst per-record figure +// anywhere in this tree — 162 ms, microStore's own measurement on a +// 200-record store (FileStore.h) — that is 562 ms against the quarter, and +// this function hands back the configured interval unchanged for it. What +// the record in hand actually has is not a constant worth quoting but an +// expression — SNAPSHOT_INTERVAL_MS / kPassShareDiv - kWalkBudgetMs, the +// share a pass is allowed less the share the budget has already spent. On +// the shipped figures that is 5000 / 4 - 400 = 850 ms against a 162 ms +// record, which is comfortable for exactly as long as all three of those +// numbers stay where they are. "What reaches the branch" below is the list +// of ways they do not. +// * passMayStop() may not end a pass that has dereferenced nothing. That is +// the forward-progress guarantee, and its price is stated where it is +// defined: a pass costs the prefix it steps over plus one record, not the +// budget, if stepping ever stops being free. Stepping is free today and +// test_typed_store_iterator pins it against the microStore this build +// resolves — but it is a promise of a dependency pinned to a branch, and +// the abandoned branch fix/snapshot-walk-starves-loop ran on a microStore +// where stepping *did* load. A 50-position prefix at 30 ms a record is +// 1530 ms; the 87-path T-Beam at 162 ms is seconds. +// +// What reaches the branch +// ----------------------- +// Three routes, each read off this tree rather than supposed: +// +// * A retune this file permits. walkBudgetFitsInterval() asks only +// kWalkBudgetMs <= intervalMs / kPassShareDiv, so a budget of 1250 +// static_asserts clean at the shipped interval — and takes the expression +// above to zero. The no-op branch here is passCostMs <= intervalMs / +// kPassShareDiv, the same 1250, and a budget-stopped pass costs the budget +// *plus* the record in hand, so it is always over it: every budget-stopped +// pass would reschedule. This function fires on precisely the retune the +// static_assert lets through, which is why the node wants both. +// * One slow record, or one slow removal. The budget is read between records +// and never inside one, and the removal attempts one entry past it whatever +// the clock says — passMayStop()'s didSomething, and the attempts > 0 it is +// answered with at the removal in RnsTransport.cpp. Nor is the store +// necessarily on LittleFS: RnsFileSystem::useSd() points it at the SD card +// on a board that has one, and a card stalling in its own housekeeping goes +// well past the slack a 162 ms record leaves. +// * Time the task did not get. walkMs is millis() - walkStartMs, wall clock, +// so whatever preempts a pass is charged to the pass. The radio task is +// priority 5 on core 1 and the RNS task is priority 3 on the same core +// (main.cpp), so a burst of traffic during a pass counts against the +// measurement. That is the behaviour to want — the gap to the next pass +// should reflect how long the node was really away from forwarding — but it +// does mean this branch is reachable on a node whose own work sits well +// inside the budget. +// +// So the missing half is the measured one, and this is it. Nothing else in the +// pass watches what the pass came to, and the gate it feeds — "has +// SNAPSHOT_INTERVAL_MS passed since the *start* of the last pass" — becomes a +// no-op the moment a pass outlasts the interval: the gate is already open when +// the pass returns, the next one begins at once, and that is exactly the shape +// that took a T-Beam down at 7.5 s a walk. +// +// The rule +// -------- +// A pass gets at most a quarter of the gap between two pass starts, the same +// quarter the budget is held to. Under that it changes nothing, which is the +// ordinary node; over it, the next pass is put kPassShareDiv times the +// measured cost out. Measured on the *last* pass rather than the worst since +// boot, so a node that recovers returns to its configured interval instead of +// carrying its worst moment for ever. +// +// The ceiling +// ----------- +// `ceilingMs` is not decoration and the version of this idea on the abandoned +// branch did not have one: `max(walkMs * 4, SNAPSHOT_INTERVAL_MS)` would put a +// node whose passes cost a minute onto a four-minute interval, and a node that +// slow needs its cleanup more often than that, not less. The caller passes the +// slowest clock inside a pass — kStaleSweepMs, the minute between one dead-path +// sweep cycle and the next — because a pass carrying a minute's clock has to +// come round at least once a minute or that clock is not honoured at all. +// +// The trade the ceiling makes is worth stating: up to it, the gap is at least +// four times the pass; at it, a pass costing a quarter of the ceiling or more +// gets less than that, and one costing the whole ceiling is back to back +// again. That is not a bound this function can win — a node spending a minute +// per pass is broken in a way scheduling cannot fix — and the ceiling is where +// it stops making the node's cleanup worse in exchange for a margin it has +// already lost. +// +// Written as three comparisons rather than one min/max chain so that the +// multiply is only ever reached below the ceiling's own quarter, where it +// cannot overflow: the same reason walkBudgetFitsInterval() divides rather +// than multiplies. +constexpr uint32_t nextIntervalMs(uint32_t passCostMs, uint32_t intervalMs, + uint32_t ceilingMs) { + return ceilingMs < intervalMs ? intervalMs + : passCostMs <= intervalMs / kPassShareDiv ? intervalMs + : passCostMs >= ceilingMs / kPassShareDiv ? ceilingMs + : passCostMs * kPassShareDiv; +} + +// Whether a pass that has spent its budget may stop here. +// +// One rule for both halves of a pass — the walk between two records, and the +// removal between two entries — so there is one clock, one budget and one +// definition of "out of time" over the whole of refreshSnapshots(). +// +// `didSomething` is the forward-progress guarantee, and it is the whole reason +// this is a function rather than `elapsed >= budget` written twice. A pass has +// a prefix it does not want: positions already collected, positions the sweep +// has been through. Stepping over that prefix costs nothing today — microStore +// loads a record on dereference and not on ++, which test_typed_store_iterator +// pins at both the TypedStore and the file-store layer — so a pass always +// reaches its own cursor. If that ever stopped being true, a budget that could +// stop the walk inside the prefix would stop it *before* its cursor, on every +// pass, for ever: the cursor would never advance and the node would publish the +// same nothing until it was rebooted. That is not hypothetical. It is what the +// abandoned branch fix/snapshot-walk-starves-loop did on a bench node in +// September 2026 — "a pass pinned at position 15 of 87 for ever, publishing an +// empty list" — back when stepping did load. +// +// So the budget may not end a pass until the pass has dereferenced something. +// Worst case is then the prefix plus one record rather than the budget, which +// is the price of the guarantee, and it is only ever paid if the dependency +// regresses. Every pass moves at least one position of real work forward +// whatever a step comes to cost. +inline bool passMayStop(uint32_t elapsedMs, bool didSomething, + uint32_t budgetMs = kWalkBudgetMs) { + return didSomething && elapsedMs >= budgetMs; +} + +// What the walk should do with the position it is standing on. +enum class WalkStep : uint8_t { + Row, // read it: it fills a row, and is swept as well if a sweep is running + Examine, // read it for the sweep alone; the rows are full, so it is not rendered + Skip, // step past without touching the filesystem + StopBudget, // out of time — the pass ends here; nextCursor() says where each + // cursor picks up, which is not always here + StopRowsFull, // the rows are full and no sweep wants the rest of the table +}; + +// Everything the decision is made from. Positions are offsets into the table in +// iteration order; times are milliseconds since the walk started, so neither +// can wrap inside one pass. +struct WalkState { + size_t rowsCollected = 0; // rows in the staging list, this cycle, not this pass + size_t rowCap = 0; // SNAPSHOT_MAX_PATHS + size_t rowPos = 0; // where row collection resumes; 0 = a fresh cycle + bool sweeping = false; + size_t pos = 0; // where the walk is + size_t sweepPos = 0; // where the sweep is resuming from; 0 = a fresh cycle + uint32_t elapsedMs = 0; + uint32_t budgetMs = kWalkBudgetMs; + bool readAny = false; // a record has been dereferenced this pass +}; + +// How much of a pass's budget the rows may spend before the sweep gets the +// rest. +// +// Half each, and half is chosen because nothing measured says otherwise: the +// two halves of the walk are two unrelated jobs sharing one clock, and there is +// no figure in this tree that makes one worth more than the other. Expressed as +// a fraction of the budget rather than a constant of its own so that retuning +// kWalkBudgetMs moves it. +constexpr uint32_t rowShareMs(uint32_t budgetMs) { return budgetMs / 2; } + +// Whether the rows have spent their share and the rest of this pass belongs to +// the sweep. +// +// Why the sweep needs a share at all +// ---------------------------------- +// The walk serves positions in one order — the table's — so whichever cursor +// is in front is served first, and the budget is spent by the time the walk +// reaches the other. That is fine while the two cursors travel together, which +// they do for as long as both are ratcheting forward at the same stop position. +// It stops being fine the moment the row cycle closes: rows go back to the +// front of the table (a finished cycle returns their cursor to 0) and the sweep +// does not, so every pass afterwards spends its whole budget re-reading the +// front for rows and stops before it reaches the sweep's cursor, which then +// advances only in the one pass per row cycle where the rows catch up to it. +// +// On the synthetic 200-entry table at 30 ms a record — half of it dead entries, +// which is what the sweep is for — the cursor sat at 70 for five passes, then +// 76 for five, then 82: the first dead entry was reached on pass 35 and the +// cycle closed on pass 115, which is nine and a half minutes at five seconds a +// pass. With a share it is pass 10 and pass 23. And there is a knife edge +// inside the old behaviour: where reads per pass divide SNAPSHOT_MAX_PATHS +// exactly — sixteen of them, at 25 ms a record — the row half fills the cap +// precisely as the budget runs out, and the cursor stopped at 64 and stayed +// there until the per-record cost happened to jitter. A cleanup that never runs +// is not a slow cleanup. +// +// Only the figures *with* the share — pass 10, pass 23, and a knife-edge cursor +// that goes past 64 — are asserted, in test_snapshot_walk. The ones without it +// are not, and cannot be from this tree: the rules they were measured under are +// the ones the share replaced. They are recorded as what they are, measurements +// of the old behaviour reproduced once in review, and as why the share exists — +// not as anything this code can be checked against. +// +// The condition +// ------------- +// Only when the sweep's cursor is *ahead* of the row cursor, because that is +// the only arrangement in which serving the rows first can leave the sweep +// nothing. With the sweep behind or level, the walk reaches its cursor first or +// at the same position and it is served by the same reads — taking half the +// budget off the rows there would slow both halves and fix nothing. +// +// What it guarantees, exactly: the sweep cursor advances on every sweeping +// pass, because once the share is spent every position below the sweep's cursor +// is stepped over for free and the budget is only half gone. The exception is a +// single record expensive enough to carry the pass from inside the share to +// past the budget, which no share can legislate against — the same "checked +// between records, never inside one" the budget itself is subject to. +// +// Where that boundary is depends on whether records cost the same, and the +// difference is a factor of two. A record is served for the rows only while the +// clock is still *under* the share, so the row half can hand over as late as +// rowShareMs + c, and the sweep's record is then read only if that is still +// under the budget: +// +// * Uniform cost: the first record of the pass already spends the whole +// share, so the walk hands over at c and reaches the sweep for any +// c < kWalkBudgetMs. The exception is c >= 400 ms — a record costing the +// whole budget by itself, as the paragraph above says. +// * Mixed costs: cheap records creep the clock to one millisecond short of +// the share, and one record over rowShareMs then lands the pass at or past +// the budget. The exception starts at c > 200 ms, half the figure the +// uniform reading gives. +// +// Mixed is the real case — a filesystem charges what it charges, and one store +// was measured at 93-162 ms for a record (FileStore.h) — so 200 ms is the +// margin to hold this against, and the worst per-record cost measured anywhere +// in this tree is 81 % of it rather than 40 %. Both boundaries are driven in +// test_snapshot_walk rather than reasoned about here. +inline bool rowShareSpent(const WalkState& w) { + return w.sweeping && w.sweepPos > w.rowPos && + w.elapsedMs >= rowShareMs(w.budgetMs); +} + +// Whether this position is one the row half wanted and the share denied it. +// +// The caller needs this and cannot infer it from the step: a denied position +// comes back as Skip or Examine, which are also what a position before the row +// cursor comes back as. It matters because a cycle the share cut short is a +// prefix in exactly the way a budget-stopped one is — the rows did not reach +// those positions, so the list is not whole and must not be published, and the +// row cursor must be left where the rows actually stopped rather than where the +// walk did. rowCycleDone() and nextCursor() below take both as `cutShort`. +inline bool rowShareDenied(const WalkState& w) { + return w.rowsCollected < w.rowCap && w.pos >= w.rowPos && rowShareSpent(w); +} + +// One position. +// +// Order matters and each step is here for a reason: +// +// 1. "Nothing left to do" is answered before the clock, so a pass that +// finished what it came for is never recorded as having run out of time. +// The difference is not cosmetic: only a budget stop writes the cursors. +// +// It is decided on the rows being *full*, not on this position wanting no +// row, and that distinction is the second thing the abandoned branch got +// wrong. With a resuming row cursor, `!wantRow` is true at position 0 on +// every pass that is continuing a part-built list — it wants no row *here*, +// which is not the same as wanting no more rows at all. Stopping on it ends +// a resuming pass before it reaches its own cursor, and the short list is +// then treated as a finished one. That branch published 19 rows on a node +// holding 87. +// 2. The budget is next, and so covers every position that follows — +// including the skip below. It used to sit after the skip, where a pass +// stepping over a long prefix could not be stopped at all, and after the +// row decision, where it did not apply to the expensive half of the walk. +// It cannot stop a pass that has read nothing yet (passMayStop() above). +// 3. Only then the cheap step-over: past a position neither half wants — +// already collected, already swept, or wanted by the rows after they have +// spent their share of this pass (rowShareSpent() above). That last one is +// what makes the step-over reach the sweep's cursor rather than the budget. +inline WalkStep walkStep(const WalkState& w) { + const bool rowsFull = w.rowsCollected >= w.rowCap; + const bool wantRow = !rowsFull && w.pos >= w.rowPos && !rowShareSpent(w); + const bool wantSweep = w.sweeping && w.pos >= w.sweepPos; + if (rowsFull && !w.sweeping) return WalkStep::StopRowsFull; + if (passMayStop(w.elapsedMs, w.readAny, w.budgetMs)) return WalkStep::StopBudget; + if (!wantRow && !wantSweep) return WalkStep::Skip; + return wantRow ? WalkStep::Row : WalkStep::Examine; +} + +// Whether the row list this pass has been building is a whole one. +// +// Two ways round, and only these two: the cap filled, or the walk reached the +// end of the table without anything cutting the row half short. Anything else +// is a valid prefix and nothing more, and a prefix must not be published — a +// panel showing four paths on a node holding eighty is worse than a panel +// showing the last whole list, because nothing on it says which it is. The +// count beside the list comes from the table's own size() and stays exact +// either way. +// +// `cutShort` is the budget ending the pass *or* the share ending the row half +// (rowShareDenied() above), and the two have to be one argument because they +// have the same consequence: positions the rows wanted and did not reach. The +// caller passes `ranOut || rowsCut`. +inline bool rowCycleDone(size_t rowsCollected, size_t rowCap, bool cutShort) { + return rowsCollected >= rowCap || !cutShort; +} + +// What the last closed row cycle covered, and whether one has closed at all. +// +// Carried across passes by the caller and written only where a list is +// published, which is the pass rowCycleDone() above says yes on. +struct RowCycle { + bool closed = false; // a list has been published at least once + bool filledCap = false; // the last one ended at the row cap... + size_t tableSize = 0; // ...and this is how big the table was when it closed +}; + +// Record a cycle closing: the list about to be published, and the table it +// closed over. +// +// The table as it stands at the pass that closes the cycle, not as it stood +// when the cycle started. A cycle can span many passes and the table is mutated +// between them, so there is no one size the cycle "walked"; this is the figure +// the published list is going to be read beside, which is the one the question +// below is asked about. +inline void closeRowCycle(RowCycle& c, size_t rowsCollected, size_t rowCap, + size_t tableSize) { + c.closed = true; + c.filledCap = rowsCollected >= rowCap; + c.tableSize = tableSize; +} + +// Whether the published rows are a whole cycle over the table *as it now +// stands* — which is the question Snapshot::stillReadingPaths() asks of them, +// and the one a plain "has a cycle ever closed" latch answers wrongly. +// +// What the latch got wrong is every node's first boot, not a corner. A node +// that has heard nothing has an empty path table, the first pass walks it to +// the end and closes a cycle over it, and the latch was true from then on. Let +// that node learn two hundred paths and start a cycle it needs several passes +// for, and it went on calling the *empty* list it published at boot whole: +// stillReadingPaths() read false beside a count in the hundreds, and every +// surface drawing that list said "nothing announced yet" about a node that was +// part-way through reading its own table. +// +// The rule +// -------- +// A closed cycle is credited to the table it closed over, and answers for that +// table only: +// +// * it stays whole while the table has not grown past what it covered — a +// table that has shrunk, or churned without growing, is still described by +// that list; +// * a cycle that closed at the row cap stays whole whatever the table grows +// to, because the cap and not the cycle is what ended the list: the cap is +// the most any cycle can ever publish, so a bigger table cannot make that +// list less complete than it was; +// * and a table that has grown past a cycle that closed *below* the cap reads +// "still reading" until the next cycle closes. +// +// The trade +// --------- +// The third clause is what a node pays, and how long it pays it for is how many +// passes a cycle takes. +// +// A table the walk gets round inside one pass closes a cycle on every pass, and +// the caller republishes this flag at the end of each — so such a node never +// reads "still reading" at all: the pass that would have reported it closed a +// cycle over the grown table first. That is a table of about fourteen records +// at the 30 ms a record this firmware links (kWalkBudgetMs / 30), or about +// seven on a pass sweeping from ahead of the rows, which is where the rows get +// half the budget (rowShareSpent). +// +// Past that the reading lasts the passes of the cycle that follows the growth, +// during which the node is telling the truth: it is reading its table, and the +// rows on screen are from before the table grew. At the cap and those fourteen +// records a pass, that cycle is five passes, so four of them read "still +// reading". +// +// What it must not do is read "still reading" for the life of a large node, +// which is exactly what the third clause on its own would do: a node whose +// table keeps growing would start a new multi-pass cycle for every growth and +// never be caught up with. The cap clause is what stops it. A table holding +// more than SNAPSHOT_MAX_PATHS paths the walk can render closes its cycles at +// the cap, so such a node is whole from the first cycle that fills and stays +// whole however much the table grows afterwards. +// +// Two readings this deliberately does *not* call "still reading", because +// neither is one: +// +// * a table whose entries have no receiving interface. They are counted in +// tableSize and contribute no rows, so a cycle over them closes whole with +// a short list — which is what it is: the cycle did cover the table, and +// those entries are the dead-path sweep's to remove. +// * a table smaller than the one the cycle closed over. The list is a cycle +// old, not a prefix. +// +// One predicate, not two: this produces Tables::snapRowsWhole and +// Snapshot::stillReadingPaths() is still the only thing that reads it beside a +// count (RnsTransport.h). +inline bool rowsWhole(const RowCycle& c, size_t tableNow) { + return c.closed && (c.filledCap || tableNow <= c.tableSize); +} + +// Whether the walk should give the core up before touching this record. +// +// `elapsedMs` and `lastYieldMs` are both measured from the start of the walk, +// and `lastYieldMs` starts at zero — so the first yield of a pass comes at the +// first record at or past the interval, not at the first record. +inline bool walkShouldYield(uint32_t elapsedMs, uint32_t lastYieldMs, + uint32_t intervalMs = kWalkYieldMs) { + return (uint32_t)(elapsedMs - lastYieldMs) >= intervalMs; +} + +// Where a cursor resumes at the top of a pass, given how big the table is now. +// +// One rule, both cursors. The walk carries two — where the sweep left off and +// where row collection left off — and the hazard is identical for each, so it +// is defined once and asked twice rather than written out again for the newer +// one. +// +// A cursor is an offset into a table that is mutated between passes, so it can +// be left pointing past the end of one: the caller drops up to +// SNAPSHOT_MAX_PATHS entries at the end of a pass, which can take the table out +// from under a cursor that was beyond them. Such a cursor is reached by no +// position, and nothing downstream corrects it — nextCursor() below only ever +// moves forwards, so on a table slow enough for the budget to end every pass it +// would keep returning that same stale value: the sweep would stay part-way +// through for ever, the cycle would never close, and the minute clock that +// starts the next one would never be stamped again. The row cursor stranded the +// same way would stop a list ever being finished, so nothing would be published +// at all. +// +// So a cursor at or past the end of the table is not a cursor, and its cycle +// starts again from the front. Asked before the caller decides whether it is +// sweeping, so the pass that finds it stale is the one that starts afresh. +inline size_t resumeCursor(size_t cursor, size_t tableSize) { + return cursor < tableSize ? cursor : 0; +} + +// Where the row cursor resumes, which is the rule above plus one condition of +// its own. +// +// The row cursor indexes a list as well as a table, and the two have to agree: +// the staging list holds exactly what the positions before the cursor +// contributed. The one thing that can part them is the pass throwing between +// the last row it pushed and the cursor being written back — Diag::guard +// catches it, and reading a record under memory pressure can cause it. The +// rows collected before the throw are then in the list with the cursor still +// behind them, so the next pass collects them a second time and publishes a +// list with duplicates in it, or one short of the table. +// +// `passWasClean` is the caller's record of whether the last pass got as far as +// writing the cursor back. When it did not, the cycle starts again from the +// front: cheaper than reasoning about which rows survived, and it is the same +// answer resumeCursor() gives a cursor it cannot trust. +// +// Here rather than at the call site because it is a rule about a cursor, and +// every other rule about these two cursors is in this file where the host can +// drive it. It was the one piece of that bookkeeping left in RnsTransport.cpp, +// which cannot be compiled for the host at all. +inline size_t resumeRowCursor(size_t cursor, size_t tableSize, bool passWasClean) { + return passWasClean ? resumeCursor(cursor, tableSize) : 0; +} + +// Where a cursor resumes on the next pass, given where this one stopped. +// +// One rule, both cursors again, and for the same reason: what the sweep needed +// of its cursor is exactly what row collection needs of its own. +// +// Forwards only, within a cycle. The budget can end the walk anywhere, +// including at a position *behind* one of the cursors — a sweeping pass steps +// over the prefix it has already examined and can be stopped in it, and a pass +// resuming a part-built row list steps over the rows it already has. Writing +// the stop position in unconditionally would drag the cursor back to the front +// and leave the tail of the table never reached, which is the exact bug a +// resuming cursor is added to avoid. Getting all the way round (`!cutShort`) +// closes the cycle instead: for the sweep that puts the next one a +// kStaleSweepMs out, and for the rows it is what makes the list publishable. +// +// `cutShort` and `stoppedAt` are each cursor's own, not the walk's. They are +// the same for the sweep, whose half ends where the walk ends; for the rows +// they are where row collection stopped and whether anything stopped it — +// which after the share is spent is not where the walk stopped, because the +// walk carries on to the sweep's cursor without them. +// +// Forwards only is a ratchet, and a ratchet has to be answerable to the thing +// it indexes: resumeCursor() above is what keeps it from ratcheting into a +// table that has since shrunk past it. +inline size_t nextCursor(size_t cursor, size_t stoppedAt, bool cutShort) { + if (!cutShort) return 0; + return stoppedAt > cursor ? stoppedAt : cursor; +} + +} // namespace Rns diff --git a/src/sys/Maintenance.cpp b/src/sys/Maintenance.cpp index 97ffa7d..ceadcbd 100644 --- a/src/sys/Maintenance.cpp +++ b/src/sys/Maintenance.cpp @@ -391,13 +391,20 @@ static void doStatus() { // // rx_drain_capped is on the same line and is not a third fault: it counts the // Reticulum-task passes whose batch of received frames ended with more still - // in the ring, which loses nothing and is expected after a long path-table - // sweep. The format below prints it after the rx=/tx= pair and before the two - // carrier-sense counters — with the traffic figures it is about, and without - // splitting the two an operator reads together — and it is on the console at - // all because a node reachable only over TCP 4243 has no other way to be - // asked. /api/status carries it as radio.rx_drain_capped, and real loss on - // this path is radio.rx_dropped_ring. + // in the ring, which loses nothing. The pass after a full-budget path-table + // walk is the case to expect — the budget covers the whole walk now, not the + // sweep half, so on a table too big to read in one pass it ends most passes, + // every five seconds, for as long as the table stays that big. A total that + // climbs steadily is therefore this node getting round its own table as + // readily as a busy channel (Config.h, loraRxDrainCapped). Nothing on this + // line tells the two apart: the console has never carried table figures, and + // diag.tables.snap_budget_stops in /api/status is what says which. The format + // below prints it after the rx=/tx= pair and before the two carrier-sense + // counters — with the traffic figures it is about, and without splitting the + // two an operator reads together — and it is on the console at all because a + // node reachable only over TCP 4243 has no other way to be asked. + // /api/status carries it as radio.rx_drain_capped, and real loss on this path + // is radio.rx_dropped_ring. dataf("STATUS", "radio=%s model=%s rx=%lu tx=%lu rx_drain_capped=%lu " "cad_timeouts=%lu cad_arm_errors=%lu", g_stats.radioOnline ? "online" : "offline", g_stats.radioModel, diff --git a/src/sys/RingDrain.h b/src/sys/RingDrain.h index da02aaf..b491b31 100644 --- a/src/sys/RingDrain.h +++ b/src/sys/RingDrain.h @@ -44,7 +44,7 @@ // // That last step is read off the code, not off a log. No such reset has been // observed on this ring: the two-day reboot loop the neighbouring scar -// describes is the path-table sweep's (RnsTransport.cpp, kWalkBudgetMs), a +// describes is the path-table sweep's (SnapshotWalk.h, kWalkBudgetMs), a // different unbounded loop, and the bench reproduction for this one — // flooding the ring from a host on the access point — has not been run. // Where the reset itself is named it is named as something that *can* @@ -89,31 +89,29 @@ namespace RingDrain { // explain the counter to a reader quote the walk's 400 ms budget as the gap: // main.cpp's heartbeat line, Config.h beside loraRxDrainCapped, // tools/soak.py's column notes, docs/api.md and docs/troubleshooting.md. -// Retuning kWalkBudgetMs means visiting all of those, and the radio drain's -// frames-per-gap arithmetic in RnsTransport.cpp is derived from this figure -// and moves with it — test_airtime pins the two frame times that arithmetic -// rests on, not the frames it puts in the gap. +// Retuning kWalkBudgetMs (SnapshotWalk.h) means visiting all of those, and the +// radio drain's frames-per-gap arithmetic in RnsTransport.cpp is derived from +// this figure and moves with it — test_airtime pins the two frame times that +// arithmetic rests on, not the frames it puts in the gap. // // The RNS task delays 10 ms between passes (main.cpp), but the interval // between two drains of the same ring is that delay plus a whole pass, and a // pass contains refreshSnapshots(), whose path-table walk reads records back // off the filesystem under a kWalkBudgetMs — 400 ms — budget -// (RnsTransport.cpp). -// -// That budget is a floor under the gap, not a ceiling over it. It is consulted -// only once the snapshot's rows are full — the check is guarded on !wantRow, -// and the walk states the rule itself: "the budget ends the sweep, never the -// rows". While rows are still being collected it is not consulted at all, and -// a record whose interface has gone away is read off the filesystem and then -// skipped without filling a row, which is the very thing the sweep exists to -// clean up. A table of those keeps the row phase going to the end of the table -// with no budget in force. The row phase is bounded by the table, not by the -// clock, and it runs ahead of the budgeted part. +// (SnapshotWalk.h). +// +// That budget is a floor under the gap, not a ceiling over it. It covers every +// position of the walk now, rows included — it used to be guarded on !wantRow, +// so the row phase ahead of it ran unbudgeted and a table of entries whose +// interfaces had gone away, which fill no row, kept that phase going to the end +// of the table with no bound in force at all. What keeps it a floor rather than +// a ceiling is the rest: the budget is consulted between records and never +// inside one, and the walk is one part of a pass. // // Two consecutive drains of one ring are therefore of the order of 410 ms -// apart rather than 10 — the sweep's budget plus the tick — and that is the -// least of it, before the row phase ahead of the budget or the rest of the -// pass is counted at all, and further again after a pass that threw, which +// apart rather than 10 — the walk's budget plus the tick — and that is the +// least of it, before the record in hand when the budget ran out or the rest of +// the pass is counted at all, and further again after a pass that threw, which // adds loop()'s 250 ms back-off. // // So the cap does bind, on both rings, after a long walk: 410 ms on its own is @@ -133,12 +131,20 @@ namespace RingDrain { // is also what keeps it from showing up as anything else. constexpr size_t kBatch = 64; -// Items between watchdog feeds, and the one definition of that cadence: the -// record walk in refreshSnapshots() reads it from here rather than keeping its -// own 16, so the two cannot drift apart. The cap ends the pass, but it is only -// checked between items and one item can be a whole packet through -// microReticulum — so the drain keeps reporting while it runs rather than -// relying on finishing. +// Items between watchdog feeds. The cap ends the pass, but it is only checked +// between items and one item can be a whole packet through microReticulum — so +// the drain keeps reporting while it runs rather than relying on finishing. +// +// The rings' cadence and no one else's, now. The path-table walk in +// refreshSnapshots() used to borrow this number for its own feeds, on the +// reasoning above and for the sake of one definition; the arithmetic does not +// carry across. A ring item is a memcpy and a handler, and 64 of them are what +// one pass takes; a record is a file opened on LittleFS, and at 30 ms — or the +// 93-162 ms of the reopen-per-record regime — sixteen of them are longer than +// that walk's whole 400 ms budget, so neither a feed nor a yield on this +// cadence could fire there at all. The walk feeds either side of its loop +// instead, being bounded, and yields on an elapsed-time cadence of its own: +// both are in SnapshotWalk.h, with the arithmetic and the test that drives it. constexpr size_t kFeedEvery = 16; // What one pass did. @@ -193,14 +199,21 @@ inline Pass drain(size_t cap, size_t feedEvery, while (pass.handled < cap) { auto item = receive(); if (!item) { ranDry = true; break; } - // Feeds bracket the work the way the snapshot walk's do: one before the - // first item, one every `every` items through it, one after the last. Not - // before the receive, though — this is called a hundred times a second on - // a ring that is usually empty, and a pass with no work has nothing to - // report and no reason to take the watchdog's lock to say so. + // Feeds bracket the work: one before the first item, one every `every` + // items through it, one after the last. Not before the receive, though — + // this is called a hundred times a second on a ring that is usually empty, + // and a pass with no work has nothing to report and no reason to take the + // watchdog's lock to say so. + // + // The cadence in the middle is this drain's own and no longer has a + // sibling: the snapshot walk used to feed on the same rule and does not any + // more, because a bounded pass needs no feed inside it and 16 records is + // longer than the whole of that pass's budget anyway (SnapshotWalk.h). Here + // an item is a ring item rather than a file read, a batch is 64 of them, + // and nothing bounds one by time — so the cadence stands on that. if (pass.handled == 0) feed(); - // Counted, and fed for, before the item is handled: as in the walk, the - // feed has to come before the expensive part, not after it. + // Counted, and fed for, before the item is handled: the feed has to come + // before the expensive part, not after it. if (++pass.handled % every == 0) feed(); handle(item); } diff --git a/src/ui/lvgl/UiDestinations.cpp b/src/ui/lvgl/UiDestinations.cpp index 149f04d..17467da 100644 --- a/src/ui/lvgl/UiDestinations.cpp +++ b/src/ui/lvgl/UiDestinations.cpp @@ -145,7 +145,12 @@ namespace Ui { void openDestinations() { lv_obj_t* body = newScreen("Mesh"); - sCount = RnsTransport::paths(sPaths, kMax); + // One reading, under one lock — Display.cpp's transport panel uses the same + // idiom. The rows, the total that describes them and whether the rows are a + // whole cycle all come out of one pass, which is what lets the empty case + // below say which empty it is (RnsTransport.h). + const RnsTransport::Snapshot snap = RnsTransport::snapshot(sPaths, kMax, nullptr, 0); + sCount = snap.pathRows; // Nearest and freshest first, the order a person routes by. for (size_t i = 0; i + 1 < sCount; i++) for (size_t j = 0; j + 1 < sCount - i; j++) { @@ -158,7 +163,22 @@ void openDestinations() { lv_obj_t* list = lv_list_create(body); lv_obj_set_width(list, lv_pct(100)); lv_obj_set_flex_grow(list, 1); - if (!sCount) lv_list_add_text(list, "nothing announced yet"); + if (!sCount) { + // "Nothing there" and "not read yet" render as the same empty list and are + // not the same node. Home's PEERS SEEN is the table's own size and is exact + // from the first pass, so on exactly that node the two screens used to + // contradict each other: "500" there and "nothing announced yet" here. + // The rule itself is Snapshot::stillReadingPaths() — one definition, asked + // here, by the nav page's peer plot and by the web portal. + if (snap.stillReadingPaths()) { + char line[48]; + snprintf(line, sizeof(line), "still reading %u path%s…", (unsigned)snap.pathTotal, + snap.pathTotal == 1 ? "" : "s"); + lv_list_add_text(list, line); + } else { + lv_list_add_text(list, "nothing announced yet"); + } + } for (size_t i = 0; i < sCount; i++) { char age[8], line[80]; Ui::ageTextS(sPaths[i].ageS, age, sizeof(age)); diff --git a/src/ui/lvgl/UiNav.cpp b/src/ui/lvgl/UiNav.cpp index 2c194e6..12cdeae 100644 --- a/src/ui/lvgl/UiNav.cpp +++ b/src/ui/lvgl/UiNav.cpp @@ -165,11 +165,18 @@ void plotRefresh(lv_timer_t*) { static RnsTransport::PathInfo sPaths[24]; size_t count = 0; const Gps::Fix own = Gps::fix(); + // One reading, under one lock — the list screen and Display.cpp's transport + // panel take theirs the same way. Asked outside the fix check because the + // caption below needs it either way: an empty plot on a node that has not + // finished reading its own path table looks exactly like an empty plot on a + // node nobody has announced to, and the two want different answers + // (RnsTransport.h). + const RnsTransport::Snapshot snap = RnsTransport::snapshot(sPaths, 24, nullptr, 0); if (own.valid) { // Peers with announced positions, north-up from our fix: ring one is a // kilometre, the rim two, and beyond clamps just inside the rim — not on // the compass letters. - const size_t n = RnsTransport::paths(sPaths, 24); + const size_t n = snap.pathRows; for (size_t i = 0; i < n && count < 8; i++) { PeerPositions::Position pp; if (!PeerPositions::getByHex(sPaths[i].hash, pp)) continue; @@ -191,7 +198,13 @@ void plotRefresh(lv_timer_t*) { // identical readings is churn on the task the glass is painted from. The // caption's inputs are in the stamp too, since it is redrawn with them. const size_t held = PeerPositions::count(); + // A third caption, and so a third stamp input: a node still reading its own + // path table has no rows to plot from and is not the same as a node with no + // peer positions on the air. The rule is Snapshot::stillReadingPaths(), the + // same one the destinations page and the web portal ask. + const bool stillReading = snap.stillReadingPaths(); uint32_t stamp = (uint32_t)count * 131u + (uint32_t)held * 7u + (own.valid ? 1u : 0u); + stamp = stamp * 31u + (stillReading ? (uint32_t)snap.pathTotal + 1u : 0u); for (size_t i = 0; i < count; i++) { stamp = stamp * 31u + (uint32_t)(sPlaced[i].x + 1024) * 2048u + (uint32_t)(sPlaced[i].y + 1024); @@ -215,11 +228,17 @@ void plotRefresh(lv_timer_t*) { if (count) lv_label_set_text_fmt(sPlotCap, "NORTH UP · %u peer%s placed", (unsigned)count, count == 1 ? "" : "s"); - else if (held) + else if (held && (!own.valid || !stillReading)) // The store knows the truth the old caption guessed at: positions are - // on the air; the missing half is our own fix. + // on the air; the missing half is our own fix. Without a fix that is the + // whole answer whatever the path table is doing, which is why it is asked + // first; with one, a table still being read is the better explanation for + // an empty plot and gets the caption instead. lv_label_set_text_fmt(sPlotCap, "NORTH UP · own fix needed — %u position%s held", (unsigned)held, held == 1 ? "" : "s"); + else if (stillReading) + lv_label_set_text_fmt(sPlotCap, "NORTH UP · still reading %u path%s", + (unsigned)snap.pathTotal, snap.pathTotal == 1 ? "" : "s"); else lv_label_set_text(sPlotCap, "NORTH UP · no peer positions on the air yet"); } diff --git a/test/test_ring_drain/test_main.cpp b/test/test_ring_drain/test_main.cpp index 18693f6..8dad9dd 100644 --- a/test/test_ring_drain/test_main.cpp +++ b/test/test_ring_drain/test_main.cpp @@ -324,10 +324,17 @@ static void test_exactly_the_cap_with_one_more_waiting_is_capped() { TEST_ASSERT_EQUAL_size_t(1, ring.waiting()); } -static void test_the_feed_cadence_matches_the_snapshot_walk() { - // refreshSnapshots(): feed before the walk, feed before every kFeedEvery-th - // record, feed after the walk. Positions are the count of items completed - // when the feed happened, so a feed "before the 16th" reads as 15. +static void test_a_pass_is_bracketed_by_feeds_with_the_cadence_in_between() { + // Feed before the first item, feed before every kFeedEvery-th item after + // that, feed after the last. Positions are the count of items completed when + // the feed happened, so a feed "before the 16th" reads as 15. + // + // This used to be named for the path-table walk in refreshSnapshots(), which + // borrowed kFeedEvery for its own feeds. It no longer does: a record costs + // 30 ms or more, so sixteen of them outlast that walk's whole budget and the + // middle branch below never ran there at all. The walk is bounded and feeds + // either side instead (SnapshotWalk.h). What is asserted here is unchanged + // and is the drains' own cadence, where an item is a memcpy and a handler. FakeRing ring; fill(ring, 100); Record rec; @@ -513,7 +520,7 @@ int main() { RUN_TEST(test_exactly_the_cap_with_one_more_waiting_is_capped); RUN_TEST(test_the_ring_is_asked_at_most_once_a_pass); RUN_TEST(test_a_handler_that_returns_early_still_counts_and_keeps_going); - RUN_TEST(test_the_feed_cadence_matches_the_snapshot_walk); + RUN_TEST(test_a_pass_is_bracketed_by_feeds_with_the_cadence_in_between); RUN_TEST(test_an_empty_ring_is_a_no_op); RUN_TEST(test_a_zero_feed_cadence_does_not_divide_by_zero); RUN_TEST(test_a_zero_cap_takes_nothing_and_reports_nothing); diff --git a/test/test_snapshot_walk/test_main.cpp b/test/test_snapshot_walk/test_main.cpp new file mode 100644 index 0000000..f3d1a78 --- /dev/null +++ b/test/test_snapshot_walk/test_main.cpp @@ -0,0 +1,1631 @@ +// SPDX-License-Identifier: GPL-3.0-or-later +// Copyright (C) 2026 Dobrev IT Ltd +// +// This file is part of RetiMesh Node. +// +// RetiMesh Node is free software: you can redistribute it and/or modify it +// under the terms of the GNU General Public License as published by the +// Free Software Foundation, either version 3 of the License, or (at your +// option) any later version. +// +// RetiMesh Node is distributed in the hope that it will be useful, but +// WITHOUT ANY WARRANTY; without even the implied warranty of +// MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the GNU General +// Public License for more details. +// +// You should have received a copy of the GNU General Public License along +// with RetiMesh Node. If not, see . + + +// SnapshotWalk: the bound that keeps the path-table walk from starving the +// task underneath it, and the rules that make that bound safe. +// +// What is pinned here is what the fix is: +// +// * the budget stops a pass while the rows are still filling — it used to be +// guarded on !wantRow, so the expensive half of the walk had no bound at +// all; +// * it stops one on the free step-over path too, which used to `continue` +// before the check was ever reached; +// * "the rows are full and no sweep wants the rest" is still a clean finish +// and not a budget stop, because only a budget stop leaves a cursor +// part-way down the table; +// * neither cursor ever moves backwards, which is a hazard the first of +// those creates: a stop in the row half is at the front of the table, and +// writing it in would drag the sweep there and leave the tail unexamined; +// * a cursor the table has shrunk past starts the cycle again instead of +// latching, which is the other side of "forwards only": a ratchet with +// nothing to answer to would never come back inside the table; +// * the budget stays well inside the interval a pass is gated on, which is +// what actually returns the core to loopTask — the yields are a margin; +// * and the yield cadence really does give the core up several times inside +// one budget at the per-record costs this repository has measured — the +// exact thing reusing Sys::RingDrain::kFeedEvery would have failed at. +// +// And what the pass that resumed row collection across passes had to hold on +// to, all of it learned from the abandoned branch that tried it first: +// +// * row collection carries a cursor of its own, under the same two rules the +// sweep's is under — test_a_row_bound_table_now_advances_the_cursor is the +// limitation test that used to assert the opposite; +// * a pass may not be stopped by the budget until it has dereferenced one +// record, so it always reaches its own cursor and always moves it forward, +// whatever a step comes to cost; +// * the end of a pass is the rows being *full*, not this position wanting no +// row — "no row here" is what a resuming pass sees at position 0, and +// ending on it published 19 rows on a node holding 87; +// * only a whole list is published; a budget-stopped pass keeps its prefix; +// * a pass that threw between its last row and its cursor starts the cycle +// again rather than collecting those rows a second time; +// * the removal that follows the walk is on the *walk's* clock, so the two +// together are one budget and not two; +// * a closed row cycle answers only for the table it closed over, so the +// empty one every node boots with stops being called whole the moment the +// table grows past it — and a cycle that closed at the cap keeps answering, +// so a large node does not read "still reading" for the life of the run; +// * and a pass that threw buys the node the same back-off a pass that +// returned does, measured from where it stopped. +// +// refreshSnapshots() itself cannot be built for the host — [env:native] has no +// framework, no microReticulum, no LittleFS and no FreeRTOS — so the rule was +// lifted into a pure header the firmware calls and this suite drives directly, +// the way test_ring_drain drives RingDrain.h. The walk harness below is that +// loop written out again over a table of flags and a clock: if the two shapes +// diverge, this suite stops describing the firmware, so it is kept deliberately +// close to the call site. +// +// The per-record costs the yield tests use are the repository's own, not +// invented for this suite: +// +// 30 ms platformio.ini, lib_deps: a 200-record walk "costs about 6 s now" +// once microStore held its segment file open across the iteration. +// 6000/200 = 30. +// 162 ms microStore's FileStore.h, load_value(): "one record cost 93-162 ms" +// on a 200-record path store in the reopen-per-record regime, "nearly +// all of it under lfs_dir_find". The slow end of that range is the +// worst per-record figure anywhere in the tree. +#include +#include +#include +#include +#include "Config.h" // SNAPSHOT_MAX_PATHS, SNAPSHOT_SWEEP_INTERVAL_MS +#include "../../src/sys/RingDrain.h" // kFeedEvery, the cadence that will not do +#include "../../src/rns/SnapshotWalk.h" + +namespace { + +// The firmware's row cap, not a number of this suite's own: a retune of +// SNAPSHOT_MAX_PATHS must move what is asserted here with it. +constexpr size_t kRowCap = SNAPSHOT_MAX_PATHS; + +// The ceiling refreshSnapshots() passes nextIntervalMs() — the minute between +// dead-path sweep cycles. Read from Config.h for the same reason as the cap: +// the firmware's kStaleSweepMs is that same figure, and this suite writing +// 60000 out for itself is how the two come to disagree after a retune. +constexpr uint32_t kSweepCeilingMs = SNAPSHOT_SWEEP_INTERVAL_MS; + +// Per-record costs, sourced above. +constexpr uint32_t kFastRecordMs = 30; +constexpr uint32_t kSlowRecordMs = 162; + +// --------------------------------------------------------------------------- +// One position's inputs, spelled out so a test reads as a sentence. +// --------------------------------------------------------------------------- +// `readAny` is true because that is what every position after the first of a +// pass looks like; the two tests about the forward-progress rule say otherwise +// with havingReadNothing() below. +Rns::WalkState at(size_t rows, bool sweeping, size_t pos, size_t sweepPos, + uint32_t elapsedMs, uint32_t budgetMs = Rns::kWalkBudgetMs) { + Rns::WalkState w; + w.rowsCollected = rows; + w.rowCap = kRowCap; + w.rowPos = 0; + w.sweeping = sweeping; + w.pos = pos; + w.sweepPos = sweepPos; + w.elapsedMs = elapsedMs; + w.budgetMs = budgetMs; + w.readAny = true; + return w; +} + +// The same position on a pass that is continuing a part-built row list. +Rns::WalkState resumingRowsAt(Rns::WalkState w, size_t rowPos) { + w.rowPos = rowPos; + return w; +} + +// The same position on a pass that has not dereferenced anything yet. +Rns::WalkState havingReadNothing(Rns::WalkState w) { + w.readAny = false; + return w; +} + +// --------------------------------------------------------------------------- +// The walk, as refreshSnapshots() runs it, over a synthetic table. +// +// `live[k]` is "position k has a receiving interface", which is what decides +// whether reading it fills a row. A dead entry costs exactly as much to read as +// a live one and fills nothing — that asymmetry is the reason the old !wantRow +// guard left the whole table unbudgeted, so the harness has to model it. +// +// The clock only moves when a record is dereferenced, plus one tick per yield: +// stepping over a position is free (test_typed_store_iterator pins that against +// microStore itself). `skipMs` exists to say what happens when it is *not* — +// the regression the forward-progress rule is a defence against — and is zero +// everywhere else. +// --------------------------------------------------------------------------- +struct Pass { + size_t rows = 0; // rows in the staging list after this pass + size_t added = 0; // ...of which this pass collected these + size_t reads = 0; // records dereferenced + size_t skipped = 0; // positions stepped over + size_t yields = 0; + size_t stoppedAt = 0; // the position the walk left off at + // Row collection's own two, which are not the walk's once the sweep's share + // of the budget begins: the walk goes on to the sweep's cursor without the + // rows, so where it stopped is not where they did. + size_t rowStoppedAt = 0; // one past the last position the rows were served at + bool rowsCut = false; // the share ended the row half before the list did + bool ranOut = false; // the budget ended it + bool rowsFull = false; // it ended because there was nothing left to do + uint32_t elapsedMs = 0; + std::vector swept; // dead entries the pass found while sweeping + std::vector yieldAt; // walk time at each yield, before its tick is paid +}; + +// `costMs` is what each position's record costs, for the one property that +// needs two different per-record figures inside one pass: a filesystem charges +// what it charges, and the range measured on one store is 93-162 ms rather than +// a constant (FileStore.h). Positions past its end fall back to `recordMs`, so +// a short vector says "these first few, then the usual". +Pass runWalk(const std::vector& live, bool sweeping, size_t sweepPos, + uint32_t recordMs, uint32_t yieldMs = Rns::kWalkYieldMs, + uint32_t tickMs = 1, uint32_t budgetMs = Rns::kWalkBudgetMs, + size_t rowPos = 0, size_t rowsAlready = 0, uint32_t skipMs = 0, + const std::vector* costMs = nullptr) { + Pass r; + r.rows = rowsAlready; // the cycle's list, carried in + uint32_t lastYieldMs = 0; + for (size_t pos = 0; pos < live.size(); pos++) { + Rns::WalkState w = + at(r.rows, sweeping, pos, sweepPos, r.elapsedMs, budgetMs); + w.rowPos = rowPos; + w.readAny = r.reads > 0; + const Rns::WalkStep step = Rns::walkStep(w); + r.stoppedAt = pos; + if (step == Rns::WalkStep::StopRowsFull) { r.rowsFull = true; return r; } + if (step == Rns::WalkStep::StopBudget) { r.ranOut = true; return r; } + // Before the step-over, as at the call site: a position the share denied + // the rows comes back as a Skip when the sweep does not want it either. + if (step == Rns::WalkStep::Row) r.rowStoppedAt = pos + 1; + else if (Rns::rowShareDenied(w)) r.rowsCut = true; + if (step == Rns::WalkStep::Skip) { r.skipped++; r.elapsedMs += skipMs; continue; } + + if (Rns::walkShouldYield(w.elapsedMs, lastYieldMs, yieldMs)) { + lastYieldMs = w.elapsedMs; + r.yields++; + r.yieldAt.push_back(w.elapsedMs); + r.elapsedMs += tickMs; // a yield is paid out of the budget + } + r.reads++; + r.elapsedMs += (costMs && pos < costMs->size()) ? (*costMs)[pos] : recordMs; + if (!live[pos]) { if (sweeping) r.swept.push_back(pos); continue; } + if (step == Rns::WalkStep::Row) { r.rows++; r.added++; } + } + r.stoppedAt = live.size(); // the walk reached the end of the table + return r; +} + +std::vector table(size_t n, bool allLive) { return std::vector(n, allLive); } + +// --------------------------------------------------------------------------- +// One pass with the cursor rules around it, in the order refreshSnapshots() +// applies them: resume against the table as it is now, walk, write the cursor +// back. `sweeping` is forced on, which is the firmware's state whenever a +// cursor is part-way down a table or the minute is up. +// +// Row collection is left at the front here, so this drives the sweep cursor on +// its own. The whole of refreshSnapshots()'s bookkeeping — both cursors, the +// staging list and the publish — is Node below. +// --------------------------------------------------------------------------- +struct Sweep { + size_t cursor = 0; // where the next pass would resume + bool closed = false; // this pass reached the end of the table + Pass pass; +}; + +Sweep sweepOnce(const std::vector& live, size_t cursor, uint32_t recordMs) { + Sweep s; + const size_t from = Rns::resumeCursor(cursor, live.size()); + s.pass = runWalk(live, true, from, recordMs); + s.closed = !s.pass.ranOut; + s.cursor = Rns::nextCursor(from, s.pass.stoppedAt, s.pass.ranOut); + return s; +} + +// --------------------------------------------------------------------------- +// Everything refreshSnapshots() carries in statics from one pass to the next, +// and the order it applies the rules in: resume both cursors against the table +// as it is now, empty the staging list only if the row cycle is starting, walk, +// write both cursors back, and publish the rows only if the cycle finished. +// +// Kept deliberately close to the call site, like runWalk() above: if the two +// shapes diverge this suite stops describing the firmware. +// --------------------------------------------------------------------------- +struct Node { + size_t sweepPos = 0; + size_t rowPos = 0; + size_t staged = 0; // rows the current cycle has collected so far + size_t published = 0; // rows in the list readers actually see + // What the last cycle to publish covered, and what the node serves as + // snapRowsWhole because of it: the firmware's sRowCycle and the + // Rns::rowsWhole() it is read through, carried here for the same reason the + // cursors are — so the harness cannot describe a node this firmware is not. + Rns::RowCycle cycle; + bool rowsWhole = false; // Tables::snapRowsWhole, recomputed every pass + bool rowPassClean = true; // the last pass wrote its row cursor back + size_t rowCycles = 0; + size_t sweepCloses = 0; + size_t sweptTotal = 0; + size_t budgetStops = 0; +}; + +// Snapshot::stillReadingPaths() — !snapRowsWhole && pathTotal > 0 +// (RnsTransport.h). That header cannot be built for the host any more than +// refreshSnapshots() can, so the one predicate every surface asks is driven +// here through its two inputs, the way the walk itself is written out again +// above. +bool stillReading(const Node& n, size_t tableSize) { + return !n.rowsWhole && tableSize > 0; +} + +// `aborts` is a pass that throws mid-walk: Diag::guard catches it in the +// firmware and nothing after the walk runs — no cursor written back, no +// publish. The staging list keeps what the walk pushed into it before the +// throw, because it is the caller's own vector and the throw does not unwind +// it. That is the one state in which the list and the cursor disagree, and it +// is what Rns::resumeRowCursor() is for. +Pass onePass(Node& n, const std::vector& live, uint32_t recordMs, + bool sweeping = true, uint32_t skipMs = 0, bool aborts = false) { + n.sweepPos = Rns::resumeCursor(n.sweepPos, live.size()); + n.rowPos = Rns::resumeRowCursor(n.rowPos, live.size(), n.rowPassClean); + if (n.rowPos == 0) n.staged = 0; + n.rowPassClean = false; // set again when the cursor is written back + const Pass r = runWalk(live, sweeping, n.sweepPos, recordMs, Rns::kWalkYieldMs, 1, + Rns::kWalkBudgetMs, n.rowPos, n.staged, skipMs); + n.staged = r.rows; // pushed as the walk went, so it survives a throw + if (aborts) return r; + n.sweptTotal += r.swept.size(); + if (r.ranOut) n.budgetStops++; + // The row half's own two figures, and its own answer to "was it cut short": + // the budget, or the sweep's share of the budget. + const bool rowsShort = r.ranOut || r.rowsCut; + const bool rowsDone = Rns::rowCycleDone(r.rows, kRowCap, rowsShort); + n.rowPos = rowsDone ? 0 : Rns::nextCursor(n.rowPos, r.rowStoppedAt, rowsShort); + n.rowPassClean = true; // list and cursor agree again + if (sweeping) { + n.sweepPos = Rns::nextCursor(n.sweepPos, r.stoppedAt, r.ranOut); + if (!r.ranOut) n.sweepCloses++; + } + if (rowsDone) { + n.published = r.rows; + Rns::closeRowCycle(n.cycle, r.rows, kRowCap, live.size()); + n.rowCycles++; + } + // Every pass publishes the flag, whether or not it published a list: it + // describes the list readers are holding against the table as it is now. + n.rowsWhole = Rns::rowsWhole(n.cycle, live.size()); + return r; +} + +// --------------------------------------------------------------------------- +// The removal that follows the walk, as refreshSnapshots() runs it. +// +// The point of the harness is the clock. The loop at the call site is bounded +// by passMayStop((uint32_t)(millis() - walkStartMs), ...) — the *walk's* start, +// deliberately, so that the walk and the removal together are one budget and +// not two. Only the primitive was pinned before this; the sharing was not, and +// swapping walkStartMs for a removeStartMs of its own would hand the removal a +// second full budget without failing anything. +// +// `removeMs` is this harness's own parameter and not a measurement: nothing in +// this tree times a BasicFileStore::remove(), which is a tombstone appended and +// flushed plus an index entry written and flushed (FileStore.h). The tests pick +// figures that divide the budget so the arithmetic is readable. +// +// `allGone` is the case where every key in `stale` has already been removed by +// something else: remove_path() returns false, and it returns before touching +// flash, so the iteration costs nothing. +// --------------------------------------------------------------------------- +struct Removal { + size_t dropped = 0; // remove_path() said yes + size_t attempts = 0; // ...out of this many tries + uint32_t elapsedMs = 0; // still measured from the start of the *walk* + bool stopped = false; // the budget ended it with entries left +}; + +Removal runRemoval(size_t stale, uint32_t walkElapsedMs, uint32_t removeMs, + uint32_t budgetMs = Rns::kWalkBudgetMs, bool allGone = false) { + Removal r; + r.elapsedMs = walkElapsedMs; // one clock, and the walk started it + for (size_t k = 0; k < stale; k++) { + if (Rns::passMayStop(r.elapsedMs, r.attempts > 0, budgetMs)) { r.stopped = true; break; } + r.attempts++; + if (!allGone) { r.dropped++; r.elapsedMs += removeMs; } + } + return r; +} + +// --------------------------------------------------------------------------- +// The gate refreshSnapshots() is entered through, and what a pass costs the +// node on its way out of it whichever way it leaves. +// +// Two statics and the scheduler between them, as the call site applies them: +// sSnapAtMs, stamped on the way in so a fast throw cannot come straight back; +// sSnapIntervalMs, which the gate is read against; and Rns::nextIntervalMs(), +// asked with what the pass cost. Written out again here for the same reason the +// walk is — refreshSnapshots() cannot be built for the host — and kept as close +// to it. +// --------------------------------------------------------------------------- +struct Gate { + uint32_t atMs = 0; + uint32_t intervalMs = (uint32_t)SNAPSHOT_INTERVAL_MS; + + bool dueAt(uint32_t nowMs) const { return (uint32_t)(nowMs - atMs) >= intervalMs; } + + void enter(uint32_t startMs) { atMs = startMs; } // the entry stamp + + // A pass that returned. Its cost buys the gap, measured from where the pass + // started, which is what the gate has always meant. + void passed(uint32_t startMs, uint32_t costMs) { + enter(startMs); + intervalMs = Rns::nextIntervalMs(costMs, (uint32_t)SNAPSHOT_INTERVAL_MS, kSweepCeilingMs); + } + + // A pass that threw. Diag::guard catches it and nothing after the throw runs, + // so the back-off is taken on the way out of the function instead — and the + // gap it buys runs from where the pass stopped, because a pass that has + // already outlasted its own interval would otherwise be due the instant it + // left. + void threw(uint32_t startMs, uint32_t costMs) { + enter(startMs); + intervalMs = Rns::nextIntervalMs(costMs, (uint32_t)SNAPSHOT_INTERVAL_MS, kSweepCeilingMs); + atMs = startMs + costMs; + } +}; + +} // namespace + +// --------------------------------------------------------------------------- +// The constants, and the relation the yield cadence rests on +// --------------------------------------------------------------------------- + +void test_the_constants_are_what_the_fix_committed_to() { + TEST_ASSERT_EQUAL_UINT32(400, Rns::kWalkBudgetMs); + TEST_ASSERT_EQUAL_UINT32(100, Rns::kWalkYieldMs); + // Strictly more than twice, not merely twice: a cadence of exactly half the + // budget yields once and then needs the whole budget elapsed for its second, + // which is a stop. + TEST_ASSERT_TRUE(Rns::kWalkYieldMs * 2 < Rns::kWalkBudgetMs); +} + +void test_the_budget_stays_well_inside_the_interval_a_pass_is_gated_on() { + // The relation the fix actually rests on, and the one most likely to be + // broken by someone buying rows back with a bigger budget. refreshSnapshots() + // runs at most once per SNAPSHOT_INTERVAL_MS, measured from the start of a + // pass: while a walk ends well inside that window the RNS task spends the + // rest of it going round its loop and sleeping 10 ms at a time, and those + // sleeps are the only core 1 the priority-1 loopTask gets. A walk that + // outlasts the window makes the gate a no-op and the passes run back to back, + // which is the shape that took a T-Beam down at 7.5 s a walk. The firmware + // static_asserts this beside the call; it is asserted here too, because this + // is the file kWalkBudgetMs would be retuned in. + // + // The relation, not the interval: retuning SNAPSHOT_INTERVAL_MS is allowed + // and this suite has no opinion on the figure, only on the two holding + // together. An equality on 5000 here would have failed such a retune while + // saying nothing about the rule. + TEST_ASSERT_TRUE_MESSAGE(Rns::walkBudgetFitsInterval(SNAPSHOT_INTERVAL_MS), + "the rule is the relation: the walk's budget must stay " + "inside a quarter of SNAPSHOT_INTERVAL_MS"); + // A quarter is where the line is: the same rule read the other way says the + // budget may not exceed a quarter of the interval. + TEST_ASSERT_TRUE(Rns::walkBudgetFitsInterval(Rns::kWalkBudgetMs * 4)); + TEST_ASSERT_FALSE(Rns::walkBudgetFitsInterval(Rns::kWalkBudgetMs * 4 - 1)); + // At the figures the firmware ships, that leaves 12.5x rather than 4x. + TEST_ASSERT_GREATER_OR_EQUAL_UINT32(Rns::kWalkBudgetMs * 12, + (uint32_t)SNAPSHOT_INTERVAL_MS); + // The rule is written `budget <= interval / 4` rather than + // `budget * 4 <= interval`, which are the same relation on every pair of + // integers that does not overflow and differ on the pairs that do: a + // kWalkBudgetMs at or above 2^30 wraps the product to something small and the + // multiplied form answers "fits". The budget is a constant, so only the + // interval side is reachable from here — an interval too small to hold any + // budget is refused, and is not a division by anything. + TEST_ASSERT_FALSE(Rns::walkBudgetFitsInterval(0)); + TEST_ASSERT_FALSE(Rns::walkBudgetFitsInterval(1)); + TEST_ASSERT_FALSE(Rns::walkBudgetFitsInterval(3)); +} + +void test_a_budget_that_outlasts_the_interval_is_what_the_guard_is_for() { + // The passage in SnapshotWalk.h that this pins used to work its example at + // 3 s and call it "a walk that never stops". It is not. The guard's rule read + // as a bound on the budget is budget <= interval/4, so a 3 s budget does fail + // it on the shipped interval... + TEST_ASSERT_GREATER_THAN_UINT32((uint32_t)SNAPSHOT_INTERVAL_MS / 4, 3000u); + // ...but a 3 s pass, plus even the worst record this tree has measured, still + // ends well before the 5 s gate reopens, so the RNS task reaches the 10 ms + // sleep at the end of its loop a couple of hundred times in the remainder. + // The guard is a 4x margin, not the cliff. + TEST_ASSERT_LESS_THAN_UINT32((uint32_t)SNAPSHOT_INTERVAL_MS, 3000u + kSlowRecordMs); + + // The cliff is a budget the interval cannot hold: the pass is still walking + // when the gate reopens, so the next one starts at once and the task never + // gets to its sleep. That is the shape that took the T-Beam down. + TEST_ASSERT_GREATER_THAN_UINT32((uint32_t)SNAPSHOT_INTERVAL_MS, 6000u); + + // And the yields buy nothing there, which is the whole point of the example. + // Sixty would be 6000/100; the real figure is 49, because a yield costs a + // tick that is itself charged to the budget, so at 30 ms a record the yields + // land about 121 ms apart. Driven rather than divided out — dividing it out + // is how the comment came to claim 29 for the 3 s case, which is 24. + const Pass wide = runWalk(table(4000, true), true, 0, kFastRecordMs, + Rns::kWalkYieldMs, 1, 6000); + TEST_ASSERT_TRUE(wide.ranOut); + TEST_ASSERT_EQUAL_size_t(49, wide.yields); + const Pass narrow = runWalk(table(4000, true), true, 0, kFastRecordMs, + Rns::kWalkYieldMs, 1, 3000); + TEST_ASSERT_TRUE(narrow.ranOut); + TEST_ASSERT_EQUAL_size_t(24, narrow.yields); + // At the shipped budget it is three, and that is the figure the header quotes. + const Pass shipped = runWalk(table(4000, true), true, 0, kFastRecordMs); + TEST_ASSERT_EQUAL_size_t(3, shipped.yields); +} + +// --------------------------------------------------------------------------- +// One position at a time +// --------------------------------------------------------------------------- + +void test_the_budget_stops_a_pass_while_rows_are_still_filling() { + // The defect, at its smallest. The rows are nowhere near full and no sweep is + // running, so every earlier shape of this rule returned a row here: the check + // was `if (!wantRow && elapsed >= budget)`. + TEST_ASSERT_TRUE(Rns::WalkStep::Row == + Rns::walkStep(at(1, false, 1, 0, Rns::kWalkBudgetMs - 1))); + TEST_ASSERT_TRUE(Rns::WalkStep::StopBudget == + Rns::walkStep(at(1, false, 1, 0, Rns::kWalkBudgetMs))); + // And with a sweep running as well, which is the case the old guard did cover + // — but only after the rows had filled. + TEST_ASSERT_TRUE(Rns::WalkStep::StopBudget == + Rns::walkStep(at(1, true, 1, 0, Rns::kWalkBudgetMs))); +} + +void test_the_budget_applies_on_the_skip_path() { + // Rows full, sweeping, and behind the cursor: the position is stepped over + // for free while there is time... + TEST_ASSERT_TRUE(Rns::WalkStep::Skip == + Rns::walkStep(at(kRowCap, true, 3, 10, Rns::kWalkBudgetMs - 1))); + // ...and the pass ends there once there is not. The skip used to `continue` + // before the budget was ever consulted, so a walk with a long prefix to step + // over could not be stopped on that path at all. + TEST_ASSERT_TRUE(Rns::WalkStep::StopBudget == + Rns::walkStep(at(kRowCap, true, 3, 10, Rns::kWalkBudgetMs))); +} + +void test_rows_full_and_no_sweep_is_a_finish_not_a_budget_stop() { + TEST_ASSERT_TRUE(Rns::WalkStep::StopRowsFull == + Rns::walkStep(at(kRowCap, false, 9, 0, 0))); + // Even with the budget spent, because the difference is not cosmetic: only a + // budget stop writes the sweep cursor, and a pass that finished what it came + // for has not run out of anything. + TEST_ASSERT_TRUE(Rns::WalkStep::StopRowsFull == + Rns::walkStep(at(kRowCap, false, 9, 0, Rns::kWalkBudgetMs * 4))); +} + +void test_a_position_neither_half_wants_is_stepped_over() { + // Rows full, sweep running, but the cursor is ahead: nothing to do here and + // nothing to pay for it. + TEST_ASSERT_TRUE(Rns::WalkStep::Skip == Rns::walkStep(at(kRowCap, true, 0, 5, 0))); + TEST_ASSERT_TRUE(Rns::WalkStep::Skip == Rns::walkStep(at(kRowCap, true, 4, 5, 0))); + // At the cursor it becomes the sweep's business. + TEST_ASSERT_TRUE(Rns::WalkStep::Examine == Rns::walkStep(at(kRowCap, true, 5, 5, 0))); + TEST_ASSERT_TRUE(Rns::WalkStep::Examine == Rns::walkStep(at(kRowCap, true, 6, 5, 0))); +} + +void test_a_row_is_read_whether_or_not_the_sweep_wants_it() { + // While the rows are unfilled the record is read regardless of the cursor: + // it is being paid for anyway, so the sweep gets it for nothing. + TEST_ASSERT_TRUE(Rns::WalkStep::Row == Rns::walkStep(at(0, true, 0, 40, 0))); + TEST_ASSERT_TRUE(Rns::WalkStep::Row == Rns::walkStep(at(0, false, 0, 0, 0))); +} + +// --------------------------------------------------------------------------- +// Whole passes +// --------------------------------------------------------------------------- + +void test_a_slow_table_is_bounded_by_the_budget_in_the_row_half() { + // 200 live entries at 30 ms each is 6 s of reading — the walk that tripped + // the watchdog. The rows never fill, so the old guard never consulted the + // budget; this one ends the pass inside it. + const Pass r = runWalk(table(200, true), false, 0, kFastRecordMs); + TEST_ASSERT_TRUE(r.ranOut); + TEST_ASSERT_FALSE(r.rowsFull); + TEST_ASSERT_LESS_THAN_size_t(kRowCap, r.rows); // a prefix, not a full list + // The budget is checked between records, so a pass overruns by at most the + // record in hand plus the tick a yield costs. + TEST_ASSERT_GREATER_OR_EQUAL_UINT32(Rns::kWalkBudgetMs, r.elapsedMs); + TEST_ASSERT_LESS_THAN_UINT32(Rns::kWalkBudgetMs + kFastRecordMs + 1 + 1, r.elapsedMs); +} + +void test_a_table_of_dead_entries_is_bounded_too() { + // The case the old guard could not stop at all: an entry with no receiving + // interface is read off the filesystem and fills no row, so `wantRow` stayed + // true to the end of the table and every position was dereferenced with no + // check. This is exactly the table the sweep exists to clean up. + const Pass r = runWalk(table(200, false), true, 0, kFastRecordMs); + TEST_ASSERT_TRUE(r.ranOut); + TEST_ASSERT_EQUAL_size_t(0, r.rows); + TEST_ASSERT_LESS_THAN_size_t(200, r.reads); + TEST_ASSERT_EQUAL_size_t(r.reads, r.swept.size()); // every one read was swept + TEST_ASSERT_LESS_THAN_UINT32(Rns::kWalkBudgetMs + kFastRecordMs + 1 + 1, r.elapsedMs); +} + +void test_a_small_table_finishes_inside_the_budget_and_closes_the_cycle() { + // Nothing here should behave differently from before the fix: a table the + // walk can finish is finished, the cycle closes, and no yield is reached. + const Pass r = runWalk(table(3, true), true, 0, kFastRecordMs); + TEST_ASSERT_FALSE(r.ranOut); + TEST_ASSERT_EQUAL_size_t(3, r.reads); + TEST_ASSERT_EQUAL_size_t(3, r.rows); + TEST_ASSERT_EQUAL_size_t(0, r.yields); // 90 ms of walk, cadence is 100 + TEST_ASSERT_EQUAL_size_t(0, Rns::nextCursor(0, r.stoppedAt, r.ranOut)); +} + +void test_a_pass_stops_on_rows_full_when_nothing_else_needs_the_rest() { + // No sweep due: the walk collects its cap and stops, having read exactly the + // rows and not one record more. + const Pass r = runWalk(table(kRowCap * 3, true), false, 0, 0); + TEST_ASSERT_TRUE(r.rowsFull); + TEST_ASSERT_FALSE(r.ranOut); + TEST_ASSERT_EQUAL_size_t(kRowCap, r.rows); + TEST_ASSERT_EQUAL_size_t(kRowCap, r.reads); + TEST_ASSERT_EQUAL_size_t(0, r.skipped); + TEST_ASSERT_EQUAL_size_t(kRowCap, r.stoppedAt); +} + +void test_a_sweeping_pass_steps_over_the_prefix_it_has_already_examined() { + // Rows fill at the front, the cursor is past them, and the positions in + // between cost nothing. Free records so the budget is not what ends it. + const size_t cursor = kRowCap + 10; + const Pass r = runWalk(table(kRowCap + 20, true), true, cursor, 0); + TEST_ASSERT_FALSE(r.ranOut); + TEST_ASSERT_EQUAL_size_t(kRowCap, r.rows); + TEST_ASSERT_EQUAL_size_t(10, r.skipped); // kRowCap .. cursor-1 + TEST_ASSERT_EQUAL_size_t(kRowCap + 10, r.reads); // the rows, then the tail +} + +// --------------------------------------------------------------------------- +// The sweep cursor +// --------------------------------------------------------------------------- + +void test_the_sweep_cursor_never_moves_backwards() { + // The hazard the budget's new reach creates. Rows are collected from the + // front of the table on every pass, so a budget stop in the row half is at a + // position *behind* a cursor that has already worked its way down the table. + TEST_ASSERT_EQUAL_size_t(60, Rns::nextCursor(60, 13, true)); + TEST_ASSERT_EQUAL_size_t(60, Rns::nextCursor(60, 0, true)); + TEST_ASSERT_EQUAL_size_t(60, Rns::nextCursor(60, 59, true)); + // Forwards it does move. + TEST_ASSERT_EQUAL_size_t(61, Rns::nextCursor(60, 61, true)); + TEST_ASSERT_EQUAL_size_t(60, Rns::nextCursor(60, 60, true)); + // And reaching the end of the table closes the cycle whatever the position. + TEST_ASSERT_EQUAL_size_t(0, Rns::nextCursor(60, 999, false)); + TEST_ASSERT_EQUAL_size_t(0, Rns::nextCursor(60, 0, false)); +} + +void test_a_row_bound_pass_leaves_the_cursor_where_it_was() { + // End to end: a table slow enough that the budget runs out in the row half, + // with a sweep already part-way down it. Written out as the firmware writes + // it — the cursor is fed the position the walk stopped at. + // + // What reaches that state has narrowed, and the narrowing is the sweep's + // share doing its job: on the shipped regime the rows now give the budget up + // half way and the walk goes on to the cursor, so an ordinary budget stop is + // at or *past* it (the case below, and the fairness tests further down). What + // is left behind it is the regression the harness's `skipMs` models — a + // microStore whose ++ loads a record, which is what the abandoned branch ran + // on — where the pass is stopped in a step-over before it reaches anything. + const size_t cursor = 60; + const Pass r = runWalk(table(200, true), true, cursor, kFastRecordMs, + Rns::kWalkYieldMs, 1, Rns::kWalkBudgetMs, + /*rowPos=*/0, /*rowsAlready=*/0, /*skipMs=*/kFastRecordMs); + TEST_ASSERT_TRUE(r.ranOut); + TEST_ASSERT_LESS_THAN_size_t(cursor, r.stoppedAt); // stopped behind the cursor + TEST_ASSERT_EQUAL_size_t(cursor, Rns::nextCursor(cursor, r.stoppedAt, r.ranOut)); + // Which is not what an unconditional write would have done: that is the value + // on the other side of the clamp, and it is at the front of the table. + TEST_ASSERT_NOT_EQUAL_size_t(r.stoppedAt, + Rns::nextCursor(cursor, r.stoppedAt, r.ranOut)); + + // The same table with stepping free, which is what this build links: the + // pass reaches the cursor and the write-back moves it forward. Both halves + // of the rule, on one table. + const Pass now = runWalk(table(200, true), true, cursor, kFastRecordMs); + TEST_ASSERT_TRUE(now.ranOut); + TEST_ASSERT_GREATER_THAN_size_t(cursor, now.stoppedAt); + TEST_ASSERT_EQUAL_size_t(now.stoppedAt, + Rns::nextCursor(cursor, now.stoppedAt, now.ranOut)); +} + +void test_a_cursor_past_the_end_of_the_table_starts_the_cycle_again() { + // The other side of "forwards only". Positions run 0..size-1, so the size + // itself is already past the end. + TEST_ASSERT_EQUAL_size_t(0, Rns::resumeCursor(150, 100)); + TEST_ASSERT_EQUAL_size_t(0, Rns::resumeCursor(100, 100)); + TEST_ASSERT_EQUAL_size_t(0, Rns::resumeCursor(1, 0)); // an emptied table + // A cursor the table still holds is left exactly where it was. + TEST_ASSERT_EQUAL_size_t(99, Rns::resumeCursor(99, 100)); + TEST_ASSERT_EQUAL_size_t(0, Rns::resumeCursor(0, 100)); +} + +void test_a_cursor_left_past_a_shrunken_table_does_not_latch() { + // Reachable through the sweep's own behaviour: what it collects is capped at + // SNAPSHOT_MAX_PATHS, so one pass can drop 64 entries from under a cursor + // sitting beyond them. Here a table of 200 with the sweep at 150 is 100 long + // by the next pass. + const std::vector shrunk = table(100, true); + const size_t stranded = 150; + + // The rule itself, which is what latches it: nextCursor() only moves forwards, + // so a pass that stops anywhere below an out-of-range cursor hands that same + // out-of-range value straight back. No position in this table is at or past + // it, so no pass can stop at or past it either. + TEST_ASSERT_EQUAL_size_t(stranded, Rns::nextCursor(stranded, 0, true)); + TEST_ASSERT_EQUAL_size_t(stranded, Rns::nextCursor(stranded, 99, true)); + + // Unresumed and driven, on the stepping-costs regression: the pass stops in + // the row half with the budget spent, below the cursor, and the cycle never + // closes and the minute clock is never stamped again. + const Pass raw = runWalk(shrunk, true, stranded, kFastRecordMs, Rns::kWalkYieldMs, 1, + Rns::kWalkBudgetMs, /*rowPos=*/0, /*rowsAlready=*/0, + /*skipMs=*/kFastRecordMs); + TEST_ASSERT_TRUE(raw.ranOut); + TEST_ASSERT_LESS_THAN_size_t(stranded, raw.stoppedAt); + TEST_ASSERT_EQUAL_size_t(stranded, + Rns::nextCursor(stranded, raw.stoppedAt, raw.ranOut)); + + // With stepping free, which is what this build links, the same unresumed + // pass comes out differently and no better: the rows spend their share, every + // position below the stranded cursor is stepped over for nothing, and the + // walk falls off the end of the table having examined not one record for the + // sweep — and calls that a finished cycle. resumeCursor() is what keeps that + // unreachable, which is why it is asked before `sweeping` is decided. + const Pass off = runWalk(shrunk, true, stranded, kFastRecordMs); + TEST_ASSERT_FALSE(off.ranOut); + TEST_ASSERT_EQUAL_size_t(shrunk.size(), off.stoppedAt); + TEST_ASSERT_EQUAL_size_t(0, Rns::nextCursor(stranded, off.stoppedAt, off.ranOut)); + + // Resumed against the table as it is now, the cursor is inside it again and + // this pass advances it like any other. + const Sweep s = sweepOnce(shrunk, stranded, kFastRecordMs); + TEST_ASSERT_GREATER_THAN_size_t(0, s.cursor); + TEST_ASSERT_LESS_THAN_size_t(shrunk.size(), s.cursor); + + // And a table cheap enough to walk closes the cycle from the same stale + // start, rather than being stuck outside itself for ever. + const Sweep cheap = sweepOnce(shrunk, stranded, 0); + TEST_ASSERT_TRUE(cheap.closed); + TEST_ASSERT_EQUAL_size_t(0, cheap.cursor); +} + +// --------------------------------------------------------------------------- +// Row collection resumes across passes, and what that closed +// --------------------------------------------------------------------------- + +void test_a_row_bound_table_now_advances_the_cursor() { + // This was test_a_row_bound_table_never_advances_the_cursor, and it was + // written to be flipped. What it pinned was the cost of bounding the row + // half: rows were re-collected from the front of the table on every pass, so + // on a table slow enough to spend the budget before they filled, every pass + // read the same live prefix and stopped in the same place. Over thirty passes + // the cursor settled at 14 and never moved, the cycle closed zero times, not + // one of the hundred dead entries was ever seen, and the published list was a + // permanent fourteen-row prefix stamped fresh every five seconds. + // + // The same table, the same per-record cost, with row collection carrying a + // cursor of its own. The three assertions that were `== 0` are the three that + // matter. + std::vector live = table(200, true); + for (size_t k = 100; k < live.size(); k++) live[k] = false; + + Node n; + std::vector rowCursor; + for (int passNo = 0; passNo < 5; passNo++) { + onePass(n, live, kFastRecordMs); + rowCursor.push_back(n.rowPos); + } + // Four budget-stopped passes walking fourteen records each, and the fifth + // fills the cap and closes the cycle. The cursor moves every pass, which is + // the whole of what was broken. + TEST_ASSERT_EQUAL_size_t(14, rowCursor[0]); + TEST_ASSERT_EQUAL_size_t(28, rowCursor[1]); + TEST_ASSERT_EQUAL_size_t(42, rowCursor[2]); + TEST_ASSERT_EQUAL_size_t(56, rowCursor[3]); + TEST_ASSERT_EQUAL_size_t(0, rowCursor[4]); // wrapped: the cycle closed + TEST_ASSERT_EQUAL_size_t(1, n.rowCycles); + // And a whole list is what got published, not the fourteen-row prefix. + TEST_ASSERT_EQUAL_size_t(kRowCap, n.published); + TEST_ASSERT_TRUE(n.rowsWhole); + + // The dead half beyond the prefix is reached as well, which it never was. + // The sweep cursor used to advance only on whatever was left of a budget + // after the rows had had theirs, which on this table was 30 further passes to + // the first dead entry and 110 to a closed sweep cycle. It gets a guaranteed + // half of the budget now whenever taking none would starve it + // (Rns::rowShareSpent), and the same two figures are 5 and 18 — driven, + // beside the rest of that rule, in + // test_the_sweep_cursor_advances_on_every_sweeping_pass below. The bounds + // asserted here stay loose because the exact figures are an artefact of one + // synthetic table with nothing ever removed from it; that they are finite is + // this test's property. + size_t firstSwept = 0, firstClose = 0; + for (int passNo = 1; passNo <= 200; passNo++) { + const Pass r = onePass(n, live, kFastRecordMs); + if (!firstSwept && !r.swept.empty()) firstSwept = (size_t)passNo; + if (!firstClose && n.sweepCloses) firstClose = (size_t)passNo; + } + TEST_ASSERT_GREATER_THAN_size_t(0, firstSwept); + TEST_ASSERT_LESS_OR_EQUAL_size_t(60, firstSwept); + TEST_ASSERT_GREATER_THAN_size_t(0, firstClose); + TEST_ASSERT_LESS_OR_EQUAL_size_t(150, firstClose); + TEST_ASSERT_GREATER_THAN_size_t(0, n.sweptTotal); + TEST_ASSERT_GREATER_OR_EQUAL_size_t(1, n.sweepCloses); +} + +void test_a_pass_may_not_stop_on_budget_before_it_has_read_something() { + // The forward-progress guarantee, at one position. With the budget spent and + // nothing read yet, a position the pass would step over is still stepped + // over, and a position it wants is still read. + TEST_ASSERT_TRUE(Rns::WalkStep::Skip == + Rns::walkStep(havingReadNothing( + resumingRowsAt(at(14, false, 0, 0, Rns::kWalkBudgetMs), 14)))); + TEST_ASSERT_TRUE(Rns::WalkStep::Row == + Rns::walkStep(havingReadNothing(at(14, false, 20, 0, Rns::kWalkBudgetMs)))); + // Once one record has been dereferenced the budget bites at the next position. + TEST_ASSERT_TRUE(Rns::WalkStep::StopBudget == + Rns::walkStep(resumingRowsAt(at(14, false, 0, 0, Rns::kWalkBudgetMs), 14))); + TEST_ASSERT_TRUE(Rns::WalkStep::StopBudget == + Rns::walkStep(at(14, false, 20, 0, Rns::kWalkBudgetMs))); + // The same rule the removal is bounded by, asked directly. + TEST_ASSERT_FALSE(Rns::passMayStop(Rns::kWalkBudgetMs * 10, false)); + TEST_ASSERT_TRUE(Rns::passMayStop(Rns::kWalkBudgetMs, true)); + TEST_ASSERT_FALSE(Rns::passMayStop(Rns::kWalkBudgetMs - 1, true)); +} + +void test_a_pass_reaches_its_own_cursor_even_if_stepping_stops_being_free() { + // The structural defence, driven. Stepping costs nothing today — microStore + // loads on dereference and not on ++, which test_typed_store_iterator pins — + // so the prefix a resuming pass steps over is free. The abandoned branch + // fix/snapshot-walk-starves-loop tried a row cursor back when stepping *did* + // load, and the pass stopped inside its own prefix on every pass: "pinned at + // position 15 of 87 for ever, publishing an empty list". + // + // Here every step costs a whole record, so the budget is long gone before the + // cursor at 50 is reached. The pass still gets there, still reads one record, + // and the cursor still moves forward. + const Pass r = runWalk(table(200, true), false, 0, kFastRecordMs, Rns::kWalkYieldMs, + 1, Rns::kWalkBudgetMs, /*rowPos=*/50, /*rowsAlready=*/50, + /*skipMs=*/kFastRecordMs); + TEST_ASSERT_TRUE(r.ranOut); + TEST_ASSERT_EQUAL_size_t(50, r.skipped); + TEST_ASSERT_EQUAL_size_t(1, r.reads); // exactly one, beyond the cursor + TEST_ASSERT_EQUAL_size_t(1, r.added); + TEST_ASSERT_EQUAL_size_t(51, r.stoppedAt); + TEST_ASSERT_GREATER_THAN_size_t(50, Rns::nextCursor(50, r.stoppedAt, r.ranOut)); + // The price of the guarantee: the pass costs the prefix plus one record + // rather than the budget. That is only ever paid if the dependency regresses, + // and it is the right way round — a bound that could stall the node for ever + // is worse than one that can be overrun. + TEST_ASSERT_GREATER_THAN_UINT32(Rns::kWalkBudgetMs, r.elapsedMs); +} + +void test_a_resuming_pass_does_not_end_at_its_own_front_door() { + // The second thing the abandoned branch got wrong, and it published 19 rows + // on a node holding 87. With a row cursor, `!wantRow` is true at position 0 on + // every resuming pass — it wants no row *there*. Ending the pass on that, and + // treating the short list as finished, is the bug; the end condition is the + // rows being full. + const Rns::WalkState front = resumingRowsAt(at(14, false, 0, 0, 0), 14); + TEST_ASSERT_TRUE(Rns::WalkStep::Skip == Rns::walkStep(front)); + TEST_ASSERT_FALSE(Rns::WalkStep::StopRowsFull == Rns::walkStep(front)); + // Full is full, though, and that is still a clean finish. + TEST_ASSERT_TRUE(Rns::WalkStep::StopRowsFull == + Rns::walkStep(resumingRowsAt(at(kRowCap, false, 0, 0, 0), 14))); + + // End to end: a pass resuming at 14 on a table with no sweep due walks past + // its prefix and collects the next fourteen rather than stopping at nothing. + const Pass r = runWalk(table(200, true), false, 0, kFastRecordMs, Rns::kWalkYieldMs, + 1, Rns::kWalkBudgetMs, /*rowPos=*/14, /*rowsAlready=*/14); + TEST_ASSERT_EQUAL_size_t(14, r.skipped); + TEST_ASSERT_EQUAL_size_t(14, r.added); + TEST_ASSERT_EQUAL_size_t(28, r.rows); + TEST_ASSERT_EQUAL_size_t(28, r.stoppedAt); +} + +void test_only_a_whole_list_is_published() { + // A budget-stopped pass has a valid prefix and nothing more. What readers see + // stays at the last whole list rather than becoming four paths on a node + // holding eighty. + TEST_ASSERT_FALSE(Rns::rowCycleDone(14, kRowCap, true)); // stopped, not full + TEST_ASSERT_TRUE(Rns::rowCycleDone(kRowCap, kRowCap, true)); // the cap filled + TEST_ASSERT_TRUE(Rns::rowCycleDone(3, kRowCap, false)); // walked to the end + TEST_ASSERT_TRUE(Rns::rowCycleDone(0, kRowCap, false)); // an empty table + + Node n; + const std::vector live = table(200, true); + // Nothing published until the fifth pass closes the cycle. + for (int k = 0; k < 4; k++) { + onePass(n, live, kFastRecordMs, /*sweeping=*/false); + TEST_ASSERT_EQUAL_size_t(0, n.published); + TEST_ASSERT_FALSE(n.rowsWhole); + TEST_ASSERT_GREATER_THAN_size_t(0, n.staged); // but the prefix is kept + } + onePass(n, live, kFastRecordMs, /*sweeping=*/false); + TEST_ASSERT_EQUAL_size_t(kRowCap, n.published); + TEST_ASSERT_TRUE(n.rowsWhole); + // And a table the walk finishes in one pass publishes on that pass, which is + // every ordinary node: no list is delayed by this. + Node small; + onePass(small, table(3, true), kFastRecordMs, /*sweeping=*/false); + TEST_ASSERT_EQUAL_size_t(3, small.published); + TEST_ASSERT_TRUE(small.rowsWhole); + TEST_ASSERT_EQUAL_size_t(0, small.rowPos); +} + +void test_a_cycle_over_an_empty_table_does_not_answer_for_a_full_one() { + // The transition nothing exercised, and it is every node's first boot rather + // than a corner: the table is empty until something is announced, so the + // first pass walks it to the end and closes a cycle over nothing. A flag that + // latched on that first close then said "whole" for the rest of the run, and + // the empty list it was published with went on being called a whole answer + // after the node had learned two hundred paths — stillReadingPaths() false + // beside a count in the hundreds, which every surface draws as "nothing + // announced yet". + Node n; + onePass(n, table(0, true), kFastRecordMs, /*sweeping=*/false); + TEST_ASSERT_EQUAL_size_t(1, n.rowCycles); + TEST_ASSERT_EQUAL_size_t(0, n.published); + TEST_ASSERT_TRUE(n.rowsWhole); // an empty table, wholly read + // And that is the right answer for it: with no paths in the table there is + // nothing to be still reading, which is what the second half of the predicate + // is for. + TEST_ASSERT_FALSE(stillReading(n, 0)); + + // Then the node learns two hundred paths. No pass walks that in one — fourteen + // records fit in the budget at 30 ms a record — so the cycle takes five, and + // for four of them what readers hold is still the empty list from boot. + const std::vector grown = table(200, true); + for (int k = 0; k < 4; k++) { + onePass(n, grown, kFastRecordMs, /*sweeping=*/false); + TEST_ASSERT_EQUAL_size_t(0, n.published); + TEST_ASSERT_EQUAL_size_t(1, n.rowCycles); // none has closed since + TEST_ASSERT_FALSE(n.rowsWhole); // the latch said true here + TEST_ASSERT_TRUE(stillReading(n, grown.size())); + } + // The fifth closes the cycle at the cap and publishes it. + onePass(n, grown, kFastRecordMs, /*sweeping=*/false); + TEST_ASSERT_EQUAL_size_t(2, n.rowCycles); + TEST_ASSERT_EQUAL_size_t(kRowCap, n.published); + TEST_ASSERT_TRUE(n.rowsWhole); + TEST_ASSERT_FALSE(stillReading(n, grown.size())); +} + +void test_a_node_that_has_read_its_table_does_not_flap_between_the_two() { + // The other half of the rule, and the one that decides whether it is usable: + // a node that has read its table must not alternate between whole and partial + // on every pass, or the reading means nothing on any surface that draws it. + // + // Two nodes, because there are two ways a cycle closes. + // + // A table the walk gets round inside one pass closes a cycle every pass, so + // the flag never leaves true — this is the ordinary node. + Node small; + const std::vector few = table(6, true); + for (int k = 0; k < 6; k++) { + onePass(small, few, kFastRecordMs, /*sweeping=*/false); + TEST_ASSERT_TRUE(small.rowsWhole); + TEST_ASSERT_FALSE(stillReading(small, few.size())); + TEST_ASSERT_EQUAL_size_t(6, small.published); + } + + // And a table past the cap, which is the case a per-cycle rule could ruin: + // its cycles take five passes each, so a rule that went partial whenever a + // cycle was under way would read "still reading" four passes in five for the + // life of the node. It does not, because such a cycle closes at the *cap* — + // sixty-four rows is the most any cycle can publish, so a bigger table cannot + // make that list less complete than it was. + Node big; + const std::vector many = table(200, true); + for (int k = 0; k < 5; k++) onePass(big, many, kFastRecordMs, /*sweeping=*/false); + TEST_ASSERT_EQUAL_size_t(kRowCap, big.published); + TEST_ASSERT_TRUE(big.rowsWhole); + const std::vector bigger = table(400, true); + for (int k = 0; k < 4; k++) { // four passes of the next cycle, mid-cycle + onePass(big, bigger, kFastRecordMs, /*sweeping=*/false); + TEST_ASSERT_EQUAL_size_t(kRowCap, big.published); + TEST_ASSERT_TRUE(big.rowsWhole); + TEST_ASSERT_FALSE(stillReading(big, bigger.size())); + } + + // The rule on its own, all four clauses of it. + Rns::RowCycle none; + TEST_ASSERT_FALSE(Rns::rowsWhole(none, 0)); // nothing has closed yet + TEST_ASSERT_FALSE(Rns::rowsWhole(none, 200)); + Rns::RowCycle closed; + Rns::closeRowCycle(closed, 10, kRowCap, 10); // ten rows over a ten-row table + TEST_ASSERT_TRUE(Rns::rowsWhole(closed, 10)); + TEST_ASSERT_TRUE(Rns::rowsWhole(closed, 4)); // a table that has since shrunk + TEST_ASSERT_FALSE(Rns::rowsWhole(closed, 11)); // one it has since grown past + Rns::RowCycle capped; + Rns::closeRowCycle(capped, kRowCap, kRowCap, 200); + TEST_ASSERT_TRUE(Rns::rowsWhole(capped, 200)); + TEST_ASSERT_TRUE(Rns::rowsWhole(capped, 5000)); // the cap ended it, not the table + // A cycle that walked a table of dead entries to the end publishes a short + // list and is whole, which is what it is: the cycle did cover the table, and + // those entries are the sweep's to remove rather than rows nobody has read. + Rns::RowCycle sparse; + Rns::closeRowCycle(sparse, 0, kRowCap, 40); + TEST_ASSERT_TRUE(Rns::rowsWhole(sparse, 40)); +} + +// --------------------------------------------------------------------------- +// A pass that threw, and the removal's clock +// --------------------------------------------------------------------------- + +void test_a_pass_that_threw_starts_the_row_cycle_again() { + // The newest piece of bookkeeping in refreshSnapshots() and the one with no + // test: the flag that says whether the last pass got as far as writing its + // row cursor back. The staging list and the cursor have to agree, and the one + // thing that parts them is the pass throwing between the last row it pushed + // and the write-back — Diag::guard catches that, and reading a record under + // memory pressure can cause it. + const std::vector live = table(200, true); + Node n; + + // Two clean passes: fourteen rows, then twenty-eight, cursor following. + onePass(n, live, kFastRecordMs, /*sweeping=*/false); + TEST_ASSERT_EQUAL_size_t(14, n.rowPos); + TEST_ASSERT_EQUAL_size_t(14, n.staged); + TEST_ASSERT_TRUE(n.rowPassClean); + + // The third throws after the walk. Its rows are in the list — the vector is + // the caller's own and the throw does not unwind it — and the cursor was + // never written, so it still points at 14 with 28 rows collected. + const Pass thrown = onePass(n, live, kFastRecordMs, /*sweeping=*/false, + /*skipMs=*/0, /*aborts=*/true); + TEST_ASSERT_EQUAL_size_t(28, thrown.rows); + TEST_ASSERT_EQUAL_size_t(28, n.staged); + TEST_ASSERT_EQUAL_size_t(14, n.rowPos); + TEST_ASSERT_FALSE(n.rowPassClean); + + // That disagreement is exactly what the rule is asked about. Resumed as an + // ordinary cursor it would say 14 — and the next pass would then collect + // positions 14..27 a second time into a list that already holds them. + TEST_ASSERT_EQUAL_size_t(14, Rns::resumeCursor(n.rowPos, live.size())); + TEST_ASSERT_EQUAL_size_t(0, Rns::resumeRowCursor(n.rowPos, live.size(), n.rowPassClean)); + + // So the next pass starts at the front with an empty list: nothing stepped + // over, fourteen rows collected, fourteen in the list rather than forty-two. + const Pass again = onePass(n, live, kFastRecordMs, /*sweeping=*/false); + TEST_ASSERT_EQUAL_size_t(0, again.skipped); + TEST_ASSERT_EQUAL_size_t(14, again.added); + TEST_ASSERT_EQUAL_size_t(14, again.rows); + TEST_ASSERT_EQUAL_size_t(14, n.rowPos); + TEST_ASSERT_TRUE(n.rowPassClean); + + // And the cycle that follows it closes on a whole list of exactly the cap, + // not on a list padded out by the rows the throw left behind. + for (int k = 0; k < 4; k++) onePass(n, live, kFastRecordMs, /*sweeping=*/false); + TEST_ASSERT_EQUAL_size_t(kRowCap, n.published); + TEST_ASSERT_EQUAL_size_t(1, n.rowCycles); + + // The rule on its own, both conditions of it. A clean pass keeps a cursor the + // table still holds; an unclean one starts again whatever the cursor said; + // and a cursor the table has shrunk past starts again either way. + TEST_ASSERT_EQUAL_size_t(14, Rns::resumeRowCursor(14, 200, true)); + TEST_ASSERT_EQUAL_size_t(0, Rns::resumeRowCursor(14, 200, false)); + TEST_ASSERT_EQUAL_size_t(0, Rns::resumeRowCursor(150, 100, true)); + TEST_ASSERT_EQUAL_size_t(0, Rns::resumeRowCursor(150, 100, false)); +} + +void test_the_removal_is_bounded_by_the_walks_clock_and_not_a_fresh_one() { + // The removal at the end of a pass is bounded by + // passMayStop(millis() - walkStartMs, ...) — the walk's start, so that the + // walk and the removal together are one budget rather than two. The rule was + // pinned; the sharing was not, and a removeStartMs of its own would be a + // silent second budget. + // + // 20 ms a removal is this harness's own figure and divides the budget by + // twenty, so what each case spends is readable rather than asserted blind. + const uint32_t kRemoveMs = 20; + + // A pass whose walk spent the whole budget still removes one entry. Not + // none: passMayStop() may not stop a pass that has done nothing, which is + // the same forward-progress rule the walk is under. + const Removal spent = runRemoval(kRowCap, Rns::kWalkBudgetMs, kRemoveMs); + TEST_ASSERT_EQUAL_size_t(1, spent.attempts); + TEST_ASSERT_EQUAL_size_t(1, spent.dropped); + TEST_ASSERT_TRUE(spent.stopped); + + // A pass whose walk finished early removes as many as the rest of the budget + // holds: 400 / 20. + const Removal early = runRemoval(kRowCap, 0, kRemoveMs); + TEST_ASSERT_EQUAL_size_t(20, early.dropped); + TEST_ASSERT_TRUE(early.stopped); + + // And the sharing itself, which is the assertion a fresh clock would fail. + // The same removal after a walk that used 300 of the 400 gets what is left, + // five entries — where a clock of its own would give it the full twenty + // again and let one pass spend 700 ms. + const Removal shared = runRemoval(kRowCap, 300, kRemoveMs); + TEST_ASSERT_EQUAL_size_t(5, shared.dropped); + TEST_ASSERT_EQUAL_UINT32(400, shared.elapsedMs); // measured from the walk's start + TEST_ASSERT_EQUAL_size_t(20, early.dropped); // what a fresh clock would allow + TEST_ASSERT_LESS_THAN_size_t(early.dropped, shared.dropped); + + // Walk plus removal is one budget and the item in hand, at every split of it. + for (uint32_t walked = 0; walked <= Rns::kWalkBudgetMs; walked += 25) { + const Removal r = runRemoval(kRowCap, walked, kRemoveMs); + TEST_ASSERT_GREATER_OR_EQUAL_size_t(1, r.attempts); + TEST_ASSERT_LESS_OR_EQUAL_UINT32(Rns::kWalkBudgetMs + kRemoveMs, r.elapsedMs); + } + + // Attempts and not successes. Every key already gone is a `stale` full of + // remove_path()s that return false without touching flash, so the clock does + // not move: answered with successes the loop would run all 64 with nothing + // watching it, which is the count-bounded loop this milestone exists to kill. + const Removal gone = runRemoval(kRowCap, Rns::kWalkBudgetMs, kRemoveMs, + Rns::kWalkBudgetMs, /*allGone=*/true); + TEST_ASSERT_EQUAL_size_t(0, gone.dropped); + TEST_ASSERT_EQUAL_size_t(1, gone.attempts); + TEST_ASSERT_TRUE(gone.stopped); +} + +// --------------------------------------------------------------------------- +// The sweep's share of the budget +// --------------------------------------------------------------------------- + +void test_the_rows_give_the_sweep_half_the_budget_when_it_is_ahead() { + // The share, at one position. Half the budget, and only where taking it all + // would leave the sweep nothing: the sweep's cursor ahead of the row cursor. + TEST_ASSERT_EQUAL_UINT32(Rns::kWalkBudgetMs / 2, Rns::rowShareMs(Rns::kWalkBudgetMs)); + TEST_ASSERT_EQUAL_UINT32(200, Rns::rowShareMs(Rns::kWalkBudgetMs)); + + // Under the share, at the front of the table with the sweep at 70: still a + // row. + TEST_ASSERT_TRUE(Rns::WalkStep::Row == + Rns::walkStep(at(10, true, 0, 70, Rns::rowShareMs(Rns::kWalkBudgetMs) - 1))); + // Over it, the same position is stepped over for nothing — the sweep does not + // want position 0 either — which is what lets the walk reach 70 at all. + const Rns::WalkState spent = at(10, true, 0, 70, Rns::rowShareMs(Rns::kWalkBudgetMs)); + TEST_ASSERT_TRUE(Rns::WalkStep::Skip == Rns::walkStep(spent)); + TEST_ASSERT_TRUE(Rns::rowShareSpent(spent)); + TEST_ASSERT_TRUE(Rns::rowShareDenied(spent)); + // And the position the sweep does want is read for it. + TEST_ASSERT_TRUE(Rns::WalkStep::Examine == + Rns::walkStep(at(10, true, 70, 70, Rns::rowShareMs(Rns::kWalkBudgetMs)))); + + // Not while the two cursors travel together, which is most of a cycle: the + // same reads serve both halves there, so taking half the budget off the rows + // would slow both and fix nothing. + const Rns::WalkState level = at(10, true, 0, 0, Rns::kWalkBudgetMs - 1); + TEST_ASSERT_FALSE(Rns::rowShareSpent(level)); + TEST_ASSERT_TRUE(Rns::WalkStep::Row == Rns::walkStep(level)); + // Nor with the sweep behind the rows, where the walk reaches its cursor first + // anyway. + TEST_ASSERT_FALSE(Rns::rowShareSpent(resumingRowsAt(at(10, true, 80, 40, Rns::kWalkBudgetMs - 1), 60))); + // Nor on a pass with no sweep running at all, which is eleven passes in + // twelve: the rows get the whole budget, as they always did. + TEST_ASSERT_FALSE(Rns::rowShareSpent(at(10, false, 0, 70, Rns::kWalkBudgetMs - 1))); + // And never once the rows are full — there is nothing left to deny. + TEST_ASSERT_FALSE(Rns::rowShareDenied(at(kRowCap, true, 0, 70, Rns::kWalkBudgetMs - 1))); + + // End to end, on the table the rest of this suite uses. Seven rows and then + // the walk hands over: sixty-three positions stepped over for nothing and + // seven records read at the sweep's cursor, out of the same fourteen reads a + // pass has always had at this per-record cost. + const Pass r = runWalk(table(200, true), true, 70, kFastRecordMs); + TEST_ASSERT_EQUAL_size_t(7, r.rows); + TEST_ASSERT_EQUAL_size_t(14, r.reads); + TEST_ASSERT_EQUAL_size_t(63, r.skipped); // 7..69, none of them dereferenced + TEST_ASSERT_EQUAL_size_t(77, r.stoppedAt); // the sweep got to 77 + TEST_ASSERT_EQUAL_size_t(7, r.rowStoppedAt); // the rows got to 7 + TEST_ASSERT_TRUE(r.rowsCut); + TEST_ASSERT_TRUE(r.ranOut); + // Without the share this pass read fourteen rows and stopped at 14, and the + // sweep's cursor at 70 was not reached at all — which is the whole of what + // follows. +} + +void test_the_sweep_cursor_advances_on_every_sweeping_pass() { + // The guarantee the share exists for, driven over two hundred passes of the + // table this suite uses — two hundred entries, the first hundred live. + // + // Before it, the sweep advanced only in the one pass per row cycle where the + // row cursor caught up to it: the cursor sat at 70 for five passes, then 76 + // for five, then 82, and the first dead entry was reached on pass 35 with the + // cycle closing on pass 115. Those are measurements of the pre-share rules, + // which this tree no longer has — narrative here and in SnapshotWalk.h, and + // not re-derivable from anything below; only the with-share figures are + // asserted. With it, the cursor moves on every pass, the + // first dead entry comes on pass 10 and the cycle closes on pass 23 — and + // goes round eight times in two hundred passes rather than once. + std::vector live = table(200, true); + for (size_t k = 100; k < live.size(); k++) live[k] = false; + + // The three exact figures below are exact about one arithmetic: at 30 ms a + // record a pass gets fourteen reads, seven of them rows before the share + // hands the rest to the sweep. Stated here so that a retune of + // kWalkBudgetMs, kWalkYieldMs or SNAPSHOT_MAX_PATHS fails on the premise — + // which says what moved — rather than three lines further down on a bare + // "expected 10, was 12". + const Pass shape = runWalk(live, true, 70, kFastRecordMs); + TEST_ASSERT_EQUAL_size_t_MESSAGE(14, shape.reads, + "reads per pass at 30 ms a record moved; the pass counts below follow from it"); + TEST_ASSERT_EQUAL_size_t_MESSAGE(7, shape.rows, + "rows before the share hands over moved; the pass counts below follow from it"); + + Node n; + size_t firstSwept = 0, firstClose = 0, stalls = 0; + for (size_t passNo = 1; passNo <= 200; passNo++) { + const size_t before = n.sweepPos; + const Pass r = onePass(n, live, kFastRecordMs); + // A sweeping pass either moved the cursor forward or closed the cycle and + // put it back to the front. Standing still is the failure. + if (n.sweepPos != 0 && n.sweepPos <= before && passNo > 1) stalls++; + if (!firstSwept && !r.swept.empty()) firstSwept = passNo; + if (!firstClose && n.sweepCloses) firstClose = passNo; + } + TEST_ASSERT_EQUAL_size_t(0, stalls); + TEST_ASSERT_EQUAL_size_t_MESSAGE(10, firstSwept, + "the first dead entry is reached on a different pass now (was 35 without the share)"); + TEST_ASSERT_EQUAL_size_t_MESSAGE(23, firstClose, + "the first sweep cycle closes on a different pass now (was 115 without the share)"); + TEST_ASSERT_EQUAL_size_t_MESSAGE(8, n.sweepCloses, + "cycles closed in 200 passes moved (was 1 without the share)"); + // The rows are not starved for it: they still go all the way round, and every + // list published is a whole one. + TEST_ASSERT_GREATER_THAN_size_t(0, n.rowCycles); + TEST_ASSERT_EQUAL_size_t(kRowCap, n.published); + TEST_ASSERT_TRUE(n.rowsWhole); +} + +void test_the_row_cap_knife_edge_no_longer_stalls_the_sweep() { + // The pathological case, which is not exotic: where reads per pass divide + // SNAPSHOT_MAX_PATHS exactly, the row half fills the cap precisely as the + // budget runs out, so the walk stopped at the cap on every pass and the sweep + // cursor never moved past it at all. At 25 ms a record a pass reads exactly + // sixteen, and 64 / 16 = 4. + TEST_ASSERT_EQUAL_size_t(16, runWalk(table(4000, true), false, 0, 25).reads); + TEST_ASSERT_EQUAL_size_t(0, kRowCap % 16); + + // Before the share the cursor went 16, 32, 48, 64 and then stayed at 64 for + // ever: no dead entry beyond it was ever found and no cycle ever closed. It + // took a change in the per-record cost to break out, which is a cleanup that + // depends on the filesystem jittering. + Node n; + const std::vector live = table(200, true); + std::vector cursor; + size_t firstClose = 0; + for (size_t passNo = 1; passNo <= 40; passNo++) { + onePass(n, live, 25); + cursor.push_back(n.sweepPos); + if (!firstClose && n.sweepCloses) firstClose = passNo; + } + TEST_ASSERT_EQUAL_size_t(16, cursor[0]); + TEST_ASSERT_EQUAL_size_t(32, cursor[1]); + TEST_ASSERT_EQUAL_size_t(48, cursor[2]); + TEST_ASSERT_EQUAL_size_t(64, cursor[3]); + // The knife edge itself: the pass that used to stop at the cap and stay + // there. It goes past it by the records the sweep's half of the budget buys + // — 200 ms at 25 ms each is eight positions — which is what the share is. + TEST_ASSERT_EQUAL_size_t_MESSAGE(kRowCap + Rns::rowShareMs(Rns::kWalkBudgetMs) / 25, + cursor[4], "the pass that broke the knife edge moved; was 64, and 64 for ever after"); + TEST_ASSERT_EQUAL_size_t(80, cursor[5]); + TEST_ASSERT_EQUAL_size_t_MESSAGE(21, firstClose, + "the pass the cycle first closes on moved; it never closed at all before the share"); + TEST_ASSERT_GREATER_OR_EQUAL_size_t(1, n.sweepCloses); +} + +void test_a_cycle_the_share_cut_short_is_kept_as_a_prefix() { + // The hazard the share creates, and the reason the row half carries its own + // "was it cut short" rather than borrowing the walk's. A pass that hands over + // to the sweep and then runs off the end of the table has *not* run out of + // budget — and a list judged on that alone would be published as a whole + // cycle. Here that is seven rows on a table of seventy-five. + const Pass r = runWalk(table(75, true), true, 70, kFastRecordMs); + TEST_ASSERT_FALSE(r.ranOut); // it reached the end of the table + TEST_ASSERT_TRUE(r.rowsCut); // but the rows did not + TEST_ASSERT_EQUAL_size_t(7, r.rows); + TEST_ASSERT_EQUAL_size_t(7, r.rowStoppedAt); + // Judged on the walk alone, this publishes a seven-row list as complete. + TEST_ASSERT_TRUE(Rns::rowCycleDone(r.rows, kRowCap, r.ranOut)); + // Judged on the row half's own answer, it is the prefix it is. + TEST_ASSERT_FALSE(Rns::rowCycleDone(r.rows, kRowCap, r.ranOut || r.rowsCut)); + // And the row cursor follows the rows rather than the walk: 7, not 75, which + // would have skipped everything between them for a whole cycle. + TEST_ASSERT_EQUAL_size_t(7, Rns::nextCursor(0, r.rowStoppedAt, r.ranOut || r.rowsCut)); + TEST_ASSERT_EQUAL_size_t(0, Rns::nextCursor(0, r.stoppedAt, r.ranOut)); + + // The sweep, on the same pass, did reach the end and its cycle did close. + // The two halves answer separately, which is the point. + TEST_ASSERT_EQUAL_size_t(75, r.stoppedAt); +} + +void test_a_record_over_the_row_share_can_still_deny_the_sweep() { + // Where the share's guarantee stops, which is not where the header used to + // say it did. "A single record that costs the whole budget" is the uniform + // reading; the boundary for mixed costs is half of it, and mixed is the real + // case — one store was measured at 93-162 ms a record, not at a constant + // (FileStore.h). + // 200 ms, pinned against the budget by + // test_the_rows_give_the_sweep_half_the_budget_when_it_is_ahead above. + const uint32_t share = Rns::rowShareMs(Rns::kWalkBudgetMs); + + // Uniform, and well over the share: the sweep is served anyway. The first + // record spends the whole share by itself, so the walk hands over at 250 ms + // and reaches the cursor at 70 with a third of the budget still in hand. + const Pass uniform = runWalk(table(200, true), true, 70, 250); + TEST_ASSERT_EQUAL_size_t(2, uniform.reads); // one row, then the sweep's own + TEST_ASSERT_EQUAL_size_t(71, uniform.stoppedAt); + TEST_ASSERT_EQUAL_size_t(71, Rns::nextCursor(70, uniform.stoppedAt, uniform.ranOut)); + + // The same 250 ms among cheap ones, which is the case that fails: sixty-three + // 3 ms records creep the clock to just under the share, the sixty-fourth + // costs 250, and the pass is past the budget before it reaches position 70. + // The cursor stands still for this pass — the one thing the share exists to + // prevent, and it takes half the cost the uniform reading asks for. + std::vector costs(kRowCap, 3); + costs[kRowCap - 1] = 250; + const Pass mixed = runWalk(table(200, true), true, 70, 3, Rns::kWalkYieldMs, 1, + Rns::kWalkBudgetMs, 0, 0, 0, &costs); + TEST_ASSERT_TRUE_MESSAGE(mixed.elapsedMs - 250 < share, + "the cheap records no longer land the pass just under the share; retune them"); + TEST_ASSERT_TRUE(mixed.ranOut); + TEST_ASSERT_EQUAL_size_t(kRowCap, mixed.stoppedAt); // short of the cursor at 70 + TEST_ASSERT_EQUAL_size_t(70, Rns::nextCursor(70, mixed.stoppedAt, mixed.ranOut)); + TEST_ASSERT_GREATER_OR_EQUAL_UINT32(Rns::kWalkBudgetMs, mixed.elapsedMs); + + // The turning point as the rule rather than as a scenario. The last position + // the rows are served at is the last one under the share, so from there a + // record of exactly the share leaves the pass one millisecond inside the + // budget and one millisecond more does not. + TEST_ASSERT_TRUE(Rns::WalkStep::Row == Rns::walkStep(at(1, true, 5, 70, share - 1))); + TEST_ASSERT_TRUE(Rns::WalkStep::Skip == + Rns::walkStep(at(1, true, 6, 70, share - 1 + share))); + TEST_ASSERT_TRUE(Rns::WalkStep::StopBudget == + Rns::walkStep(at(1, true, 6, 70, share - 1 + share + 1))); + + // So the margin this tree actually has is against 200 ms and not 400: the + // worst per-record figure measured anywhere in it is 81 % of the share. + TEST_ASSERT_LESS_THAN_UINT32(share, kSlowRecordMs); + TEST_ASSERT_EQUAL_UINT32_MESSAGE(81, kSlowRecordMs * 100 / share, + "the worst measured record is no longer 81 % of the row share; the margin " + "paragraph in SnapshotWalk.h quotes that figure"); +} + +// --------------------------------------------------------------------------- +// Scheduling the next pass against what this one cost +// --------------------------------------------------------------------------- + +void test_the_scheduler_is_inert_at_every_cost_this_tree_has_measured() { + // The measured half of the same quarter walkBudgetFitsInterval() applies to + // the budget. On any node whose pass costs less than that quarter it hands + // the configured interval straight back, and it must: a scheduler that moved + // the interval on a healthy node would be a tuning knob rather than a guard. + TEST_ASSERT_EQUAL_UINT32(4, Rns::kPassShareDiv); + const uint32_t interval = (uint32_t)SNAPSHOT_INTERVAL_MS; + const uint32_t ceiling = kSweepCeilingMs; // kStaleSweepMs, the caller's own + + // The budget plus the worst record anywhere in this tree, which is what a + // pass costs when the budget ends it. + const uint32_t worstMeasured = Rns::kWalkBudgetMs + kSlowRecordMs; + TEST_ASSERT_EQUAL_UINT32(562, worstMeasured); + TEST_ASSERT_EQUAL_UINT32(interval, Rns::nextIntervalMs(worstMeasured, interval, ceiling)); + TEST_ASSERT_EQUAL_UINT32(interval, Rns::nextIntervalMs(0, interval, ceiling)); + // Right up to the quarter, and one millisecond past it is where it starts. + TEST_ASSERT_EQUAL_UINT32(interval, Rns::nextIntervalMs(interval / 4, interval, ceiling)); + TEST_ASSERT_EQUAL_UINT32(5004, Rns::nextIntervalMs(interval / 4 + 1, interval, ceiling)); +} + +void test_a_pass_that_outgrows_its_share_buys_itself_room() { + const uint32_t interval = (uint32_t)SNAPSHOT_INTERVAL_MS; + const uint32_t ceiling = kSweepCeilingMs; + + // The case this exists for, and it is not hypothetical: passMayStop() may not + // end a pass that has read nothing, so a pass costs the prefix it steps over + // plus one record if stepping ever stops being free — which is the microStore + // the abandoned branch ran on. This is the very pass + // test_a_pass_reaches_its_own_cursor_even_if_stepping_stops_being_free + // drives: fifty positions at 30 ms and one record. + const Pass overrun = runWalk(table(200, true), false, 0, kFastRecordMs, Rns::kWalkYieldMs, + 1, Rns::kWalkBudgetMs, /*rowPos=*/50, /*rowsAlready=*/50, + /*skipMs=*/kFastRecordMs); + TEST_ASSERT_GREATER_THAN_UINT32(Rns::kWalkBudgetMs, overrun.elapsedMs); + TEST_ASSERT_GREATER_THAN_UINT32(interval / 4, overrun.elapsedMs); + TEST_ASSERT_EQUAL_UINT32(overrun.elapsedMs * 4, + Rns::nextIntervalMs(overrun.elapsedMs, interval, ceiling)); + + // And the figure that took a T-Beam down: 7.5 s a walk against a 5 s gate is + // a gate that is already open when the pass returns, so passes ran back to + // back. Four times the cost is 30 s, and the ceiling is not reached. + TEST_ASSERT_EQUAL_UINT32(30000, Rns::nextIntervalMs(7500, interval, ceiling)); +} + +void test_the_scheduler_has_a_ceiling_the_abandoned_formula_did_not() { + const uint32_t interval = (uint32_t)SNAPSHOT_INTERVAL_MS; + const uint32_t ceiling = kSweepCeilingMs; + + // max(walkMs * 4, SNAPSHOT_INTERVAL_MS) — the version on the abandoned branch + // — has no upper end, so a node whose passes cost a minute would be put on a + // four-minute interval, and a node that slow needs its cleanup more often + // than that rather than less. + TEST_ASSERT_GREATER_THAN_UINT32(ceiling, ceiling * Rns::kPassShareDiv); + TEST_ASSERT_EQUAL_UINT32(ceiling, Rns::nextIntervalMs(ceiling, interval, ceiling)); + // The clamp begins at a quarter of the ceiling, where four times the cost + // would first exceed it. + TEST_ASSERT_EQUAL_UINT32(ceiling, Rns::nextIntervalMs(ceiling / 4, interval, ceiling)); + TEST_ASSERT_EQUAL_UINT32(59996, Rns::nextIntervalMs(ceiling / 4 - 1, interval, ceiling)); + // It never returns less than the configured interval, whatever it is asked. + for (uint32_t cost = 0; cost <= 20000; cost += 137) + TEST_ASSERT_GREATER_OR_EQUAL_UINT32(interval, + Rns::nextIntervalMs(cost, interval, ceiling)); + // A ceiling below the interval is a misconfiguration and is answered with the + // interval rather than with something shorter than the node was told to use. + TEST_ASSERT_EQUAL_UINT32(interval, Rns::nextIntervalMs(9000, interval, 1000)); + // No multiply is reached above the ceiling's own quarter, which is what keeps + // the arithmetic from wrapping at absurd inputs — the same reason + // walkBudgetFitsInterval() divides rather than multiplies. + TEST_ASSERT_EQUAL_UINT32(ceiling, Rns::nextIntervalMs(0xFFFFFFFFu, interval, ceiling)); + TEST_ASSERT_EQUAL_UINT32(0xFFFFFFFFu, + Rns::nextIntervalMs(0xFFFFFFFFu, interval, 0xFFFFFFFFu)); +} + +void test_passes_cannot_run_back_to_back_under_the_worst_timing() { + // The property the static 12.5x margin cannot give, because that margin is + // between the *budget* and the interval and a pass is not its budget. The + // gate is "has the interval passed since the *start* of the last pass", so + // what the RNS task gets back is interval - cost: the time it spends going + // round its loop and sleeping 10 ms at a time, which is the only core the + // priority-1 loopTask gets (SnapshotWalk.h). + const uint32_t interval = (uint32_t)SNAPSHOT_INTERVAL_MS; + const uint32_t ceiling = kSweepCeilingMs; + + // A pass that outlasts the interval leaves nothing at all under the fixed + // gate — the gate is open the moment the pass returns and the next one starts + // at once. That is the shape that took the T-Beam down. + TEST_ASSERT_TRUE(7500u > interval); + // Scheduled against what it cost, the same pass leaves 22.5 s. + TEST_ASSERT_EQUAL_UINT32(22500, Rns::nextIntervalMs(7500, interval, ceiling) - 7500); + + // The general form: up to the ceiling's quarter, the gap is at least four + // times the pass, so the task is out of this function for at least three + // quarters of every window whatever a pass comes to cost. + // Every cost in the linear branch rather than a sample of them. The property + // is an algebraic identity inside that branch, so a stride proves nothing a + // step does not — and the branch is fifteen thousand values, which costs + // this suite nothing. + for (uint32_t cost = 0; cost <= ceiling / Rns::kPassShareDiv; cost++) { + const uint32_t next = Rns::nextIntervalMs(cost, interval, ceiling); + TEST_ASSERT_GREATER_OR_EQUAL_UINT32(cost * Rns::kPassShareDiv, next); + // ...and so out of it for all but one share of every window. + TEST_ASSERT_GREATER_OR_EQUAL_UINT32(cost * (Rns::kPassShareDiv - 1), next - cost); + } + // Past that quarter the ceiling takes over and the margin is given up on + // purpose: a node spending a quarter of a minute in one pass is broken in a + // way scheduling cannot fix, and holding the ratchet there would put its + // dead-path cleanup further out than the minute it is supposed to run on. + // What is kept is that the interval never shrinks and never runs away. + TEST_ASSERT_LESS_THAN_UINT32(45000u * 4, Rns::nextIntervalMs(45000, interval, ceiling)); + TEST_ASSERT_EQUAL_UINT32(ceiling, Rns::nextIntervalMs(45000, interval, ceiling)); +} + +void test_a_pass_that_threw_costs_the_node_the_same_back_off() { + // The scheduler was asked only where a pass returned: sSnapIntervalMs was + // written after the walk and the removal had both come back, so a pass that + // threw left the interval it had been gated on standing. The entry stamp + // stops a *fast* throw coming back on the next 10 ms tick and that part + // worked; what it cannot do is stop a slow one, because by the time such a + // pass throws the interval it was gated on has already gone. + const uint32_t start = 10000; + const uint32_t cost = 7500; // the T-Beam's figure, and past the interval + + // What that looked like: the entry stamp, an interval nobody updated, and a + // gate already open at the moment of the throw. + Gate unfixed; + unfixed.enter(start); + TEST_ASSERT_EQUAL_UINT32((uint32_t)SNAPSHOT_INTERVAL_MS, unfixed.intervalMs); + TEST_ASSERT_TRUE(unfixed.dueAt(start + cost)); + + // With the back-off taken on the way out, the same pass costs the node the + // 30 s its cost earns — and from where it stopped, so the gap is real rather + // than one the pass has already spent. + Gate g; + g.threw(start, cost); + TEST_ASSERT_EQUAL_UINT32(30000, g.intervalMs); + TEST_ASSERT_FALSE(g.dueAt(start + cost)); + TEST_ASSERT_FALSE(g.dueAt(start + cost + 29999)); + TEST_ASSERT_TRUE(g.dueAt(start + cost + 30000)); + + // Repeated slow failures, which is the sick filesystem this is for: every one + // of them buys a gap instead of the passes running back to back. + uint32_t at = start; + for (int k = 0; k < 4; k++) { + g.threw(at, cost); + TEST_ASSERT_FALSE(g.dueAt(at + cost)); + at = at + cost + g.intervalMs; + TEST_ASSERT_TRUE(g.dueAt(at)); + } + + // A pass slower than the ceiling itself is the case the entry stamp alone + // cannot cover at all: 60 s is the most the scheduler will ask for, and a + // pass that ran longer than that has spent it before it throws. Measured from + // where it stopped, it still leaves the node a minute. + Gate slow; + slow.threw(start, 70000); + TEST_ASSERT_EQUAL_UINT32(kSweepCeilingMs, slow.intervalMs); + TEST_ASSERT_FALSE(slow.dueAt(start + 70000)); + TEST_ASSERT_TRUE(slow.dueAt(start + 70000 + kSweepCeilingMs)); + + // And a throw that is not slow is not punished for it: under the quarter the + // scheduler is inert, so the node is back on its configured interval. + Gate fast; + fast.threw(start, 5); + TEST_ASSERT_EQUAL_UINT32((uint32_t)SNAPSHOT_INTERVAL_MS, fast.intervalMs); + TEST_ASSERT_TRUE(fast.dueAt(start + 5 + SNAPSHOT_INTERVAL_MS)); + + // One formula for both ways out, which is the other half of the fix: a pass + // that threw and a pass that returned having cost the same are given the same + // interval, and only where it is measured from differs. + Gate ok; + ok.passed(start, cost); + TEST_ASSERT_EQUAL_UINT32(g.intervalMs, ok.intervalMs); +} + +// --------------------------------------------------------------------------- +// The yield cadence +// --------------------------------------------------------------------------- + +void test_the_yield_cadence_fires_more_than_once_inside_one_budget() { + // At the cost this firmware links, one budget's walk yields three times. + // Where those three land is asserted below, and is not the tidy 100/200/300. + const Pass fast = runWalk(table(200, true), false, 0, kFastRecordMs); + TEST_ASSERT_EQUAL_size_t(3, fast.yields); + // Where they land, which the header quotes and used to divide out wrongly. + // Not 100, 200 and 300: the cadence is measured from the previous yield, and + // a yield costs a tick that is itself charged to the budget, so the gap + // between two of them is a record's worth over the interval rather than + // exactly it. Driven here so the header cannot drift back to the tidy + // version. + TEST_ASSERT_EQUAL_size_t(3, fast.yieldAt.size()); + TEST_ASSERT_EQUAL_UINT32(120, fast.yieldAt[0]); + TEST_ASSERT_EQUAL_UINT32(241, fast.yieldAt[1]); + TEST_ASSERT_EQUAL_UINT32(362, fast.yieldAt[2]); + // The rule they come from, at each landing: at or past a cadence since the + // one before, and never before it. + TEST_ASSERT_GREATER_OR_EQUAL_UINT32(Rns::kWalkYieldMs, fast.yieldAt[0]); + TEST_ASSERT_GREATER_OR_EQUAL_UINT32(Rns::kWalkYieldMs, fast.yieldAt[1] - fast.yieldAt[0]); + TEST_ASSERT_GREATER_OR_EQUAL_UINT32(Rns::kWalkYieldMs, fast.yieldAt[2] - fast.yieldAt[1]); + // And at the worst per-record cost the tree records, where a pass reads only + // a handful of records at all. Still more than once, which is the property. + const Pass slow = runWalk(table(200, true), false, 0, kSlowRecordMs); + TEST_ASSERT_EQUAL_size_t(2, slow.yields); + TEST_ASSERT_GREATER_THAN_size_t(1, fast.yields); + TEST_ASSERT_GREATER_THAN_size_t(1, slow.yields); +} + +void test_the_feed_cadence_would_not_yield_at_all() { + // Why the yield is not Sys::RingDrain::kFeedEvery. That cadence is a count of + // records; 16 of them at 30 ms is 480 ms, which is longer than the whole + // budget, so the walk is stopped before it ever reaches one. It is also why + // the walk no longer *feeds* on that cadence: the same sixteenth record is + // the one a feed on it would have waited for. + TEST_ASSERT_EQUAL_size_t(16, Sys::RingDrain::kFeedEvery); + TEST_ASSERT_GREATER_THAN_UINT32(Rns::kWalkBudgetMs, + (uint32_t)Sys::RingDrain::kFeedEvery * kFastRecordMs); + + // Driven rather than argued: the same walk with a count-of-16 cadence. + size_t reads = 0, yields = 0; + uint32_t elapsedMs = 0; + for (size_t pos = 0; pos < 200; pos++) { + if (Rns::walkStep(at(reads, false, pos, 0, elapsedMs)) != Rns::WalkStep::Row) break; + if (++reads % Sys::RingDrain::kFeedEvery == 0) yields++; + elapsedMs += kFastRecordMs; + } + TEST_ASSERT_EQUAL_size_t(0, yields); + TEST_ASSERT_LESS_THAN_size_t(Sys::RingDrain::kFeedEvery, reads); + + // The elapsed-time cadence on the identical walk gives the core up three + // times. That difference is the fix. + const Pass r = runWalk(table(200, true), false, 0, kFastRecordMs); + TEST_ASSERT_EQUAL_size_t(3, r.yields); +} + +void test_the_yield_ceiling_does_not_move_with_the_record_cost() { + // The property no count of records has: however cheap a record becomes, a + // pass gives the core up at most three times, because a fourth would need the + // whole budget elapsed and that is a stop. + for (uint32_t recordMs = 0; recordMs <= 40; recordMs++) { + const Pass r = runWalk(table(4000, true), false, 0, recordMs); + TEST_ASSERT_LESS_OR_EQUAL_size_t(3, r.yields); + } + // A free record is the extreme of that, and it needs a sweep running to be + // the case it claims: with no sweep the walk stops at the row cap after 64 + // positions and the 4000 are never reached. Sweeping, it reads all 4000 — + // and because nothing moves the clock it never reaches a yield at all, which + // is the ceiling holding from below rather than above. + const Pass free = runWalk(table(4000, true), true, 0, 0); + TEST_ASSERT_FALSE(free.ranOut); + TEST_ASSERT_EQUAL_size_t(4000, free.reads); + TEST_ASSERT_EQUAL_size_t(0, free.yields); + TEST_ASSERT_LESS_OR_EQUAL_size_t(3, free.yields); +} + +void test_the_first_record_of_a_pass_does_not_yield() { + // lastYieldMs starts at the walk's own start, so a short walk pays nothing. + TEST_ASSERT_FALSE(Rns::walkShouldYield(0, 0)); + TEST_ASSERT_FALSE(Rns::walkShouldYield(Rns::kWalkYieldMs - 1, 0)); + TEST_ASSERT_TRUE(Rns::walkShouldYield(Rns::kWalkYieldMs, 0)); + // And the interval is measured from the last yield, not from the start. + TEST_ASSERT_FALSE(Rns::walkShouldYield(Rns::kWalkYieldMs + 1, Rns::kWalkYieldMs)); + TEST_ASSERT_TRUE(Rns::walkShouldYield(Rns::kWalkYieldMs * 2, Rns::kWalkYieldMs)); +} + +void setUp() {} +void tearDown() {} + +int main() { + UNITY_BEGIN(); + RUN_TEST(test_the_constants_are_what_the_fix_committed_to); + RUN_TEST(test_the_budget_stays_well_inside_the_interval_a_pass_is_gated_on); + RUN_TEST(test_a_budget_that_outlasts_the_interval_is_what_the_guard_is_for); + RUN_TEST(test_the_budget_stops_a_pass_while_rows_are_still_filling); + RUN_TEST(test_the_budget_applies_on_the_skip_path); + RUN_TEST(test_rows_full_and_no_sweep_is_a_finish_not_a_budget_stop); + RUN_TEST(test_a_position_neither_half_wants_is_stepped_over); + RUN_TEST(test_a_row_is_read_whether_or_not_the_sweep_wants_it); + RUN_TEST(test_a_slow_table_is_bounded_by_the_budget_in_the_row_half); + RUN_TEST(test_a_table_of_dead_entries_is_bounded_too); + RUN_TEST(test_a_small_table_finishes_inside_the_budget_and_closes_the_cycle); + RUN_TEST(test_a_pass_stops_on_rows_full_when_nothing_else_needs_the_rest); + RUN_TEST(test_a_sweeping_pass_steps_over_the_prefix_it_has_already_examined); + RUN_TEST(test_the_sweep_cursor_never_moves_backwards); + RUN_TEST(test_a_row_bound_pass_leaves_the_cursor_where_it_was); + RUN_TEST(test_a_cursor_past_the_end_of_the_table_starts_the_cycle_again); + RUN_TEST(test_a_cursor_left_past_a_shrunken_table_does_not_latch); + RUN_TEST(test_a_row_bound_table_now_advances_the_cursor); + RUN_TEST(test_a_pass_may_not_stop_on_budget_before_it_has_read_something); + RUN_TEST(test_a_pass_reaches_its_own_cursor_even_if_stepping_stops_being_free); + RUN_TEST(test_a_resuming_pass_does_not_end_at_its_own_front_door); + RUN_TEST(test_only_a_whole_list_is_published); + RUN_TEST(test_a_cycle_over_an_empty_table_does_not_answer_for_a_full_one); + RUN_TEST(test_a_node_that_has_read_its_table_does_not_flap_between_the_two); + RUN_TEST(test_a_pass_that_threw_starts_the_row_cycle_again); + RUN_TEST(test_the_removal_is_bounded_by_the_walks_clock_and_not_a_fresh_one); + RUN_TEST(test_the_rows_give_the_sweep_half_the_budget_when_it_is_ahead); + RUN_TEST(test_the_sweep_cursor_advances_on_every_sweeping_pass); + RUN_TEST(test_the_row_cap_knife_edge_no_longer_stalls_the_sweep); + RUN_TEST(test_a_cycle_the_share_cut_short_is_kept_as_a_prefix); + RUN_TEST(test_a_record_over_the_row_share_can_still_deny_the_sweep); + RUN_TEST(test_the_scheduler_is_inert_at_every_cost_this_tree_has_measured); + RUN_TEST(test_a_pass_that_outgrows_its_share_buys_itself_room); + RUN_TEST(test_the_scheduler_has_a_ceiling_the_abandoned_formula_did_not); + RUN_TEST(test_passes_cannot_run_back_to_back_under_the_worst_timing); + RUN_TEST(test_a_pass_that_threw_costs_the_node_the_same_back_off); + RUN_TEST(test_the_yield_cadence_fires_more_than_once_inside_one_budget); + RUN_TEST(test_the_feed_cadence_would_not_yield_at_all); + RUN_TEST(test_the_yield_ceiling_does_not_move_with_the_record_cost); + RUN_TEST(test_the_first_record_of_a_pass_does_not_yield); + return UNITY_END(); +} diff --git a/test/test_typed_store_iterator/test_main.cpp b/test/test_typed_store_iterator/test_main.cpp new file mode 100644 index 0000000..1eae08a --- /dev/null +++ b/test/test_typed_store_iterator/test_main.cpp @@ -0,0 +1,603 @@ +// SPDX-License-Identifier: GPL-3.0-or-later +// Copyright (C) 2026 Dobrev IT Ltd +// +// This file is part of RetiMesh Node. +// +// RetiMesh Node is free software: you can redistribute it and/or modify it +// under the terms of the GNU General Public License as published by the +// Free Software Foundation, either version 3 of the License, or (at your +// option) any later version. +// +// RetiMesh Node is distributed in the hope that it will be useful, but +// WITHOUT ANY WARRANTY; without even the implied warranty of +// MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the GNU General +// Public License for more details. +// +// You should have received a copy of the GNU General Public License along +// with RetiMesh Node. If not, see . + + +// microStore's iterator: stepping is free, reading is not. +// +// This suite is a tripwire, not a test of our own code. The path table is +// RNS::Persistence::NewPathTable = microStore::TypedStore, and the walk in refreshSnapshots() +// (src/rns/RnsTransport.cpp) is built on the promise that ++ touches the +// in-memory index only and that * is the sole path to the filesystem. That +// promise is what makes a resumable row cursor safe: a cursor that resumes at +// position N must reach it for one read, not N. If it costs N, resuming is +// the O(n^2) trap and the cursor must not be adopted. +// +// The promise is not ours to keep. microStore is pinned in platformio.ini to +// the branch dobrevit/microStore#retimesh/combined, not to a commit, so it +// moves under us between builds. It has already moved the wrong way once: +// TypedStore's iterator loaded in its constructor and again in operator++, +// so a traversal paid a read for every entry it stepped over, whether the +// caller looked at it or not. Upstream a213413 ("Load the record on +// dereference, not on every step") is the fix; the library's own comment in +// TypedStore.h records what the old shape cost. +// +// So if this suite goes red, the branch has regressed and the row cursor in +// refreshSnapshots() has to be reconsidered before anything else is done +// about it. Nothing here is a workaround to be relaxed. +// +// The promise has two halves and both are held here, because a regression in +// either one costs the firmware the same read per step: +// +// * TypedStore's half — that it does not dereference the store beneath it +// while stepping — over a hand-written CountingStore. What that fake +// models is BasicFileStore's I/O manners and nothing more: operator++ +// moves a position and reads nothing, operator* is the only thing that +// reads a value, and a value already read at this position is not read +// again. It is not a BasicFileStore in any other respect — the real +// operator++ calls load_meta(), which repopulates key/timestamp/ttl from +// the in-memory index and clears the value; begin() flushes the write +// buffer first, and a flush writes bytes to the segment file; there is a +// metadata-only operator->; and the real Entry carries timestamp and ttl +// this Record has no field for. None of that reads or opens a file, and +// reads and opens are the only I/O the meters below count, so the +// accounting still holds. +// +// * BasicFileStore's own half — that load_meta() really is "Zero disk I/O", +// which is its own comment on itself in FileStore.h, and that load_value() +// is the only path to the filesystem — over a real microStore::FileStore +// on a RAM filesystem that counts opens and reads. This half is not +// reachable through the fake by construction, and it is the half the +// firmware actually pays for. +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include "Config.h" // SNAPSHOT_MAX_PATHS +#include +#include + +namespace { + +// As many rows as refreshSnapshots() will ever render in one pass. Taken from +// the firmware's own constant rather than repeated here, so a retune of the +// budget cannot leave this suite measuring a table size the node never builds. +// Big enough that "one read" and "one read per step" are not the same number +// by accident. +constexpr size_t kRows = SNAPSHOT_MAX_PATHS; + +// Two of the tests below read that constant as a table size rather than as a +// budget: the subset walk expects exactly kRows/4 reads, and the resume walk +// visits {kRows-1, kRows/2, 1, 0}, which are only distinct in-range positions +// while the table is comfortably longer than one row. Pinned here so that +// retuning the budget cannot turn this tripwire red for a reason that has +// nothing to do with microStore — a red here has to mean upstream regressed. +static_assert(kRows % 4 == 0 && kRows >= 8, + "test_typed_store_iterator needs a row count divisible by 4 and " + "well above 1. If SNAPSHOT_MAX_PATHS is retuned past that, give " + "this suite its own row count instead of relaxing its numbers."); + +std::string keyAt(size_t n) { return "k" + std::to_string(n); } +std::string valueAt(size_t n) { return "v" + std::to_string(n); } + +// --------------------------------------------------------------------------- +// Part one: TypedStore, over a store with BasicFileStore's iterator contract +// and a meter on it. +// --------------------------------------------------------------------------- +class CountingStore { +public: + // What the store hands out on dereference: the raw, still-encoded record, + // which is what BasicFileStore::Entry is as far as TypedStore can see. + struct Record { + std::vector key; + std::vector value; + }; + + void add(const std::string& key, const std::string& value) { + _rows.push_back({key, value}); + } + + // Values actually read out of the store. On the real thing this is the + // filesystem open-seek-read; here it is the only place the row's bytes are + // touched, which is the same claim. + size_t reads() const { return _reads; } + // Positions stepped over. Counted so a test that expects zero reads cannot + // pass because the walk never moved. + size_t steps() const { return _steps; } + void resetMeter() { _reads = 0; _steps = 0; } + + class iterator { + public: + iterator(CountingStore* store, size_t pos) : _store(store), _pos(pos) {} + + // Index-only, as BasicFileStore::operator++ is: it calls load_meta(), + // which is documented there as zero disk I/O. + iterator& operator++() { + ++_pos; + _loaded = false; + _store->_steps++; + return *this; + } + + bool operator==(const iterator& other) const { return _pos == other._pos; } + bool operator!=(const iterator& other) const { return _pos != other._pos; } + + const Record& operator*() const { + if (!_loaded) read(); + return _current; + } + + private: + void read() const { + _loaded = true; + // Counted before the range check, not after: the meter records that the + // store was asked for a row, and a request past the last one is still a + // request. That is what makes the end() case below fail on its read + // count rather than on an out-of-range index. + _store->_reads++; + if (_pos >= _store->_rows.size()) { + // end() is not dereferenceable. If TypedStore's guard ever moves back + // out of load(), the walk arrives here with _pos one past the last + // row; hand back an empty record so the test that exists to catch + // that reports a failed assertion instead of indexing off the end. + // Without this the native build aborts on the out-of-range subscript, + // and everything Unity had printed before it goes with the buffer — + // measured here as no output at all and status 134, which PlatformIO's + // reader can only show as an unexplained signal (docs/development.md). + _current.key.clear(); + _current.value.clear(); + return; + } + const Row& row = _store->_rows[_pos]; + _current.key.assign(row.key.begin(), row.key.end()); + _current.value.assign(row.value.begin(), row.value.end()); + } + + CountingStore* _store; + size_t _pos; + mutable bool _loaded = false; + mutable Record _current; + }; + + iterator begin() { return iterator(this, 0); } + iterator end() { return iterator(this, _rows.size()); } + + bool isValid() const { return true; } + size_t size() const { return _rows.size(); } + +private: + struct Row { std::string key; std::string value; }; + + std::vector _rows; + size_t _reads = 0; + size_t _steps = 0; +}; + +// The real TypedStore, over the fake. std::string on both sides because +// Codec ships with the library and the property under test is +// the iterator's, not the codec's. +using Store = microStore::TypedStore; + +void fill(CountingStore& store, size_t rows) { + for (size_t n = 0; n < rows; n++) store.add(keyAt(n), valueAt(n)); + store.resetMeter(); +} + +// --------------------------------------------------------------------------- +// Part two: a RAM filesystem with a meter, for the real BasicFileStore. +// +// Records live in shared buffers rather than in the map itself, so a handle +// the store still holds survives the file being removed from under it — which +// is what flash does, and what the store's own compaction relies on. +// --------------------------------------------------------------------------- +class RamDisk { +public: + using Blob = std::shared_ptr>; + + Blob find(const std::string& name) { + auto it = _files.find(name); + return it == _files.end() ? Blob() : it->second; + } + Blob create(const std::string& name) { + Blob blob = std::make_shared>(); + _files[name] = blob; + return blob; + } + bool erase(const std::string& name) { return _files.erase(name) > 0; } + bool exists(const std::string& name) const { return _files.count(name) > 0; } + bool rename(const std::string& from, const std::string& to) { + auto it = _files.find(from); + if (it == _files.end()) return false; + _files[to] = it->second; + _files.erase(it); + return true; + } + + // Files opened. On LittleFS this is the expensive half of a record read — + // every open resolves the path afresh — which is why it is metered apart + // from the bytes. + size_t opens() const { return _opens; } + // Calls that took content off a file: both read() overloads and peek(). + size_t reads() const { return _reads; } + void resetMeter() { _opens = 0; _reads = 0; } + + void countOpen() { _opens++; } + void countRead() { _reads++; } + +private: + std::map _files; + size_t _opens = 0; + size_t _reads = 0; +}; + +class RamFileImpl : public microStore::FileImpl { +public: + RamFileImpl(RamDisk* disk, RamDisk::Blob blob, const std::string& name, bool append) + : _disk(disk), _blob(blob), _name(name), _pos(append ? blob->size() : 0) {} + +protected: + const char* name() const override { return _name.c_str(); } + size_t size() const override { return _blob->size(); } + void close() override { _open = false; } + + int read() override { + _disk->countRead(); + if (_pos >= _blob->size()) return EOF; + return (*_blob)[_pos++]; + } + + size_t read(uint8_t* buffer, size_t size) override { + _disk->countRead(); + if (_pos >= _blob->size()) return 0; + const size_t avail = _blob->size() - _pos; + const size_t n = size < avail ? size : avail; + memcpy(buffer, _blob->data() + _pos, n); + _pos += n; + return n; + } + + size_t write(uint8_t ch) override { + if (_pos >= _blob->size()) _blob->resize(_pos + 1); + (*_blob)[_pos++] = ch; + return 1; + } + + size_t write(const uint8_t* buffer, size_t size) override { + if (_blob->size() < _pos + size) _blob->resize(_pos + size); + memcpy(_blob->data() + _pos, buffer, size); + _pos += size; + return size; + } + + int available() override { + return _pos >= _blob->size() ? 0 : (int)(_blob->size() - _pos); + } + + int peek() override { + _disk->countRead(); + if (_pos >= _blob->size()) return EOF; + return (*_blob)[_pos]; + } + + size_t tell() override { return _pos; } + + long seek(uint32_t pos, microStore::SeekMode mode) override { + switch (mode) { + case microStore::SeekModeEnd: _pos = _blob->size() + pos; break; + case microStore::SeekModeCur: _pos += pos; break; + case microStore::SeekModeSet: + default: _pos = pos; break; + } + return (long)_pos; + } + + void flush() override {} + bool isValid() const override { return _open; } + +private: + RamDisk* _disk; + RamDisk::Blob _blob; + std::string _name; + size_t _pos; + bool _open = true; +}; + +class RamFileSystemImpl : public microStore::FileSystemImpl { +public: + explicit RamFileSystemImpl(RamDisk* disk) : _disk(disk) {} + +protected: + microStore::File open(const char* path, microStore::File::Mode mode, + const bool create = false) override { + (void)create; + _disk->countOpen(); + // The four modes FileStore actually asks for: ModeWrite truncates, + // ModeAppend and ModeReadAppend start at the end, ModeRead starts at 0 and + // fails if the file is not there. + const bool truncate = (mode == microStore::File::ModeWrite); + const bool append = (mode == microStore::File::ModeAppend || + mode == microStore::File::ModeReadAppend); + + RamDisk::Blob blob = _disk->find(path); + if (!blob) { + if (mode == microStore::File::ModeRead) return {}; + blob = _disk->create(path); + } else if (truncate) { + blob->clear(); + } + return microStore::File(new RamFileImpl(_disk, blob, path, append)); + } + + bool exists(const char* path) override { return _disk->exists(path); } + bool remove(const char* path) override { return _disk->erase(path); } + bool rename(const char* from, const char* to) override { return _disk->rename(from, to); } + bool mkdir(const char* path) override { (void)path; return true; } + bool rmdir(const char* path) override { (void)path; return true; } + bool isDirectory(const char* path) override { (void)path; return false; } + + std::list listDirectory(const char* path, + Callbacks::DirectoryListing callback = nullptr) override { + (void)path; (void)callback; + return {}; + } + + size_t storageSize() override { return 0; } + size_t storageAvailable() override { return 0; } + +private: + RamDisk* _disk; +}; + +// A real microStore::FileStore on that disk, filled and metered from zero. +// The meter is reset after the fill, so what the puts and the init cost is not +// charged to the walk. +void fillFileStore(microStore::FileStore& store, microStore::FileSystem& fs, + RamDisk& disk, size_t rows) { + TEST_ASSERT_TRUE(store.init(fs, "/paths")); + for (size_t n = 0; n < rows; n++) + TEST_ASSERT_TRUE(store.put(keyAt(n), valueAt(n))); + TEST_ASSERT_EQUAL_size_t(rows, store.size()); + disk.resetMeter(); +} + +// The value a key was stored with: keys are "kN", values "vN", and the index +// is an unordered_map so which key sits at which position is not predictable. +std::string valueForKey(const std::string& key) { return "v" + key.substr(1); } + +} // namespace + +// A whole walk with no dereference reads nothing. This is the property the +// row budget spends: positions a pass has no use for are stepped over for +// free, so the budget goes entirely on records that are going to be looked at. +void test_stepping_without_dereferencing_reads_nothing() { + CountingStore backing; + fill(backing, kRows); + Store store(backing); + + size_t stepped = 0; + for (auto it = store.begin(); it != store.end(); ++it) stepped++; + + TEST_ASSERT_EQUAL_size_t(kRows, stepped); + TEST_ASSERT_EQUAL_size_t(kRows, backing.steps()); // the walk really happened + TEST_ASSERT_EQUAL_size_t(0, backing.reads()); // and cost nothing +} + +// ...and a walk that does dereference pays once per position, no more. +void test_dereferencing_reads_once_per_position() { + CountingStore backing; + fill(backing, kRows); + Store store(backing); + + size_t seen = 0; + for (auto it = store.begin(); it != store.end(); ++it) { + Store::Entry& e = *it; + TEST_ASSERT_EQUAL_STRING(keyAt(seen).c_str(), e.key.c_str()); + TEST_ASSERT_EQUAL_STRING(valueAt(seen).c_str(), e.value.c_str()); + seen++; + } + + TEST_ASSERT_EQUAL_size_t(kRows, seen); + TEST_ASSERT_EQUAL_size_t(kRows, backing.reads()); +} + +// The loaded_ cache: asking twice at one position reads once. Stepping clears +// it, so the next position is read afresh rather than served the old row. +void test_re_dereferencing_the_same_position_does_not_read_again() { + CountingStore backing; + fill(backing, kRows); + Store store(backing); + + auto it = store.begin(); + TEST_ASSERT_EQUAL_STRING(keyAt(0).c_str(), (*it).key.c_str()); + TEST_ASSERT_EQUAL_size_t(1, backing.reads()); + TEST_ASSERT_EQUAL_STRING(keyAt(0).c_str(), (*it).key.c_str()); + TEST_ASSERT_EQUAL_size_t(1, backing.reads()); + + ++it; + TEST_ASSERT_EQUAL_STRING(keyAt(1).c_str(), (*it).key.c_str()); + TEST_ASSERT_EQUAL_size_t(2, backing.reads()); +} + +// The one the row cursor rests on. +// +// A cursor that resumes at position N advances an iterator from begin() to N +// and dereferences there. If advancing read, that costs a read per step and +// resuming across a table costs the sum of every prefix — the O(n^2) trap, +// and the reason an earlier attempt at a cursor was abandoned. It must cost +// exactly one read: the row it actually wants. +void test_reaching_position_n_costs_one_read_not_n() { + CountingStore backing; + fill(backing, kRows); + Store store(backing); + + // Last, a couple in between, then first: a cursor resumes wherever it left + // off, so "one read" has to hold at any position, not just at begin(). The + // far end goes first on purpose — Unity stops a test at its first failure, + // and a regression here should report the whole prefix it read rather than + // the single read it would report at position 0. Restoring the pre-a213413 + // shape by hand and running this file against it does exactly that: it + // reports kRows reads where it expected none, one per step plus the + // constructor's. + const size_t targets[] = { kRows - 1, kRows / 2, 1, 0 }; + + for (size_t t = 0; t < sizeof(targets) / sizeof(targets[0]); t++) { + const size_t target = targets[t]; + backing.resetMeter(); + + auto it = store.begin(); + for (size_t n = 0; n < target; n++) ++it; + TEST_ASSERT_EQUAL_size_t(target, backing.steps()); + TEST_ASSERT_EQUAL_size_t(0, backing.reads()); // getting there was free + + Store::Entry& e = *it; + TEST_ASSERT_EQUAL_size_t(1, backing.reads()); // not target + 1 + // And it is the row that position holds, so the count above is a real + // read of the right record and not a walk that stayed at begin(). + TEST_ASSERT_EQUAL_STRING(keyAt(target).c_str(), e.key.c_str()); + TEST_ASSERT_EQUAL_STRING(valueAt(target).c_str(), e.value.c_str()); + } +} + +// What refreshSnapshots() actually does: step the whole table, dereference +// only the positions this pass wants. The bill is the rows read, not the +// table walked. +void test_a_walk_that_reads_a_subset_pays_only_for_that_subset() { + CountingStore backing; + fill(backing, kRows); + Store store(backing); + + // One position in four. + const size_t kEvery = 4; + size_t pos = 0, read = 0; + for (auto it = store.begin(); it != store.end(); ++it, ++pos) { + if (pos % kEvery != 0) continue; + TEST_ASSERT_EQUAL_STRING(valueAt(pos).c_str(), (*it).value.c_str()); + read++; + } + + TEST_ASSERT_EQUAL_size_t(kRows / kEvery, read); + TEST_ASSERT_EQUAL_size_t(kRows, backing.steps()); + TEST_ASSERT_EQUAL_size_t(kRows / kEvery, backing.reads()); +} + +// end() is not dereferenceable, and TypedStore says so in load() rather than +// by refusing to load in the constructor — which is where the guard had to +// move when the load became lazy (a213413). If it ever moves back out, a walk +// that dereferences its terminator asks the store for a row past the last one. +void test_dereferencing_end_reads_nothing() { + CountingStore backing; + fill(backing, kRows); + Store store(backing); + + auto it = store.end(); + Store::Entry& e = *it; + TEST_ASSERT_EQUAL_size_t(0, backing.reads()); + TEST_ASSERT_TRUE(e.key.empty()); + TEST_ASSERT_TRUE(e.value.empty()); +} + +// An empty table is walked without reading, and without stepping into it. +void test_an_empty_store_walks_without_reading() { + CountingStore backing; + fill(backing, 0); + Store store(backing); + + size_t stepped = 0; + for (auto it = store.begin(); it != store.end(); ++it) stepped++; + + TEST_ASSERT_EQUAL_size_t(0, stepped); + TEST_ASSERT_EQUAL_size_t(0, backing.reads()); +} + +// The other half, on the real BasicFileStore: stepping the whole table opens +// no file and reads no byte. This is the claim TypedStore's iterator forwards +// and the one the firmware's walk is actually billed for — a regression +// confined to BasicFileStore::operator++ would leave every test above green +// while the node read a record off the filesystem at every step. +void test_file_store_stepping_opens_and_reads_nothing() { + RamDisk disk; // outlives the store below + microStore::FileSystem fs(new RamFileSystemImpl(&disk)); + microStore::FileStore store; + fillFileStore(store, fs, disk, kRows); + + // operator-> is the metadata-only dereference, so collecting keys through it + // proves the walk visited every distinct record rather than just counting + // increments — and it must still cost nothing. + std::set keys; + bool loadedWhileStepping = false; + for (auto it = store.begin(); it != store.end(); ++it) { + keys.insert(std::string(it->key.begin(), it->key.end())); + if (!it->value.empty()) loadedWhileStepping = true; + } + + // The meter is asserted before the flag, and reads before opens, so that a + // regression reports what the walk cost rather than that a value was not + // empty. Hand-regressing operator++ to load eagerly and running this file + // against it fails here on the read count, at two reads per record the walk + // lands on — a header and a value — where none was expected. + TEST_ASSERT_EQUAL_size_t(kRows, keys.size()); + TEST_ASSERT_EQUAL_size_t(0, disk.reads()); + TEST_ASSERT_EQUAL_size_t(0, disk.opens()); + TEST_ASSERT_FALSE(loadedWhileStepping); +} + +// ...and dereferencing is what pays. Reaching the far end of the table costs +// nothing; the dereference there opens the segment once and reads the record. +void test_file_store_dereferencing_is_the_only_read() { + RamDisk disk; + microStore::FileSystem fs(new RamFileSystemImpl(&disk)); + microStore::FileStore store; + fillFileStore(store, fs, disk, kRows); + + auto it = store.begin(); + for (size_t n = 0; n < kRows - 1; n++) ++it; // to the last position + TEST_ASSERT_EQUAL_size_t(0, disk.reads()); // getting there was free + TEST_ASSERT_EQUAL_size_t(0, disk.opens()); + + const microStore::FileStore::Entry& e = *it; + TEST_ASSERT_GREATER_THAN_size_t(0, disk.reads()); + // It really went to the filesystem, and once: not zero, which would mean the + // meter is not wired to the read path and the assertions above prove nothing. + TEST_ASSERT_EQUAL_size_t(1, disk.opens()); + + const std::string key(e.key.begin(), e.key.end()); + const std::string value(e.value.begin(), e.value.end()); + TEST_ASSERT_EQUAL_STRING(valueForKey(key).c_str(), value.c_str()); +} + +void setUp() {} +void tearDown() {} + +int main() { + UNITY_BEGIN(); + RUN_TEST(test_stepping_without_dereferencing_reads_nothing); + RUN_TEST(test_dereferencing_reads_once_per_position); + RUN_TEST(test_re_dereferencing_the_same_position_does_not_read_again); + RUN_TEST(test_reaching_position_n_costs_one_read_not_n); + RUN_TEST(test_a_walk_that_reads_a_subset_pays_only_for_that_subset); + RUN_TEST(test_dereferencing_end_reads_nothing); + RUN_TEST(test_an_empty_store_walks_without_reading); + RUN_TEST(test_file_store_stepping_opens_and_reads_nothing); + RUN_TEST(test_file_store_dereferencing_is_the_only_read); + return UNITY_END(); +} diff --git a/tools/soak.py b/tools/soak.py index 9cd55cf..3df179d 100755 --- a/tools/soak.py +++ b/tools/soak.py @@ -105,11 +105,30 @@ # leaves is taken on the next pass — but they are the only sign the node is # being outrun, because the cap is also what keeps that condition from # reaching the watchdog. `rx_drain_capped` is the radio's and is expected to - # move a little: two passes can be 400 ms apart when a path-table sweep runs - # its whole budget between them, which on a fast channel is more than one - # batch of frames. Real loss is drop_ring above. Appended, per the rule - # above. + # move: two passes can be 400 ms apart when the path-table walk runs its + # whole budget between them, which on a fast channel is more than one batch + # of frames. The walk, not the sweep — the budget covers the whole pass, so + # any pass it ends produces that gap, and on a table too big to read in one + # pass that is most passes. Real loss is drop_ring above. Appended, per the + # rule above. "tcp_drain_capped", "rx_drain_capped", + # The snapshot pass's own health, which is what says whether the column + # above is the node reading its own table or the channel. `paths` alone + # cannot: it is the table's size and is exact whatever the walk managed. + # snap_walk_pos is per-pass and means nothing without `paths` beside it, + # which is why the whole set is recorded rather than a chosen subset — every + # snap_* field /api/status serves, so a run can be read against the API's + # own documentation (docs/api.md). snap_rows_whole is 1/0/blank through + # fmt_bool(): a firmware too old to serve it did not say "no". Appended, per + # the rule above. + "snap_walk_max_ms", "snap_walk_pos", "snap_budget_stops", "snap_rows_whole", + # How often a pass happens at all. 5000 on any ordinary node; more where the + # node measured a pass costing more than a quarter of its window and gave + # itself room. Recorded because it is what makes the columns above readable: + # at anything above 5000 the readings in a row are older than the sampling + # interval suggests, and a table that looks like it stopped growing may only + # be being read less often. Appended, per the rule above. + "snap_interval_ms", ] # Every task a healthy node of any board runs. A board without the hardware @@ -163,6 +182,13 @@ def sample(host, timeout=8): links=tables.get("links", ""), destinations=tables.get("destinations", ""), announces=tables.get("announces", ""), + snap_walk_max_ms=tables.get("snap_walk_max_ms", ""), + snap_walk_pos=tables.get("snap_walk_pos", ""), + snap_budget_stops=tables.get("snap_budget_stops", ""), + snap_interval_ms=tables.get("snap_interval_ms", ""), + # Tri-state, like battery_charging: blank is a firmware that does not + # serve the field, which must not be read as "the list is a prefix". + snap_rows_whole=fmt_bool(tables.get("snap_rows_whole")), neighbours=len(d.get("neighbors", [])), airtime_long_pct=d.get("airtime", {}).get("long_pct", ""), transport_online=int(bool(d.get("transport", {}).get("online"))), @@ -353,8 +379,8 @@ def discharge(up, band=None): # One discharge, not several. The CSV is appended to by design, so a file # can hold last week's run, a recharge and today's; and a restart can be a # node that was replugged, which is a different draw. Split on both and - # measure the longest clean stretch, the way announce_segments() splits the - # announce counter at every boot. + # measure the longest clean stretch, the way boot_segments() splits a + # since-boot counter at every boot. segs, seg = [], [0] for i in range(1, len(volts)): recharged = volts[i][1] > volts[i - 1][1] + 0.030 # 30 mV up: not noise @@ -457,20 +483,24 @@ def summarise(path, band=None): print("no samples") return - def announce_segments(rows): - """The announce counter, split at every restart, over the samples that - actually carry it. It is a RAM counter and starts again at zero on - every boot, so a run spanning one holds several counters rather than - one long one; and a sample that does not report it (a node running - firmware from before the column existed) says nothing about any - window, so it is not part of one.""" + def boot_segments(rows, key): + """A since-boot counter, split at every restart, over the samples that + actually carry it. Such a counter starts again at zero on every boot, + so a run spanning one holds several counters rather than one long one; + and a sample that does not report it (a node running firmware from + before the column existed) says nothing about any window, so it is not + part of one. + + Keyed rather than written out per counter: announces_tx was the first + to need it and snap_budget_stops is the second, and two copies of this + are two places for a restart to stop being noticed.""" segments, current, boot = [], [], object() for r in rows: if r.get("boot_count", "") != boot: boot = r.get("boot_count", "") current = [] segments.append(current) - v = num(r.get("announces_tx")) + v = num(r.get(key)) if v is not None: current.append((parse_ts(r["ts"]), v)) return [s for s in segments if s] @@ -551,7 +581,7 @@ def announce_segments(rows): # either way, and then the check runs as it always did. intervals = {num(r.get("announce_interval")) for r in up if num(r.get("announce_interval")) is not None} - segments = announce_segments(up) + segments = boot_segments(up, "announces_tx") if intervals == {0.0}: print(" announces: switched off (announce_interval 0)") elif segments: @@ -659,18 +689,25 @@ def announce_segments(rows): # producer-side ring-full: logged on the TCP side, counted as drop_ring # on the radio side. docs/troubleshooting.md has the row for each. # - # The radio one is expected to be small and non-zero on a fast channel: - # two drains can be 400 ms apart when a path-table sweep runs its whole - # budget between them, and the node catches up on the passes after. It - # is worth printing because the figure that is *not* expected — a total - # that keeps climbing — reads the same way on the line. + # The radio one is expected to be non-zero on a fast channel: two + # drains can be 400 ms apart when the path-table walk runs its whole + # budget between them, and the node catches up on the passes after. + # + # A total that keeps climbing is *also* expected, and that is the part + # this note used to have backwards. The budget covers the whole walk + # now, rows included, so every pass it ends produces that gap — and on a + # table too big to read in one pass the budget ends most passes, every + # five seconds, for as long as the table stays that big. The figure that + # separates the two readings is snap_budget_stops, printed below: rising + # beside this one is the node getting round its own table, flat beside + # it is the channel. capped_meaning = { "tcp_drain_capped": "the inbound TCP ring's batch cap ended that many Reticulum-task passes " "with traffic still queued: a client outrunning this node's routing", "rx_drain_capped": "the RX ring's batch cap ended that many Reticulum-task passes with frames " - "still queued: expected in small totals after a path-table sweep, and real " + "still queued: check snap_budget_stops beside it before the radio, and real " "loss on that path is drop_ring", } for key, meaning in capped_meaning.items(): @@ -681,6 +718,76 @@ def announce_segments(rows): f"(peak {max(capped):.0f}) — {meaning}, and nothing lost by the cap " f"(docs/troubleshooting.md)") + # The snapshot pass, which is what the line above defers to. Recorded + # since the firmware began serving it, and read here rather than left to + # ride the CSV: `paths` climbing said the table was growing and nothing + # said whether the node was still able to read it. + # + # snap_budget_stops counts since boot, so it is read per boot and not + # off the last sample. Read off the last sample, a node that stopped + # hundreds of passes and then rebooted reports nothing at all: the + # counter is back at zero and the whole finding disappears. And the + # first-to-last range it used to print spans the reset, which reads as a + # counter that went backwards. boot_segments() is the same split the + # announce counter above gets, for the same reason. + # + # Per segment rather than per window: the value is the count since that + # boot, so the last sample of a segment is that run's own total — + # including the stops before the first sample, which is what keeps a run + # started after the stops began from losing the finding. + stop_runs = boot_segments(up, "snap_budget_stops") + if any(s[-1][1] > 0 for s in stop_runs): + totals = ", ".join(f"{s[-1][1]:.0f}" for s in stop_runs) + span = (f"{totals} over {len(stop_runs)} boots" if len(stop_runs) > 1 + else f"{stop_runs[0][0][1]:.0f} -> {stop_runs[0][-1][1]:.0f}") + print(f" snap_budget_stops: {span} — the budget " + f"ended that many path-table passes; the walk resumes where it stopped, " + f"so this is the table being bigger than one pass rather than a fault " + f"(docs/api.md)") + # The high-water mark is a peak and not a total, so a reboot in the + # middle of the run cannot hide it the way it hides a counter: max() + # over every sample still reports the worst pass on either side of one. + walk = [v for v in (num(r.get("snap_walk_max_ms")) for r in up) if v is not None] + if walk and max(walk) > 0: + print(f" snap_walk_max_ms: peak {max(walk):.0f} ms — the worst single pass " + f"the Reticulum task spent reading the path table instead of forwarding") + # And whether the node has backed its own passes off, which is the one + # thing here that makes every other reading older than it looks. + # + # Read as a change rather than against 5000, so this file does not carry + # a second copy of the firmware's SNAPSHOT_INTERVAL_MS: the scheduler + # only ever raises the interval above the configured one, so a run in + # which the figure moved at all is a run in which it happened. What that + # misses is a node already backed off before the first sample and still + # backed off at the last — for which snap_walk_max_ms above is the tell, + # and it is printed whenever it is non-zero. + gaps = [v for v in (num(r.get("snap_interval_ms")) for r in up) if v is not None] + if gaps and max(gaps) != min(gaps): + print(f" ⚠ snap_interval_ms up to {max(gaps):.0f} ms (from {min(gaps):.0f}) — this " + f"node measured a pass costing more than a quarter of its window and put " + f"the next one further out; every reading above is that much older than " + f"the sample interval suggests (docs/api.md)") + # The one reading here that is a warning. `paths` is the table's own + # size and is exact on every pass, so a node can report hundreds of + # paths while the list it serves and renders is empty: false here beside + # a non-zero paths is a node part-way through reading its own table — + # it has never got all the way round, or its table has grown past the + # last cycle that did (docs/api.md). + # + # Counted per sample and not per boot, unlike the counter above: this is + # a state and not a total, so a restart does not hide it — the samples + # after one report the state of the node after it. + never = [r for r in up + if not is_blank(r.get("snap_rows_whole")) + and not is_true(r.get("snap_rows_whole")) + and (num(r.get("paths")) or 0) > 0] + if never: + print(f" ⚠ snap_rows_whole false in {len(never)}/{len(up)} samples with paths " + f"in the table — in those samples the node was part-way through reading " + f"its own path table, so the rows /api/status and the panels showed were " + f"the previous cycle's, or none at all if it has never closed one " + f"(docs/api.md)") + def appender(f, path): """A csv.DictWriter for appending samples to `path`, already opened as `f`. diff --git a/tools/tests/fixtures/soak-header.csv b/tools/tests/fixtures/soak-header.csv index 97acf00..5244f1a 100644 --- a/tools/tests/fixtures/soak-header.csv +++ b/tools/tests/fixtures/soak-header.csv @@ -1 +1 @@ -ts,node,reachable,uptime_s,boot_count,boot_reason,boot_clean,prev_uptime_s,heap_free,heap_min,heap_largest,stack_lowest,stack_lowest_task,rx_packets,tx_packets,drop_ring,drop_reasm,drop_partial,crc_errors,bad_length,spurious_irq,paths,links,destinations,announces,neighbours,airtime_long_pct,transport_online,announces_tx,tasks_missing,dram_free,dram_min,dram_largest,announce_interval,cad_timeouts,cad_arm_errors,alloc_failures,faults_contained,fault_last_ms_ago,prev_alloc_failures,prev_contained,power_profile,cpu_mhz,pmu,battery_present,battery_v,battery_pct,battery_charging,tcp_drain_capped,rx_drain_capped +ts,node,reachable,uptime_s,boot_count,boot_reason,boot_clean,prev_uptime_s,heap_free,heap_min,heap_largest,stack_lowest,stack_lowest_task,rx_packets,tx_packets,drop_ring,drop_reasm,drop_partial,crc_errors,bad_length,spurious_irq,paths,links,destinations,announces,neighbours,airtime_long_pct,transport_online,announces_tx,tasks_missing,dram_free,dram_min,dram_largest,announce_interval,cad_timeouts,cad_arm_errors,alloc_failures,faults_contained,fault_last_ms_ago,prev_alloc_failures,prev_contained,power_profile,cpu_mhz,pmu,battery_present,battery_v,battery_pct,battery_charging,tcp_drain_capped,rx_drain_capped,snap_walk_max_ms,snap_walk_pos,snap_budget_stops,snap_rows_whole,snap_interval_ms diff --git a/tools/tests/test_soak.py b/tools/tests/test_soak.py index 096cd76..272f41b 100644 --- a/tools/tests/test_soak.py +++ b/tools/tests/test_soak.py @@ -383,6 +383,154 @@ def test_the_radio_counter_is_taken_off_the_radio_object(self): self.assertNotEqual(blank["rx_drain_capped"], 0) +class TheSnapshotWalkIsRecordedAndRead(unittest.TestCase): + """The columns rx_drain_capped now defers to. `paths` is the path table's + own size and is exact whatever the walk managed, so a run watching it climb + could not tell a node still reading its table from one that had given up on + it. These four are what says which, and the firmware served them while this + script threw them away.""" + + def test_the_snapshot_figures_are_recorded_off_the_tables_object(self): + body = _status() + body["diag"]["tables"] = {"paths": 200, "links": 0, "destinations": 2, + "announces": 0, "snap_walk_max_ms": 412, + "snap_walk_pos": 14, "snap_budget_stops": 96, + "snap_rows_whole": False, "snap_interval_ms": 5000} + with _mocked_node(body): + row = soak.sample("node") + self.assertEqual(row["paths"], 200) + self.assertEqual(row["snap_walk_max_ms"], 412) + self.assertEqual(row["snap_walk_pos"], 14) + self.assertEqual(row["snap_budget_stops"], 96) + self.assertEqual(row["snap_interval_ms"], 5000) + # Encoded like every other tri-state in this file: 0 for a real false. + self.assertEqual(row["snap_rows_whole"], 0) + + def test_a_firmware_that_does_not_serve_them_records_blanks(self): + # And blank is not "the list is a prefix": a node too old to have the + # field did not say the rows were partial, it said nothing. + with _mocked_node(_status()): + row = soak.sample("node") + for key in ("snap_walk_max_ms", "snap_walk_pos", "snap_budget_stops", + "snap_rows_whole", "snap_interval_ms"): + self.assertEqual(row[key], "", key) + self.assertFalse(soak.is_true(row["snap_rows_whole"])) + self.assertTrue(soak.is_blank(row["snap_rows_whole"])) + + def test_a_node_that_has_never_read_its_table_is_a_warning(self): + # The one finding here. A node reporting paths in the hundreds with + # snap_rows_whole false has never got all the way round its own table, + # so the rows /api/status serves and the panels render are empty while + # the count beside them is in the hundreds. + rows = [] + for k in range(4): + body = _status(clean=True) + body["diag"]["tables"] = {"paths": 200, "links": 0, "destinations": 2, + "announces": 0, "snap_walk_max_ms": 402, + "snap_walk_pos": 14, "snap_budget_stops": 20 * k, + "snap_rows_whole": False} + with _mocked_node(body): + rows.append(soak.sample("node")) + text = _summary_of(rows) + self.assertIn("snap_rows_whole false", text) + self.assertIn("snap_budget_stops", text) + self.assertIn("snap_walk_max_ms", text) + + def test_a_reboot_does_not_erase_the_budget_stops_behind_it(self): + # snap_budget_stops counts since boot. Read off the last sample alone, a + # node that stopped hundreds of passes and then restarted reports + # nothing at all — the counter is back at zero and the finding is gone + # with it, which is the one shape a soak run most needs to keep. + rows = [] + for k in range(3): # boot 7: the stops + body = _status(clean=True, count=7) + body["diag"]["tables"] = {"paths": 200, "links": 0, "destinations": 2, + "announces": 0, "snap_walk_max_ms": 402, + "snap_walk_pos": 14, "snap_budget_stops": 100 + 20 * k, + "snap_rows_whole": True, "snap_interval_ms": 5000} + with _mocked_node(body): + rows.append(soak.sample("node")) + for k in range(2): # boot 8: the counter starts again + body = _status(clean=True, count=8) + body["diag"]["tables"] = {"paths": 200, "links": 0, "destinations": 2, + "announces": 0, "snap_walk_max_ms": 402, + "snap_walk_pos": 14, "snap_budget_stops": 0, + "snap_rows_whole": True, "snap_interval_ms": 5000} + with _mocked_node(body): + rows.append(soak.sample("node")) + text = _summary_of(rows) + # Both runs' own totals, per boot, and not a first-to-last range across + # the reset — which would have read "100 -> 0", a counter going + # backwards. + self.assertIn("snap_budget_stops: 140, 0 over 2 boots", text) + self.assertNotIn("100 -> 0", text) + + def test_the_stops_of_a_run_that_never_restarted_read_as_one_range(self): + rows = [] + for k in range(4): + body = _status(clean=True, count=7) + body["diag"]["tables"] = {"paths": 200, "links": 0, "destinations": 2, + "announces": 0, "snap_walk_max_ms": 402, + "snap_walk_pos": 14, "snap_budget_stops": 20 * k, + "snap_rows_whole": True, "snap_interval_ms": 5000} + with _mocked_node(body): + rows.append(soak.sample("node")) + text = _summary_of(rows) + self.assertIn("snap_budget_stops: 0 -> 60", text) + self.assertNotIn("boots", text) + + def test_a_node_that_backed_its_own_passes_off_is_a_warning(self): + # The reading that makes every other one older than it looks: the node + # measured a pass costing more than a quarter of its window and put the + # next one further out (docs/api.md). + rows = [] + for k in range(4): + body = _status(clean=True) + body["diag"]["tables"] = {"paths": 200, "links": 0, "destinations": 2, + "announces": 0, "snap_walk_max_ms": 7500, + "snap_walk_pos": 14, "snap_budget_stops": 20 * k, + "snap_rows_whole": True, + "snap_interval_ms": 5000 if k == 0 else 30000} + with _mocked_node(body): + rows.append(soak.sample("node")) + text = _summary_of(rows) + self.assertIn("snap_interval_ms up to 30000", text) + + def test_a_healthy_node_says_none_of_it(self): + rows = [] + for _ in range(4): + body = _status(clean=True) + body["diag"]["tables"] = {"paths": 3, "links": 0, "destinations": 2, + "announces": 0, "snap_walk_max_ms": 0, + "snap_walk_pos": 3, "snap_budget_stops": 0, + "snap_rows_whole": True, "snap_interval_ms": 5000} + with _mocked_node(body): + rows.append(soak.sample("node")) + text = _summary_of(rows) + self.assertNotIn("snap_rows_whole false", text) + self.assertNotIn("snap_budget_stops:", text) + self.assertNotIn("snap_interval_ms", text) + + +def _summary_of(rows): + """Write `rows` to a CSV under the current header and return what + summarise() printed for it.""" + fd, path = tempfile.mkstemp(suffix=".csv") + os.close(fd) + try: + with open(path, "w", newline="") as f: + w = csv.DictWriter(f, fieldnames=soak.FIELDS) + w.writeheader() + for r in rows: + w.writerow(r) + out = io.StringIO() + with contextlib.redirect_stdout(out): + soak.summarise(path) + return out.getvalue() + finally: + os.unlink(path) + + class ResumingAnOlderCsvKeepsItWellFormed(unittest.TestCase): """Appending a column broke every CSV already in progress. A `DictWriter(fieldnames=FIELDS)` writes a cell per current column whatever