Phase 6 — the residual load, and the regression¶
Master plan: PLAN-database-load-reduction.md
Status: In progress. 6a, 6b, 6c, 6d, 6e and 6f are done; 6g (re-measurement after deploy) is outstanding and needs a full 24h window on sfcbr. What the work actually found is recorded in "Findings" below, which corrects this plan's own survey in two places.
Why this phase exists¶
Phases 1-5 took steady-state sf-database load from ~527/s to 89-92/s, below this plan's "under 100 operations per second" success criterion, measured 2026-08-05 to 2026-08-07. It has since climbed back to ~142/s (2026-08-18). That is not object-count scaling: on 2026-08-09 the cluster ran 98.0/s carrying a 24h-mean 15.24 standing instances, and on 2026-08-18 it ran 142.3/s carrying 12.48. More load, fewer objects.
So this phase has two jobs which are easy to confuse and must not be: find and fix what regressed, and reduce the residual floor that was always there and that phase 5 deliberately did not chase. The first is a bug hunt with a known-good reference point eleven days back. The second is ordinary optimisation.
What the survey found (2026-08-19)¶
Numbers are 24h-averaged per (operation, caller_daemon) from
database_requests_total, the phase 4 counter, as recorded in the nightly
facts for 2026-08-18. scaled baselines are per-standing-instance
coefficients established by the hunt described in the phase 5 plan.
| Pair | 24h QPS | Defended ceiling | Verdict |
|---|---|---|---|
GetObjectState / cluster |
18.95 | 10.5 (absolute, on-phase) | regressed |
GetObjectState / net |
11.47 | 7.67 (scaled) | healthy |
GetReservation / net |
10.09 | 8.4 (absolute) | healthy, but is #3655 |
GetReferencesFrom / api |
6.86 | 3.99 (scaled) | regressed |
GetNodeDaemonState / (7 daemons) |
~20 aggregate | 2.1 each | at the designed floor |
| everything below the top 40 | ~22 aggregate | none | unwatched |
Total 142.3/s across 401 distinct pairs; the top 40 account for 120.2/s, so ~22/s is spread across ~361 pairs that no baseline watches individually and that are individually too small to be worth a baseline.
The GetObjectState/cluster loop is the cluster maintenance sweep¶
Hunt 2026-01 characterised this as a "deploy-bracketed on/off loop" (~10 QPS continuously between certain deploys, ~zero otherwise, ~900k queries per observed on-phase) but never identified the owning code, so it was never filed. The survey places it, and the "on/off" framing now looks like an artefact of measuring a duty cycle rather than a rate:
ClusterDaemon._run_inner()
(shakenfist/daemons/cluster/main.py:568) gates all maintenance behind
if now - last_loop_run >= 60, and sets last_loop_run = now where now
was captured before the pass ran (:630, :652). The pass is
therefore scheduled every 60 s from its own start, so its duty cycle is
min(1, pass_duration / 60) — and once a pass exceeds 60 s the loop runs
back to back with no idle time at all. _cluster_wide_cleanup() (:76)
walks, per pass, every active IPAM, every in-use floating address, every
artifact, every blob and every namespace key, reading state for each.
Direct evidence from the sfcbr journals (RecordedOperation('cluster wide
cleanup', threshold=10) logs any pass over 10 s):
- Over six hours on 2026-08-19, six passes exceeded 10 s; the rest were faster. Durations 11.8, 13.4, 15.5, 33.9, 14.5, 16.6 seconds.
- The last three of those are consecutive minutes (17:10:29, 17:11:03, 17:12:10) — the loop briefly running nearly continuously, which is the shape the hunt's "on-phase" describes, in miniature.
- Separately, the same loop logs ~30
deleting this namespace key because it expiredaudits every 15-16 minutes, sustained. Something is minting short-lived namespace keys at roughly 2/minute and this loop is reaping them — which is very likely the same phenomenon as the unfiledPOST /authfinding below, seen from the other end.
At 18.95 QPS against a 60 s cycle the sweep is issuing roughly 1,140
GetObjectState calls per pass. The question phase 6 must answer is not
"where does this come from" — it is _cluster_wide_cleanup() — but
"why has the per-pass object count grown, and which of those state reads
does the sweep actually need".
Also noted while reading: _cluster_wide_cleanup() takes a
last_loop_run argument (:76, passed at :648) which its body never
uses. Dead parameter; delete it while in there.
GetReservation/net is #3655, filed and unfixed¶
The one item in this phase that is already fully diagnosed. Issue #3655
(open) records that the floating-IP maintenance path sweeps every in-use
address reservation three times per 30 s cycle. The call sites confirm it:
shakenfist/daemons/network/maintain.py:533,
shakenfist/daemons/network/floating_ip_reaper.py:82 and :137, and
shakenfist/daemons/cluster/main.py:134 — each an
fn.ipam.get_reservation(addr) inside a for addr in ...in_use loop,
which is one RPC per address per sweep. mariadb.py has no bulk form;
get_reservation() (:6418) is single-address only.
GetReferencesFrom/api climbed above its per-instance ceiling¶
Flagged regressed on 7 of the last 8 nights, peaking at 13.28 on
2026-08-15. The scaled ceiling says the API should issue 0.32 of these per
standing instance; it is issuing about 0.55. references_from is populated per
object inside external_view(), one RPC each, at
shakenfist/instance.py:653, artifact.py:610, blob.py:305 and
node.py:448 — where the node path issues two, one keyed by fqdn and
one by uuid. A list endpoint therefore costs one (or two) of these per
object returned, so either a list endpoint grew the field or something is
polling one harder than it used to. Note #3654 fixed the directly
analogous defect for GetInstanceAttributes by memoising within
Instance.external_view() (instance.py:563) — check first whether
references_from in the same function was simply missed.
The POST /auth re-authentication storm was never filed¶
Hunt 2026-01 measured ~45% of "mutating" API background traffic as bare
POST /auth token acquisition — activity-independent, and disguising idle
hours in every API-side measurement. It was characterised at the API log
level but never attributed to a client, so it was never filed upstream and
exists only in the hunt's verdict document. The namespace-key expiry
cadence above is a second, independent sighting of what may be the same
behaviour. Clients are in a separate repository
(shakenfist_client, in client-python), so a fix may well land there;
the attribution work is here.
Success criterion 2 is probably wrong¶
Recorded as open question 5 on the master plan. get_node_daemon_state is
now the second operation by rate, at ~20/s aggregate — but that ~20/s is
exactly 48 daemon processes polling at the 0.5 Hz that phase 1 chose, and
it is second only because everything around it got much cheaper. Phase 6
should resolve the criterion rather than chase the number.
Decisions¶
- Separate the regression from the floor. The 2026-08-07 nightly
facts are a known-good reference point with per-pair detail. Any pair
materially above its 2026-08-07 value is regression work; anything at
or below it is floor work. Do the regression work first — it is
bounded, it has a bisection window of about eleven days of
develop, and the floor was already judged acceptable at 89-92/s. - Do not add a cache for anything mutable. Decision 2 of the master
plan still holds and this phase does not reopen it.
GetObjectState,GetReferencesFromandGetReservationare all mutable reads. The levers available are: do not ask, ask once per pass instead of once per object (the #3654 and #3502 pattern), or push the filter into SQL so one RPC answers what N did. - Prefer pushing work into SQL over batching in Python. Per the project's standing preference for filter pushdown, a sweep that needs "every X whose state is deleted and older than N" should ask MariaDB that question once, not hydrate every X and test in Python. This is also what makes the fix survive object-count growth rather than merely moving the constant.
- The long tail gets a budget, not 361 baselines. ~22/s across ~361 pairs is real but individually unattributable, and per-pair ceilings there would be pure noise. It is bounded in aggregate by phase 7's model instead. This phase's only obligation to the tail is to check that no single pair in it is a new fixed-rate poll in disguise.
- File before fixing, for anything not already filed. The
GetObjectState/clusterloop and thePOST /authstorm have both now survived one full investigation without being filed, which is how they came to be rediscovered here. They get issues as the first act of this phase, whether or not they are fixed within it.
Step plan¶
| Step | Effort | Model | Isolation | Brief for sub-agent |
|---|---|---|---|---|
| 6a | high | opus | none | Bisect the regression. Do not write code. The cluster ran 89-92/s on 2026-08-05..07 and ~142/s on 2026-08-18 at a lower standing instance count, so something merged in between. Pull the per-pair nightly facts for 2026-08-05 through 2026-08-18 and diff them pair by pair, normalising per-instance pairs by that night's instances_day_mean (the coefficients are in the phase 5 plan and the hunt verdict). Produce a ranked list of pairs by QPS added since 08-07, which will not be the same ranking as by absolute QPS. Then git log --oneline --since=2026-08-05 --until=2026-08-19 origin/develop and correlate: for each pair that grew, name the candidate commits that touch its call path. Deliverable is a written attribution, not a fix — and an honest statement of which growth is unattributed. Note that the 08-08 spike (140.5/s at 35.79 instances) is object-count scaling and is not evidence of the regression; the regression is that 08-18 sits at 142/s with a third of those instances. |
| 6b | medium | sonnet | none | File the two unfiled findings. Two GitHub issues, each carrying the measured numbers, the repro PromQL, and the call sites from this plan's survey — so neither can be lost a third time. Issue one: the cluster maintenance sweep's GetObjectState cost (~19 QPS, daemons/cluster/main.py:76 and the 60 s duty-cycle gate at :630/:652), including the pass-duration evidence and the observation that the loop runs back to back once a pass exceeds 60 s. Issue two: the bare POST /auth re-authentication volume (~45% of mutating API background per hunt 2026-01), stating explicitly that the client attribution is not done and is the first task on it. Apply the automated-fix-attempted label to both at filing time if this phase intends to fix them in-flight, so the issue autofixer does not race a branch. |
| 6c | high | opus | worktree | Fix #3655: bulk-read floating IP reservations. Four call sites each issue one get_reservation() RPC per in-use address inside a sweep: daemons/network/maintain.py:533, daemons/network/floating_ip_reaper.py:82 and :137, daemons/cluster/main.py:134. Add a bulk accessor to mariadb.py beside get_reservation() (:6418) that returns every reservation for an IPAM in one call — follow the three-layer pattern exactly (_direct_*, _grpc_*, public, a proto message, tox -e genprotos, and a database_*_total counter like its neighbours) and read PLAN-grpc-bounded-replies.md first, because an all-reservations reply is exactly the unbounded shape that plan exists to stop: bound it, and say in the plan how. Convert all four sweeps to one bulk read per pass. Expected effect ~8-9 QPS. Add a functional test in cluster_ci_tests/test_database_tier.py asserting the count, modelled on test_instance_get_fetches_the_attributes_row_once which already does exactly this shape for #3654. Commit subject: "net: read floating IP reservations in one pass." Fixes #3655. |
| 6d | high | opus | worktree | Reduce the cluster maintenance sweep's state reads. Depends on 6b's issue. _cluster_wide_cleanup() (daemons/cluster/main.py:76) reads object state per swept object across five populations. Per decision 3, convert the state-filtered walks into SQL questions: the IPAM walk (:114) discards everything whose state was updated within 300 s after hydrating it; the floating-address walk (:132) reads obj.state per reservation to find deleted-and-aged users; the artifact walk (:168) hydrates a namespace per artifact. mariadb.get_objects_by_state() and the orphan-reconciliation queries in mariadb.py are the existing precedent for asking MariaDB instead. Measure before and after with the CI harness, not by inspection. Also delete the unused last_loop_run parameter (:76, :648). Do not change the 60 s gate or the duty-cycle behaviour in this step — that is a separate judgement about maintenance latency and belongs in its own commit if it is wanted at all. |
| 6e | medium | opus | none | Diagnose GetReferencesFrom/api. It is running at roughly 0.55 per standing instance against a 0.32 ceiling and has been flagged 7 nights of 8. First check the cheap hypothesis: #3654 memoised GetInstanceAttributes within Instance.external_view() (shakenfist/instance.py:563), and references_from (:653) may be the same defect left unfixed in the same function. If so, fix it the same way and add the same style of CI assertion. If not, find which endpoint grew the read; the call sites are instance.py:653, artifact.py:610, blob.py:305 and node.py:448 (the last issuing two RPCs per node, keyed by fqdn and by uuid — worth collapsing regardless of what this step concludes). Report before fixing if the cause turns out to be a caller polling harder rather than an endpoint doing more work — that is a different fix in a different repository. |
| 6f | low | sonnet | none | Resolve success criterion 2. Master plan open question 5. Replace "get_node and get_node_daemon_state no longer appear in the top five operations by rate" with a criterion that survives the thing phase 1 actually did: get_node gone entirely, and get_node_daemon_state at or under the arithmetic floor implied by DAEMON_STATE_POLL_INTERVAL for the cluster's daemon-process count. Edit the master plan's success criteria and close the open question with the resolution recorded inline, in the style of the other resolved questions there. |
| 6g | high | opus | none | Re-measure and record. After 6c-6e deploy to sfcbr, wait for a full 24h window and record the new per-pair numbers in this plan the way phase 5's outcome section does — including any target that did not move, which per the master plan's measurement discipline is a finding rather than a detail. Then update the committed load baseline so the improved floor is the defended one, and state plainly whether the plan's under-100/s criterion is met again. If it is not, say by how much and what is left. |
Risks and mitigations¶
- Chasing the floor instead of the regression. The absolute ranking
puts
GetObjectState/clusterfirst, but the growth ranking may put something else first, and the growth is what broke the criterion. Mitigation: 6a is a pure attribution step, deliberately produces no code, and normalises for instance count before ranking. - A bulk reservations reply is unbounded. 6c replaces N small RPCs
with one large one, which is exactly the failure mode
PLAN-grpc-bounded-replies.mdexists to prevent, and sfcbr has already crossed the gRPC message limit twice (#3638). Mitigation: the step requires reading that plan and bounding the reply as part of the design, not as a follow-up. - Pushing filters into SQL without the index. Decision 3's SQL pushdown makes things worse, not better, if the predicate has no index to use — moving load from the gRPC tier onto MariaDB is not a win. Mitigation: every new predicate in 6d states which index serves it, and adds one if none does; this is a standing project rule.
- The sweep changes alter cleanup semantics. 6d touches code that deletes IPAMs, releases addresses and removes artifacts. A wrong predicate deletes live objects. Mitigation: worktree isolation, and the sweep's behaviour is covered by functional CI (which exercises full object lifecycles) rather than by unit tests alone.
- The regression is not ours. It may be a change in what runs against
sfcbr — CI shape, conductor behaviour, a client — rather than a change
in Shaken Fist. Mitigation: 6a is required to say so explicitly if the
growth does not correlate with any
developcommit, and that answer ends the phase's regression thread rather than prolonging it.
Definition of done¶
- The regression is attributed: every pair that grew materially since 2026-08-07 is either explained by a named change, explained by standing object count, or explicitly recorded as unattributed.
-
3655 is fixed and closed, with a functional-CI assertion that the¶
reservation sweep issues one bulk read per pass rather than one per address. - The cluster maintenance sweep's
GetObjectStatecost is reduced, with before-and-after numbers from a 24h window recorded in this file. - The
GetObjectState/clusterloop and thePOST /authvolume are filed as issues with their measured numbers, whether or not they are fixed here. GetReferencesFrom/apiis either back under its per-instance ceiling or its cause is documented as living outside this repository.- Master plan success criterion 2 is restated and open question 5 closed.
pre-commit run --all-filesgreen; functional CI green.- The 24h cluster total is recorded honestly against the under-100/s criterion, met or not.
Back brief¶
Before executing any step, back brief the operator: which of the two jobs (regression versus floor) the step belongs to, what the step will measure before it changes anything, and — for 6c and 6d — what the reply-size and index consequences of the chosen approach are.
Findings (2026-08-19)¶
6a — the regression is two things, and only one of them is a defect¶
Diffing the per-pair nightly facts for 2026-08-07 (92.4/s, the last night under target) against 2026-08-18 (142.3/s) gives a total delta of +49.9/s. It decomposes:
~+19/s is a real defect — GetObjectState/cluster went from below
the top-40 cutoff to 18.95/s. It is 38% of the whole regression in one
pair. Diagnosis below.
~+12/s is node count, not regression. The per-node fixed-rate pairs
all grew by almost exactly 50% on 2026-08-12: Dequeue/net 2.03 to 3.04,
GetBlobTransfersForNode/transfers 2.03 to 3.04, and every one of the
seven GetNodeDaemonState pairs 1.99 to 2.98. GetNodeDaemonState is
one read per DAEMON_STATE_POLL_INTERVAL per daemon per node, so its rate
divided by the poll interval is a node count: it reads 3.9 nodes before
2026-08-12 and 5.8 after. The cluster gained two nodes.
That is the most important finding for phase 7, and it is a gap in the model rather than a bug in the code: the ratchet's baselines scale with standing instance count but not with node count, so growing the cluster reads as a regression on every per-node pair simultaneously. Phase 7's budget must carry a per-node term. It already plans to; this is the evidence for why that is not optional.
The remainder is instance-count movement and the long tail (330 to 401 distinct pairs).
The GetObjectState/cluster diagnosis — and a correction¶
This plan's survey attributed it to _cluster_wide_cleanup() and its 60
second duty-cycle gate. That was wrong, and the correction is worth
recording because the reasoning looked sound.
The raw counters settle it. database_requests_total for this pair steps
in a burst every ~16 minutes on both database nodes — +7,614 and +7,604 at
18:38, +7,610 and +7,615 at 18:54 — against a continuous baseline of
~1.3/s. That is ~15,200 calls in a single burst every 15 minutes.
15,200/900 = 16.9/s, exactly the observed 24h average. The 60 second sweep
is the 1.3/s baseline, not the 17.
The 15-minute cadence identifies it as a schedule.every(15).minutes job,
and it is reap_expired_namespace_keys()
(shakenfist/daemons/cluster/scheduled_tasks.py). It walked every expired
key and read key.state.value per key — an uncached round trip each, since
.state is a property with no memoisation (baseobject.py:536) — purely
to discard the ones it could not act on. keys_with_attributes()
deliberately does not filter on object state (its docstring says so, and
adds that "any future soft delete path must revisit that"; this sweep is
one), so every key the sweep had already soft deleted stayed in its input
until hard deletion caught up, and every stateless zombie key stayed there
forever.
That also explains the shape the earlier investigation could not: the nightly numbers ramp monotonically (0, 2.82, 4.60, 10.45, 14.45, 16.21, 18.95) rather than switching on and off. It was a backlog growing, not a loop toggling. The "deploy-bracketed on/off loop" characterisation was an artefact of sampling.
Fix: one get_objects_by_state() query per pass for the keys in an
actionable state, and a set membership test in the loop. The zombie
counting this sweep used to do is dropped: reconcile_orphaned_objects
owns stateless rows and already counts them hourly.
6c — the bulk accessor already existed¶
The step brief anticipated adding a bulk reservation RPC through all three
layers, with a proto change and a reply-size design. None of that was
needed: mariadb.get_reservations_for_ipam() already exists and is already
used by IPAM.get_haloed_addresses(). The change is an
IPAM.get_all_reservations() helper over it and four call-site
conversions. Reply size is unchanged from a call already made on this path.
The reaper conversion also removed a second read per address —
get_allocation_age() was itself a get_reservation() — and fixed a
latent crash: for an in-use address with no reservation row,
get_allocation_age() returns None and the old code evaluated
now - None. That address is exactly the leak the sweep exists to find,
so it now falls through to the leak path rather than raising.
6e — GetReferencesFrom/api is not an endpoint defect¶
The cheap hypothesis was wrong: Instance.external_view() already issues
exactly one get_references_from per view, inside the attribute_memo()
that #3654 added. There is no per-view duplication to remove.
Per this step's brief, reporting rather than fixing: the growth is request
volume, and it correlates with the same 2026-08-12 node-count change. Two
more nodes means more concurrent CI, which means more API polling, and the
/instances list endpoint costs one reference read per instance returned —
so its cost scales with instances times poll rate while the ratchet's
coefficient captures only instances. Same model gap as above, seen through
a different pair. No code change here.
One real but small duplication was confirmed and left alone: the node
external view issues two get_references_from calls, keyed by fqdn and by
uuid (shakenfist/node.py:448), because BLOB_LOCATION rows key nodes by
fqdn and INSTANCE_LOCATION rows by uuid. Collapsing it needs an IN
variant at the SQL layer and is worth ~4 calls per sweep. Not worth the
change on these numbers.
Deviation from the step plan¶
Step 6c's brief called for a functional-CI assertion modelled on
test_instance_get_fetches_the_attributes_row_once. The sweeps this phase
fixes are fixed-rate timers, not API-triggered, so a functional assertion
would have to sleep through two sampling windows either side of floating
several addresses — around three minutes of wall clock, for a measurement
that would still be noisy on shared CI hardware. Unit assertions on the
sweep functions are exact, instant, and can assert the thing that actually
matters (that the read count does not grow with address count). Both new
guards were mutation tested: re-introducing the per-address read fails
them, and the first version of the namespace-key guard did not fail and
was rewritten until it did.