diff --git a/FIX.org b/FIX.org index e95781c..e905151 100644 --- a/FIX.org +++ b/FIX.org @@ -5818,3 +5818,182 @@ whether a game loop calls [(agent/poll)] about a program stopped between runs. Related but separate, and not this: test_reload's "the registry read under a writer" is a reader racing a writer over the allocation registry, about one run in five in isolation, and shares nothing with this but the word intermittent. + +* 2026-09-21 — the registry's flaky read, and why a spin was the bug +test_reload's "the registry read under a writer" case failed about one run in +five on a loaded machine and never on an idle one. The mode behind it is +dev_limits.c's [regfull]: 3100 live blocks in a 4096-slot table, one thread +re-noting them as fast as it can, and the main thread asking the leak question +two hundred times. It wants 200 right answers, no zero-row answers, no wrong +counts and no refusals. + +** How it was reproduced +Not by re-running the test, which takes minutes and fails a fifth of the time. +dev_limits.c was compiled by hand against runtime/flan_rt.c, flan_dev.c and +flan_dyn.c — it is a plain C main, so it needs nothing from the compiler — and +then run twenty-four at a time on a sixteen-core box. Thirty runs on an idle +machine: all green. Two hundred and forty runs under that contention: 46 of +them had at least one refusal, highest count 6 of 200. Zero and wrong never +appeared once, in any run. + +That is also the one inference in this entry worth flagging: the original +failing output from test_reload was never captured, so which of the four +counters had moved is deduced rather than observed. The deduction is safe — +zero and wrong did not occur in ~480 contended runs, and refusals reproduced at +the reported rate — but the next person should know which is which. + +** What the race actually was +A patched copy printed [unread] on every refusal. It was 1 every single time: +exactly one slot, on the best of the eight walks, that could not be copied. +Never the epoch. And in this mode the epoch *cannot* move — compaction needs +[flan_reg_dead >= FLAN_REG_RECLAIM] and re-noting a live block never kills +one, so the dead count sits at zero for the whole run and no rearrangement is +possible. The table under the reader was stationary. The reader refused it +anyway. + +[flan_reg_snap] — runtime/flan_dev.c:1140 before this commit, :1187 after, since +the fix put a block of reasoning above it — read the slot's counter sixty-four +times with nothing between the tries. Two different things leave that counter +odd and they are minutes apart in scale. A writer that is running holds it odd +for seven stores; a bare re-read wins almost at once, and that is the case the +sixty-four were written for. A writer that was *descheduled* in the middle of +those stores holds it odd until the scheduler runs it again — a millisecond or +more when there are more threads than cores — and no amount of re-reading can +end that, because the re-reading is what keeps the core busy. So the reader +spent its entire budget inside a fraction of one quantum, reported the slot as +unreadable, and [flan_dev_reg_by_type] refused the listing. + +The irony is that the file already knew. [flan_reg_scan_wait], the walk-level +pause, is written up at length with exactly this reasoning — "a spin would take +a core from the thread being waited on". The per-slot retry never got it. + +** The fix +One pause helper, [flan_reg_wait], shared by both levels, moved above +[flan_reg_snap]. The slot retry is now eight bare looks — the running-writer +case, which pays nothing — and then the same 250us step, forty tries in all. +A refusal now means the table genuinely would not hold still. + +Not a widened timeout and not a loosened assertion: the design's own contract +is that waiting is legal on the reading side and refusal is for a table that is +being rearranged. A stationary table earning a refusal was the reader lying +about the writer. + +** Proof +Three levels, because the cheap one alone proves the least. + +The direct binary, paired against a build of the same file from the commit +before. Eight copies at a time on sixteen cores: before, 13 of 80 runs +refused; after, 0 of 160. [regchurn] unchanged at 120 runs. [regrace], whose +answered/refused split is the machine's business and is printed rather than +pinned, still never produced a zero-row or a wrong count in 120 contended runs. + +Then test_reload.exe itself, 55 runs, sequential. Sequential is not caution +about load — [tmp] in test_reload.ml is a fixed /tmp/flan-reload-* path, so two +copies would fight over the same host and .so files and invent failures that +look like a regression. + +Fifty-five green runs of a one-in-five flake would be worth having; fifty-five +green runs of a flake that only appears under load, taken on an idle machine, +would be worth nothing, and there is no way to tell the two apart from the +count. So the load for that run was the *pre-fix* binary churning beside it, +which makes it a positive control as well as a load: if it stops refusing, the +window had no race in it and the run proved nothing. It did not stop. In the +same window it managed 50478 runs and 4151 of them refused — 8% — while +test_reload went 55 for 55. + +Machine: 16 cores, load average 15-18 through the run. + +And independently, by the reviewer, on their own machine and harness: 9 of 72 +refused before under 24-way contention, 0 of 120 after, test_reload.exe 20 for +20, and 10 for 10 again on the rebased merge. + +Re-run after the rebase and the [flan_dev_reg_at] change, same control +arrangement: test_reload.exe 25 for 25, with the pre-fix binary refusing 4011 +of the 73306 runs it managed beside it. + +** Two shapes of test_dev flake seen while proving this, neither of them this +Worth recording because the second one does not seem to have a name yet. +Running test_dev.exe six times at load 21 gave three failures. All three were +one shape — [rerun: the program is already running], cascading into every +dev-rerun assertion after it — which is the stale-park in [flan_merged_rerun] +(lib/dev.ml) that has its own lane. + +A second six-run batch, while the load average was still falling from that, +gave two failures of a different shape: a daemon exiting with status 1 or 2 +"before binding /tmp/flan-devtest-*.sock", across most of the daemons in the +file at once. No stale socket or leftover daemon was found afterwards. Six +more runs on a genuinely quiet machine: six green. + +Neither is the registry and neither is this fix. A daemon that dies before it +binds died on the OCaml side of the world, before any program it builds has +run a line of flan_dev.c, and the rerun shape never reads the allocation table +at all. They are noted here only so that the next person who sees red in +test_dev under load has both shapes written down rather than one. + +** It also hardens the address root, which was the same spin +[flan_dev_reg_at] — the inspector's "what block is this address in" — calls +the same [flan_reg_snap] and, unlike the listing, steps *past* a slot it could +not read rather than counting it. That is deliberate and documented: a slot it +could not read either did not hold the block, in which case skipping costs +nothing, or did, in which case the whole call answers "never heard of this +address". With the naked spin, the second branch was reachable under load, so +test_dev's address-root cases could be told an address it had just been given +was not in the table. Nothing was seen failing that way; it is named because +the fix closes it and the next person should not have to rediscover that this +verb shared the defect. + +Review caught that the same function still went bare round its *walk*-level +retries after that — a failed [flan_reg_scan_open] and a failed +[flan_reg_scan_ok] both went straight back to the top. Both wait now. It is +the one site where contention is near-impossible, because the agent gates this +verb behind a stopped program (vendor/agent/flan_agent.c), so the argument for +leaving it is that it cannot matter. The argument against, which won: it is +the same mistake the slot read was making, sitting three lines under the note +that explains why it is a mistake, and a bare retry left in place next to that +note teaches the next reader that the rule has exceptions it does not have. + +** What a refusal costs now, typical and worst, because they are far apart +The first pass through this wrote the new cost as "about sixty-six +milliseconds" and called it a bound. It is the typical case and not a bound, +and the difference is worth having right. The reasoning behind the number is +"one writer, so at most one slot of a walk is odd", which is true at any +instant and false across a walk: [flan_reg_compact] writes every slot under +its own counter, so a writer the scheduler keeps preempting can charge the +full 8ms of patience against several slots of the same walk. The arithmetic +worst case is 4096 of them. Nothing observed comes near it, and a walk paying +it is a walk about to refuse anyway, but the docs now say typical and give the +worst rather than presenting one as the other. + +One consequence of the larger figure, traced in review and recorded rather +than changed: flan_agent.c holds [request_lock] across [handle_line], so a +refusing listing serialises other agent requests — [abort] among them — behind +~66ms where it used to be ~2ms. Nothing depends on the old number. +[over_socket] reads to close with no deadline, [await] defaults to 5000ms, and +[serve]'s two-second timeout is on the read and not on the handling. Written +down so the next person does not have to derive it. + +** The sixty-four were not a short budget; there was no timeout at all +Also from review, and the sharpest way to say why this is a fix and not a +widened timeout. Sixty-four bare re-reads of a single word finish in about two +microseconds. Against a writer that will not be scheduled again for a +millisecond, the old budget was not small — it was zero wall-clock. There was +no timeout in that code to widen. What was added is the first wall-clock +patience the slot read ever had. + +** Not the dev-pause flake, and not the initialiser one either +Two other dev flakes were on the table while this was chased. Neither is this. + +test_dev's "rerun: the program is already running" at high load: nothing in +that path reads the registry. A reviewer has since put a name to it — +[flan_merged_rerun] (lib/dev.ml:4514) answers ok with [program_state] still +PROGRAM_PARKED, so an [await parked] straight after a re-run is satisfied by +the stale park. Its own lane. + +test_dev's edited-initialiser case, which failed once in a full run and passed +the two after: also not this. The race fixed here lives entirely in the +allocation registry's *reading* side, and the only symptoms it can produce are +a listing that refuses and an address root that answers "never heard of it". +It cannot make a global hold a wrong value or an install go missing. Those run +through the by-name table ([flan_dev_cell]) and the install path, which the +program touches from one thread and which share no state with the allocation +table. Three flakes, three causes; one of them is fixed here. diff --git a/docs/BUILT.md b/docs/BUILT.md index bf66114..e3d623f 100644 --- a/docs/BUILT.md +++ b/docs/BUILT.md @@ -5384,13 +5384,37 @@ asking is asking because they suspect the opposite. A slot the writer kept winni would be a leak report quietly missing the leak — and the agent turns a refusal into an `err` line naming how many slots would not hold still, which the daemon already renders as the editor's message. -**And the eight attempts wait between themselves**, which is most of what makes them eight attempts rather than one. -A walk that bails at the epoch check costs almost nothing, so eight of them back to back fit inside the single -compaction they are all losing to. A quarter of a millisecond between them -- `flan_agent.c`'s break-loop idiom, and -legal here because the waiter is the listener thread and never the game loop -- bounds the whole refusal at two -milliseconds, and under a writer churning on top of 3000 live blocks it was the difference between 8 right answers in -200 and 200 in 200. It is not magic: a writer that spends most of its time rearranging the table still gets refused, -which is the honest answer to a question asked of a table that is never still. +**And every attempt waits, at both levels**, which is most of what makes them attempts rather than one. A retry on the +reading side costs a handful of loads, so a whole run of them back to back fits inside the single write they are all +losing to and the reader gives up having waited for nothing. A quarter of a millisecond between them -- `flan_agent.c`'s +break-loop idiom, and legal here because the waiter is the listener thread and never the game loop -- was the +difference, under a writer churning on top of 3000 live blocks, between 8 right answers in 200 and 200 in 200. It is +not magic: a writer that spends most of its time rearranging the table still gets refused, which is the honest answer +to a question asked of a table that is never still. + +**The same pause belongs on the per-slot retry, and its absence was a bug.** `flan_reg_snap` re-read a slot's counter +sixty-four times with nothing between the tries, and the two things that leave a counter odd are minutes apart in +scale. A writer that is *running* holds it odd for seven stores, which a bare re-read wins almost at once. A writer +that was *descheduled* in the middle of those stores holds it odd for however long the scheduler takes to run it again +-- a millisecond or more on a machine with more threads than cores -- and looking again cannot end that, because the +looking is what keeps the core busy. So the reader burned its whole budget inside a fraction of one quantum, called a +perfectly readable slot unreadable, and the listing above it refused a table that never moved at all. It showed up +only under load, which is exactly when a writer gets descheduled: no refusals at all on an idle machine, and one run in +five when the cores were oversubscribed. The retry is now eight bare looks and then the same quarter-millisecond step, +forty tries in all, so a refusal means the table really would not hold still. + +**What that costs, said as a typical and a worst case, because they are far apart.** A refusal used to be bounded at +two milliseconds. It is not bounded any more in the arithmetic sense: eight milliseconds of patience per contended +slot, and although only one slot is odd at any instant -- there is one writer -- a compaction writes *every* slot +under its own counter, so a writer the scheduler keeps preempting can charge that against several slots of the same +walk. The worst case is 4096 of them per walk, which is not a number to design around; the typical case, and every +case measured, is one contended slot per walk and eight walks, so about sixty-six milliseconds. That is still far +under what a person waiting for a keypress to be answered notices, and it is only ever paid by a listing that is about +to refuse anyway. One consequence to know rather than to fix: `flan_agent.c` holds `request_lock` across +`handle_line`, so a refusing listing now delays other agent requests -- `abort` among them -- by that much. Nothing +depends on the old figure (`over_socket` reads to close with no deadline, `await` defaults to 5000ms, and `serve`'s +two-second timeout is on the read rather than on the handling), but a reader of that code should not have to work it +out again. See FIX.org, 2026-09-21. **"At exit" is not a hook, and the honest reason is that a game is killed.** A program stopped by a signal runs no `atexit` handler, no destructor, nothing — so no code written inside the program could report anything about the run diff --git a/runtime/flan_dev.c b/runtime/flan_dev.c index a1cef0f..4564407 100644 --- a/runtime/flan_dev.c +++ b/runtime/flan_dev.c @@ -33,8 +33,9 @@ #include #include #include -/* For the one wait in this file: the pause between a listing's attempts at - * reading the table. See flan_reg_scan_wait. Nothing on the writer's side +/* For the one wait in this file: the pause a listing takes between its + * attempts at reading the table, whether it is waiting out a rearrangement or + * a single slot mid-write. See flan_reg_wait. Nothing on the writer's side * waits for anything. */ #include @@ -1204,6 +1205,56 @@ static void flan_reg_end(flan_reg_entry *e) { __atomic_store_n(&e->gen, (e->gen | 1) + 1, __ATOMIC_RELEASE); } +/* A reader's pause between attempts, and the one wait anywhere in this file. + * + * Retrying immediately looks like several chances and is not. Every retry on + * the reading side costs a handful of loads, so a whole run of them fits + * inside the one write they are all losing to, and the reader gives up having + * waited for nothing. Measured, with a writer allocating and freeing on top of + * three thousand live blocks: without this pause 8 listings in 200 were + * answered and 192 were refused; with it, 200 of 200. + * + * A quarter of a millisecond is well over one compaction, and — the reason it + * is a sleep and not a spin — well over the handover a descheduled writer + * needs. The writer is a game loop and never reaches this; the reader is the + * agent's listener thread, or the exiting program's own, and both of them are + * answering a person. It is [flan_agent.c]'s break-loop idiom, nanosleep a + * step and look again, for its reason too: a spin would take a core from the + * thread being waited on, which on a machine with more threads than cores is + * exactly the thread that has to run before the wait can end. */ +static void flan_reg_wait(void) { + struct timespec step; + step.tv_sec = 0; + step.tv_nsec = 250000; /* 250us */ + nanosleep(&step, NULL); +} + +/* How many times a reader re-reads a slot's counter before it starts waiting + * between the tries instead of going straight round again. + * + * Two different things leave a counter odd, and they are minutes apart in + * scale. A writer that is running holds it odd for seven stores, so a reader + * that simply looks again wins almost at once and a sleep would be pure + * latency. A writer that was descheduled in the middle of those stores holds + * it odd for however long the scheduler takes to run it again — a millisecond + * or more on a loaded machine — and no amount of looking again will end that, + * because the looking is what is keeping the core busy. + * + * That second case is what this constant is for. It was the whole of a + * reproducible wrong answer: with sixty-four bare retries and nothing else, + * the reader burned its entire budget inside a fraction of one scheduler + * quantum, called the slot unreadable, and the listing above it refused a + * table that was perfectly readable and never moved. It showed up only under + * load, which is exactly when a writer gets descheduled — no refusals at all + * on an idle machine, and one run in five when the cores were oversubscribed. + * The sixty-four were not a short budget, which is the part worth being exact + * about: sixty-four bare re-reads of one word finish in about two microseconds, + * so against a writer that will not run again for a millisecond the budget was + * not small, it was zero wall-clock. There was no timeout to widen. + * See FIX.org, 2026-09-21. */ +#define FLAN_REG_SPINS 8 +#define FLAN_REG_TRIES 40 /* 8 spins, then 32 waits: ~8ms of patience */ + /* One slot, copied whole or not at all. 0 means the writer kept winning, which * a caller reports as a slot it could not read rather than as an empty one. * @@ -1219,8 +1270,19 @@ static void flan_reg_end(flan_reg_entry *e) { * program. */ static int flan_reg_snap(flan_reg_entry *e, flan_reg_entry *out) { int attempt; - for (attempt = 0; attempt < 64; attempt++) { - uint64_t g1 = __atomic_load_n(&e->gen, __ATOMIC_ACQUIRE); + for (attempt = 0; attempt < FLAN_REG_TRIES; attempt++) { + uint64_t g1; + /* The wait is only on the path that found a write in flight, so a table + nobody is writing pays nothing for it. There is one writer, so only one + slot is odd at any instant and it is almost always readable on the first + look after the first sleep — which is what a walk typically costs, and + is not a bound. A compaction writes every slot under its own counter, so + a writer the scheduler keeps taking the core from can charge the full + 8ms against several slots of one walk; the arithmetic worst case is + 4096 of them. Nothing observed comes near that, and a walk that is + paying it is a walk that is about to refuse anyway. */ + if (attempt >= FLAN_REG_SPINS) flan_reg_wait(); + g1 = __atomic_load_n(&e->gen, __ATOMIC_ACQUIRE); if (g1 & 1) continue; /* a write is in progress */ *out = *e; /* Ordered before the second read of the counter, or the check is of a copy @@ -1246,32 +1308,12 @@ static int flan_reg_scan_ok(uint64_t at) { return __atomic_load_n(&flan_reg_epoch, __ATOMIC_ACQUIRE) == at; } -/* And a pause between a reader's attempts, which is most of what makes eight - * attempts worth more than one. - * - * Retrying immediately looks like eight chances and is not. A walk that bails - * at the epoch check costs almost nothing, so eight of them back to back fit - * inside the single compaction they are all losing to, and the reader refuses - * having waited for nothing. Measured, with a writer allocating and freeing on - * top of three thousand live blocks: without this pause 8 answers in 200 were - * right and 192 were refusals; with it, 200 of 200. The rate matters and the - * pause is not magic — a writer rearranging the table more than half the time - * still gets refused, which is the honest answer to a question asked of a - * table that is never still, and is what the refusal sentence is for. - * - * Waiting is legal here and only here. The reader is the agent's listener - * thread, or the exiting program's own; the writer is a game loop and never - * reaches this. A quarter of a millisecond is well over one compaction and far - * under what a person waiting for a keypress to answer would notice, and eight - * of them bound the whole refusal at two milliseconds. It is [flan_agent.c]'s - * break-loop idiom — nanosleep a step, look again — for its reason too: a spin - * would take a core from the thread being waited on. */ -static void flan_reg_scan_wait(void) { - struct timespec step; - step.tv_sec = 0; - step.tv_nsec = 250000; /* 250us */ - nanosleep(&step, NULL); -} +/* The pause a walk takes between its own attempts is [flan_reg_wait] above, + * the same one a slot takes: a compaction is what a walk loses to, and it is + * over in well under the step. The rate matters and the pause is not magic — a + * writer rearranging the table more than half the time still gets refused, + * which is the honest answer to a question asked of a table that is never + * still, and is what the refusal sentence is for. */ /* Allocated by flan_dev_reg_enable and null until then, which is the whole of * what a release build carries: a null pointer, a zero flag, and the load and @@ -1636,11 +1678,19 @@ int32_t flan_dev_reg_at(const void *p, const char **type, int64_t *typelen, flan_reg_entry best, cur; int have = 0, attempt; if (!flan_reg_on || a == 0) return 0; + /* The walk-level retries wait between themselves, for [flan_reg_wait]'s + reason and not for this verb's own risk: the agent gates this one behind a + stopped program, so the writer is parked and there is usually nothing to + lose to. Going straight round again would still be the same mistake the + slot read was making — eight walks that all fit inside the one + rearrangement they are all losing to — and leaving one bare retry in the + file next to the note explaining why they are wrong is how the next + person learns the rule has exceptions it does not have. */ for (attempt = 0; attempt < 8; attempt++) { uint64_t at; int64_t i; have = 0; - if (!flan_reg_scan_open(&at)) continue; + if (!flan_reg_scan_open(&at)) { flan_reg_wait(); continue; } for (i = 0; i < FLAN_REG_CAP; i++) { if (!flan_reg_snap(&flan_reg[i], &cur)) continue; if (cur.base == 0) continue; @@ -1651,6 +1701,7 @@ int32_t flan_dev_reg_at(const void *p, const char **type, int64_t *typelen, } if (flan_reg_scan_ok(at)) break; have = 0; + flan_reg_wait(); } if (!have) return 0; if (type) *type = best.type; @@ -1733,7 +1784,7 @@ int64_t flan_dev_reg_by_type(int32_t live_only, int64_t *counts, uint64_t at; n = 0; missed = 0; - if (!flan_reg_scan_open(&at)) { flan_reg_scan_wait(); continue; } + if (!flan_reg_scan_open(&at)) { flan_reg_wait(); continue; } for (i = 0; i < FLAN_REG_CAP; i++) { flan_reg_entry e; int64_t j; @@ -1761,14 +1812,14 @@ int64_t flan_dev_reg_by_type(int32_t live_only, int64_t *counts, } n++; } - if (!flan_reg_scan_ok(at)) { flan_reg_scan_wait(); continue; } + if (!flan_reg_scan_ok(at)) { flan_reg_wait(); continue; } /* A stable epoch and every slot copied: this is a table that existed. */ if (missed == 0) return n; /* A stable epoch but slots that would not hold still. Worth another walk — the writer moves on — and worth remembering the closest one, because it is the number the refusal quotes. */ if (fewest < 0 || missed < fewest) fewest = missed; - flan_reg_scan_wait(); + flan_reg_wait(); } /* Eight walks, and not one of them saw the whole table. Answering with the last walk's rows would be answering with a table that never existed, and