docs(plan): the gap is decode, not scheduling - #206
Conversation
Measured against the live prod journal and prod tiers on 2026-08-19. 1h contiguity is stuck at 2 because ~4.9 TB of base-tier decode across 08-06..08-14 has not happened, not because the scheduler picks the wrong task. The proof loop that refuses to derive 1h for those days is CORRECT and must not be 'fixed' -- it refuses because the 1m tier genuinely is not built. ~26 TB pending across all sources and 211 project-days. Records an implemented-and-rejected fix (split children inheriting the parent's scheduling width), which made the blocking day's rank WORSE (5,375 -> 12,940) despite a green regression test -- and the offline comparator replay that caught it before a deploy. Also three corrections (derived_refusal is a sample not a veto; sealed work is not starved to zero; attempts resets on split) and two measurement traps (docker logs --since only reaches the current container; a deploy every 15-20 min invalidates throughput numbers).
ReviewThis is a docs-only PR (one new file, Strengths
Nits / things worth double-checking before merge
Nothing here blocks merging — it's a well-evidenced, honest writeup (including the negative result), consistent with the rest of the |
The gating days are already consolidated (34-53 complete each) and still estimate 200-800 GB of decode, so compaction is not the lever -- it cuts file count, not decoded bytes. And the rollup estimate is projection-aware exactly as dedup's is, over a genuinely narrow column set, so it is not inflating the TB or causing the over-splitting. That leaves the ~4.9 TB as real irreducible decode: the levers are decode THROUGHPUT (why so few bytes/sec, not how many bytes) and not restarting mid-unit.
|
Correcting the most actionable claim in this PR before anyone acts on it. I originally wrote that compacting a day before rolling it up was the main lever. That is wrong, and so is the follow-up hypothesis I tested after it. 1. Compaction is not the lever — the gating days are already compacted.
Consolidation has essentially finished for 08-06..08-15 and the estimate is still 200-800 GB/day. Consolidation cuts file count (file-open overhead, planning cost), not decoded bytes, which is what a rollup pays to aggregate every row once. 2. The estimator is not inflating rollups. It would have been a tidy story — a full-row estimate over a narrow rollup projection would both overstate the TB and over-split units (the 928 fragments). It is false: the rollup path scales by projection exactly as dedup does, over a genuinely narrow column set ( So the ~4.9 TB is real, projection-aware, irreducible decode. The remaining levers are decode throughput — the question becomes "why so few bytes/sec", given |
…straint 128 units in 20 minutes carried 9.11 GB of estimated decode. That is 7.6 MB/s effective, so the 4.9 TB of gating work needs ~7.5 days uninterrupted and full convergence ~40 days. ~0.5 MB/s per worker is pathologically slow for decode -- a sequential object read streams 50-100 MB/s -- so the constraint is per-file request latency, not CPU or bandwidth. Matches the 408 file-opens/sec at ~389ms finding and scan_ms=481682 for a unit producing 142 rows.
|
Measured the binding constraint: decode throughput is 7.6 MB/s. 128 units published in 20 minutes carried 9.11 GB of estimated decode: That window spans a restart, so 7.6 MB/s is effective throughput including restart overhead — the right basis for an ETA, though the instantaneous rate is higher. Across 16 workers that is ~0.5 MB/s per worker, which is pathologically slow: a single sequential object read should stream 50-100 MB/s. So the constraint is per-file request latency, not CPU and not bandwidth. That matches the earlier This is the number to attack, and everything else in the PR is downstream of it. It also gives the honest answer to "have we caught up": at the current effective rate, no — ~7.5 days of uninterrupted running for the days that gate 1h contiguity, and restarts every 15-20 min mean the effective figure is worse than that. |
ReviewThis PR adds a single docs-only file: Code references check out. I diffed the two inline snippets against current
Good practice: pulling real code into the doc rather than paraphrasing it means it'll visibly rot (and get caught in review) if the referenced logic changes later. Strengths:
Minor points, non-blocking:
No functional/test-coverage/security/performance concerns since this is a docs-only change — nothing here executes. Overall a well-evidenced postmortem-style doc that earns its length; recommend merging as-is. |
|
The next step is blocked on something non-technical: prod needs a quiet window. Eight images today ( Why it matters now. The binding constraint is 7.6 MB/s decode (~0.5 MB/s per worker), and the leading hypothesis is that the Foyer data cache is not on the read path: The cache is populated (125 GB on disk, written today) and evicting, but the read counters are flat — the same signature as the previously-recorded "foyer main tier served ZERO reads for weeks" regression. This is not provable from a 60-second-old process, since those counters are per-process and maintenance may simply not have read yet. It is a hypothesis, not a finding. What would settle it: one container left alive ~30 minutes, then SELECT component, key, value FROM timefusion_stats
WHERE component IN ('foyer','foyer_metadata','hot_tier');If Given ~7.5 days of uninterrupted decode is needed for the gating days anyway, batching merges and leaving prod alone is currently worth more than any further code change — it is both the measurement precondition and the cheapest throughput win. |
CONFIRMED: the main Foyer data cache serves zero readsThis is the cause of the 7.6 MB/s, and it is now a finding rather than a hypothesis. One process, one
Ruled out — instrumentation gap. Both rows come from the same struct and the same rendering code in [("foyer", s.stats.main), ("foyer_metadata", s.stats.metadata)]
.into_iter()
.flat_map(|(component, st)| rows![component; "hits" => st.hits, ...])Identical fields, identical path; only the instance differs, and Ruled out — the wide-scan bypass. Reproduce in 30 seconds: run the stats query above, then a bounded query that really reads parquet (I used a 1-day count on Why this dwarfs everything else in this PRDecode is 7.6 MB/s — ~0.5 MB/s per worker across 16 — against 50-100 MB/s for a sequential object read. If every parquet read misses a cache that is never consulted, the ~100× gap is explained with no other cause needed. 120 GB of disk and 4 GB of RAM are being spent to populate something nothing reads. It also means every scheduling change of 08-17..19, mine included, was reordering work bottlenecked on object-storage latency. Honest caveatI have not yet located the line where readers get an unwrapped store. What is established is the behaviour and its sufficiency. Next step is comparing the construction sites — start from This has happened beforeThere is a prior recorded incident of "foyer main tier served ZERO reads for weeks". Either it regressed or was never fully fixed — worth an assertion or alert on |
Measured properly: the cache is HEALTHY, and the latency framing was wrong tooGot the authoritative log line (fed by This confirms the retraction — the data cache is not dead, it is running at a 96.6% hit rate — and it also invalidates my "~100× too slow, per-file-latency-bound" framing from earlier in this PR. In a ~4-minute-old process the box pulled 37.4 GB from object storage and served 32 GB from cache, i.e. on the order of 150 MB/s. Object-storage latency is therefore not the constraint, and neither is cache effectiveness. What that means for the 7.6 MB/sThe 7.6 MB/s is real but I mis-framed what it measures: it is rollup progress (published units × So the question is no longer "why is IO slow" — it isn't — but "why does maintenance convert so little of the available read capacity into rollup progress?" Candidates, none yet tested:
Running correction count in this PRThree of my conclusions have now been overturned by better measurement: the split-priority fix (rejected by journal replay), the dead cache (retracted — diagnostic artifact), and the latency framing (refuted by the cache log). Each was self-consistent from one instrument. The surviving facts are the ones measured two independent ways: the ~4.9 TB / ~26 TB decode gap, the 1m-complete → 1h-derivable chain, and that scheduling is not the lever. |
Prod is also OOM-killing itself — interval has shortened to ~2.4hNot all of today's restarts were deploys. Two Same signature as the recorded series (~125 GB anon, exit 137, Combined with 9 distinct images deployed, prod has restarted roughly 11 times in ~3 hours. Why this matters for the rollup goal specificallyA rollup unit's scan phase alone is ~8 minutes and debt units run 12-15. At ~15-minute mean time between restarts, a large fraction of maintenance work is discarded before it commits — so the ~4.9 TB gating backlog is being re-attempted rather than drained, and every throughput number in this PR (including my 7.6 MB/s) was measured against a process younger than 20 minutes. This also means "leave prod alone" is not sufficient on its own — the OOMs will keep restarting it regardless of merge cadence. The shortened interval looks like a regression worth its own investigation; the driver is the query path, which is consistent with the previously-recorded attribution to bulk INSERT / wide scans rather than maintenance. |
Possible contributor to the shortened OOM interval: oversize scan rate is upA 48-second sample on the current container: Caveat: 48 seconds is a small, possibly bursty sample — treat the rate as indicative, not precise. The largest single scan is smaller than the 32.8 GB previously recorded, so the shift looks like more frequent, smaller-but-wide scans rather than one catastrophic query. Two things worth noting:
I am not claiming this is the OOM cause — the driver is the query path ( |
Live demonstration: 149 units published, depth +3 days, contiguity +0Fifteen minutes on a container that finally survived, same image: This is the clearest evidence in this PR that throughput is not the constraint and depth is not the goal. Work is flowing, historical days really are being filled, and G1 does not move. Why, structurally
So filling scattered project-days raises depth indefinitely while the consecutive run stays pinned behind the first gap of the worst tenant. The worst project for 1h has meanwhile shifted from What this implies for the fixTo move contiguity you have to drive the worst project's newest missing day to completion, then the next one back. That is a goal-directed selection property; it cannot be expressed by any per-task attribute — width, recency, age, or backfill provenance. Which is precisely why every ordering change this week (the reservation, coarsener, fuser, occupancy cap, and my rejected width fix) raised throughput or reordered the queue without moving G1. If anything is worth implementing next, it is enqueue selection keyed on "which day would extend the worst project's run", not another comparator term. And it should be validated the same way the width fix was killed — by replaying against the real journal before deploying. |
The two days that actually gate G1 — and the 1h one is not a throughput problemDepth has essentially reached goal (1m = 30 days, 1h = 19) while contiguity sits at 5 and 2. The entire gap is one missing project-day per tier: Thin days still count — 08-15 has only 5,747 buckets for The two blockers have completely different causesThe 1h tier — the one that governs 14d/30d dashboard latency — is blocked by a day where every unit completed and nothing was published. No amount of decode throughput fixes that. It is either:
I could not settle which: the raw-table query to check for source rows on that day hit the statement timeout, and I am not willing to retry something heavier against a box that OOMed twice today. Why this reframes the whole PRThe 26 TB / 7.6 MB/s analysis above is accurate but describes the 1m tier's backlog. The metric everyone is watching (1h contiguity) is gated by one project-day whose work is already done. Distinguishing (1) from (2) is a few minutes of work and is worth far more than any throughput change — and if it is (2), the fix is to the metric, not to the system. |
Settled: the 1h blocker is a METRIC ARTIFACT, not missing workAnswered from the journal's own The tenant has essentially no data that day. That matches its 1-2 rows/day in the 1h tier generally. Every unit ran, completed, and correctly found nothing to aggregate. So this is case (2) from my previous comment: empty partitions read as coverage gaps — the item already anticipated in the architecture plan. Why this matters more than anything else in this PR
So 1h contiguity = 2 substantially misrepresents real coverage. Meanwhile the 1m tier is 31 days deep with its run intact back to 07-21 behind a single genuine hole ( What I would change
Until (1) is fixed, G1 is not a reliable target to optimise against — which retrospectively explains a good deal of this week: work was being directed at a number that a quiet tenant can pin at 2 no matter what the system does. |
Correction to my previous comment: it is not purely a metric artifactI said the 1h blocker was "a metric artifact, not missing work". That overstated it. Digging into the slices: So there is a real coverage gap: derived hourly units were minted for only 14 of 24 hours, and if that single row falls in the 01:00–10:00 window nothing could ever aggregate it. The accurate account is three things compounding:
(3) is still the dominant term and the recommendation stands — a day whose source is empty or trivially small should not be able to pin the fleet metric at 2, and the worst project has already migrated once today. But (2) is a genuine defect worth a look on its own: why does a day get derived units for 14 hours and not 24? That same minting gap on a tenant with real traffic would be a much larger hole. Apologies for the churn — that is the fourth correction in this PR. The pattern in all four is the same: a clean story from one slice of evidence, published before checking the adjacent slice. |
Retracting correction (2): there is NO derived-minting gapI misread my own output. Checking derived-unit widths across project-days: The normal shape is one day-wide unit (86400s) plus hourly units — the day-wide one is the backfill unit and covers all 24 hours. The "00:00" entry I counted as a single hour was that day-wide unit; my formatting printed a 24-hour slice as Net effect on the conclusion: back to close to where I started — the 1h blocker is dominated by the metric behaviour (worst tenant, full-day hole for a tenant with ~1 row that day). What remains genuinely open, and is much narrower, is that the day-wide derived unit covered the whole day and published 0 rows while the base tier holds 1 row for it. That is either the known slice-tag/overlap issue or the row falling outside the aggregation bound — and at one row it is not worth prod risk to chase further. That is five corrections in this PR, three of them in the last hour on this one sub-question. I am going to stop iterating on a 1-row tenant: the operationally meaningful items are unchanged and stand —
|
Final datapoint: depth +2 days in 20 minutes, the blocking day still untouchedThis is the thesis of this PR demonstrated end to end. Throughput is healthy, the queue is ordered sensibly, uptime is finally sustained — and G1 does not move, because the single day that would close the run is not being worked. Its 507 pending units are split fragments that rank low by width, so the scheduler keeps servicing other days and depth climbs instead. Worth noting against my own rejected fix: promoting split children would have raised this particular day. The journal replay killed that change because it demoted 2026-08-10 — a different day. That is the distinction that matters: a policy that promotes a class of tasks is not the same as a policy that targets the day which closes the run. The first is what everything tried this week; the second is what G1 requires. Concretely, the next change I would make and validate by replay: select the worst project's newest missing day and drive that day's units to completion before spreading. For |
Sizing the recommendation: the gating day is 143 GB, ~5 hoursThe day gating 1m contiguity is ~3% of the 4.9 TB backlog and about five hours of targeted work — against ~7.5 days of undirected drain that, as the last datapoint showed, does not reach it at all. That is the quantitative case for goal-directed selection, and it is the strongest argument in this PR for doing enqueue selection rather than another comparator term. Caveat I owe on my earlier "5 → 29" claim. Contiguity is the minimum across projects. Filling this day raises This also suggests a cheap operational test that needs no code change: run those 507 units off-box or with a targeted |
Hedging my own OOM claim: no recurrence in 3.5 hoursEarlier in this PR I reported the OOM interval as "regressed from 7-15h to ~2.4h", on the basis of two kills at 13:10 and 15:34. There have been no further OOMs since — 7 total on the host, last at 15:34, i.e. ~3.5 hours quiet. Two kills in a burst followed by a long quiet stretch reads as load-dependent spikes, not a sustained regression. That claim went beyond what two datapoints support and should not be treated as a finding. What still stands unchanged: the kills are real, ~125 GB anon, exit 137, invoked by Related observation: tier depth has stalled at 1h=23 / 1m=34 across the last two images after climbing ~2 days per 20 minutes on the container that survived ~40 minutes. That is consistent with deploy churn discarding in-flight work rather than with progress ending — which is the same point as the restart-cadence comment above, now visible in the goal metric itself. |
✅ Prediction confirmed: 1m contiguity went 5 → 30 when the identified day filledThis validates the analysis end to end. I named What made it happen: uninterrupted uptime. The container has been alive ~1 hour — by far the longest today — after a stretch of ~15-minute mean time between restarts. That was the precondition flagged earlier in this PR, and it is the cheapest lever available. Where that leaves the goal
The one change I would still makeMake a day with no source rows count as covered. Right now a single quiet tenant can pin the fleet-wide number at 2 no matter how complete real coverage is — which is exactly what it is doing, and what it did earlier today under a different tenant ( |
Correcting my own recommendation: the empty-day guard ALREADY EXISTSI have repeated "make a day with no source rows count as covered" several times in this PR. It is already implemented. // A day the SOURCE never held counts as covered. A rollup cannot exist for
// [data that was never there] — answered, not missing.
covered.contains(&key) || !source.contains(&key)and the per-tier The actual residual, which is narrower
(2) is the more interesting defect class and is the real version of "empty partitions read as coverage": the guard tests whether source rows exist, not whether any rollup-eligible rows exist. A day full of rows that the rollup spec filters out is indistinguishable from a day that was never built. I am not proposing a fix. Determining "would this day produce any rollup output" is expensive, the magnitude here is one row, and I have made enough wrong calls in this PR to want a second opinion before touching the goal metric's semantics. Current state (2h uptime, no deploys, no OOMs in ~11h)The derived queue has essentially drained. Sustained uptime plus a complete base tier did what a week of scheduling changes could not — which remains the most actionable finding here. |
Closing state: the remaining defect is the enqueue veto, and it is now isolatedAfter ~2h uptime with no deploys and no OOMs: The planner sees 210 missing cells and wants none of them, while only 20 derived tasks are queued. The code comments that Healthy signals that rule out other causes:
So execution is no longer the bottleneck — selection is. With the base tier complete at 30 days and prod stable, the only thing preventing 1h coverage from filling in is that the missing cells never get enqueued. That is the one place I would point a code change now, and it is far more tractable than anything discussed earlier in this PR: compare |
FOUND IT:
|
Correcting my attribution: the 1m jump was probably a code fix, not just uptimeI wrote that 1m contiguity going 5 → 30 was caused by uptime, not a code change ("nothing was deployed to cause it"). That was wrong, and I did not check the deploy log carefully enough before saying it.
That is the fix for the byte estimate counting whole files — so a 10-minute slice estimated what a whole day would decode. That is precisely the over-splitting I documented all evening (the 928 and 507 fragment explosions, ~278 MB per 3-minute fragment). With the estimate corrected, those days stop shattering into unrunnable fragments and can actually complete — which is a far better explanation for 5 → 30 than uptime alone. Uptime almost certainly helped (units need to survive to commit), but I presented a single cause with more confidence than the evidence supported, and the more likely primary cause was someone else's fix landing four hours earlier. This also invalidates part of my earlier framing. I treated the fragment explosion as evidence that time-bisection is inherently counterproductive for whale days. The real story is narrower and more mundane: the byte estimate was wrong, so bisection was being triggered when it should not have been, and each fragment inherited a wildly inflated estimate. That is a bug in the estimator, not a flaw in bisection — and it is a much better root cause than anything I proposed for it. Credit where due: that is the finding that moved the goal metric, and it was not mine. |
Milestone: both tiers now at 30 days of DEPTH; the metric still reads 3The 1h tier — the one that governs 14d/30d dashboard latency — now holds 30 days of coverage, up from 15 when I started looking at it. Contiguity still reports 3, and the two reasons are now both identified and measured:
Neither is a throughput problem, and neither needs more compute. The question I am deliberately not answeringWhether a real 30-day dashboard query now routes to the rollup is the only test that matters for the actual goal ("30d dashboards fast, 1s ideal"). I am not running it: a dashboard-shaped 30d query that fails to route falls back to a raw scan, and this box has OOMed at 125 GB twice today on exactly the query path. That is a test worth running deliberately, with someone watching, not as an unattended probe. If it does route, the practical goal may already be met for every tenant that has data — while G1 continues to report 3 because of a quiet tenant and a stale veto. |
✅ GOAL MET: all four tiers at 30-day contiguity
Retraction: my "357 cells vetoed forever" claim
That is the sixth correction in this PR, and the same shape as the others: a mechanism read off the code, extrapolated to a consequence, published before the consequence was observed. What actually got it thereNot my work. In order of apparent contribution:
What this PR is still worthThe measurement techniques, and the record of what did not work — five scheduling changes including my own rejected one, and the offline-replay method that caught it before deploy. The |
Rollups are being USED: 91.5% hit rate on live trafficCoverage being complete is necessary but not sufficient — the goal is that dashboards actually route to the rollups. Read from the routing counters (no query executed, so no OOM risk), 2h-old process: Two hours of real dashboard traffic, and 91.5% of eligible queries route to a rollup. Together with 30-day contiguity on all four tiers, that is the coverage-and-usage half of the standing goal met, measured from actual routing rather than inferred from gauges. Caveat on the dominant miss reason
What is still unmeasuredLatency. "1 second, especially 30d" is the actual target, and a hit rate does not prove it. Measuring it means running a dashboard-shaped 30d query and timing it, which I am not doing unattended given this box OOMed twice today on the query path. That is the one remaining test, and it should take minutes with someone watching. |
The remaining gap is LATENCY on the rollup tier itself: 4.5–8.4s, not 1sMeasured safely — querying the rollup table directly, so there is no raw-fallback OOM risk: SELECT count(*) FROM otel_logs_and_spans_rollup_dashboard_1h_v2
WHERE project_id='00000000-…' AND date >= CURRENT_DATE - 30;Consistently seconds across repeats, so this is not a cold-cache artifact. Counting 38k rows does not cost 5–8 seconds of CPU, so the time is going to planning, file listing, or object-store round trips over the rollup tier's own files — not to processing the data. Where that leaves the standing goal
Coverage and routing — the two things this session and much of the week were spent on — are done. The user-visible goal is not, and the bottleneck has moved somewhere new: the coarse tier is slow to read, even though it is small. The obvious next thing to checkWhether the rollup tables are themselves fragmented. 38k rows spread over 30 days of small per-slice files would produce exactly this shape — hundreds of file opens for a trivial amount of data, which is the same root cause as the raw-side fragmentation finding (~1 MB files against a 256 MB target, 408 opens/sec at ~389 ms). If so, the rollup tiers need their own compaction, and that is a much smaller job than anything discussed earlier in this PR. This also matches the previously recorded conclusion that routing works and the gap is plan cost — which is now the only thing standing between this system and the actual goal. |
Why the rollup tier is slow to read: it is fragmented BY DESIGN and never compactedFollowing the latency finding, I checked whether the rollup tiers get compaction. They do not, and it is deliberate. From
So tier packing was tried, it stripped the identity tags, and it broke coverage — hence the exclusion. Meanwhile:
The tier therefore accumulates thousands of small tagged files by construction. That is a coherent structural explanation for a 30-day read costing 4.5–8.4s while returning only 38k rows: the time is file opens and planning, not data. The tension worth namingThe coverage mechanism and the read latency are in direct conflict:
Fixing this is not "turn compaction on for tiers" — that was tried and caused an outage-shaped regression. It needs a tag-preserving tier compaction: merge files within a (project, date, generation) group while carrying the union of their slice bounds forward, so That is now the single thing standing between this system and the stated goal ("1 second, especially 30d"). Coverage is done (30-day contiguity, all tiers), routing is done (91.5% hit rate) — the remaining cost is entirely in how the coarse tier is stored. |
Escalation: a full-table aggregate on the 1h tier now TIMES OUT at 60sA coverage probe started failing (~30 min). It is not a false alarm, and it is not server load: For comparison, the same tier with partition pruning (
This escalates the previous finding from "the tier is slower than the 1s target" to "the coarse tier is becoming unqueryable without partition filters", and it is the direct consequence of the design tension documented above: tiers are excluded from compaction to preserve coverage tags, every unit writes its own file, publications run ~10/min, and nothing consolidates. The tier now holds 35 days of accumulated per-unit files. It is getting worse monotonically, which makes tag-preserving tier compaction more urgent than it looked an hour ago — this is no longer only a latency-goal issue but an operability one. Any tooling that does an unfiltered scan of a tier (probes, dashboards without a project filter, ad-hoc checks) will now fail. Worth noting the shape: the fix that protected coverage created the latency problem. Excluding tiers from packing was correct — packing stripped the identity tags and broke coverage. But nothing replaced it, so the tier has been accumulating files ever since with no consolidation path at all. |
The tier is measurably degrading: +56% latency on +0.36% dataRe-ran the same pruned 30-day read ~4 hours after the first measurement: Latency up 56% while the data grew 0.36%. That ratio rules out data volume as the cause and is exactly the signature of file accumulation: same rows, more files, more opens per query. Combined with the earlier finding that an unfiltered aggregate on the same tier now times out at 60s, the trend is:
Coverage itself is stable — 30-day contiguity on both tiers across several restarts. The system is correct and getting slower. This is now the highest-value work item in this PR by a wide margin. It is not a latency-goal nicety: read cost is climbing on a clock, an unfiltered tier scan already fails, and the pruned path has gone from 5-8x the goal to ~10x in four hours. Tag-preserving tier compaction — merging within a (project, date, generation) group while carrying the union of slice bounds forward — is the shape that resolves it without reintroducing the coverage regression that caused tiers to be excluded in the first place. |
Correction: the "+56% degradation" was noise, not a trendI claimed the tier was measurably degrading (6.8s → 10.6s). A further sample contradicts that: A 4.3–10.6s spread with no monotonic trend. I drew a 56% degradation from two points in a noisy series and should not have — the variance is plausibly cache state and concurrent query load. Withdraw the degradation claim. Two further reasons those timings are weaker evidence than I presented:
What still stands, on better evidenceThe level is not in dispute, and neither is the structural cause:
So: the tier is slow and structurally fragmented, and the 60s timeout on unfiltered scans is real and reproducible. What I cannot support is that it is getting worse on a measurable slope — I would need a proper time series with fixed work per sample, not five ad-hoc timings. That is the seventh correction in this PR. The recurring failure is the same one each time: treating a small number of samples, or a single instrument, as sufficient for a directional claim. |
Correction: the pruned tier read is NOT fragmentation-bound — it scans 34 files
34 files, not thousands. Roughly one per day, which is a perfectly healthy layout. So my "the tier is fragmented and that is why reads are slow" explanation is wrong for this access path, and tag-preserving compaction would not fix it. But the query still takes 4–10s. 34 files in ~7s is ~200ms per file opened — which lines up almost exactly with the separately recorded The sharper diagnosisThe problem is per-file round-trip latency, not file count. At ~200ms per open, a 1-second budget allows ~5 files. Any 30-day query touches at least one file per day, so the 1s goal is unreachable on this storage path regardless of how well-compacted the tier is. That reframes the remaining work entirely:
The 60s timeout on the unfiltered aggregate remains consistent with file count — that scans every project and date. But the pruned path, which is what dashboards actually run, is latency-bound. Note on what this invalidatesThe previous two comments — the fragmentation-by-design framing and the (already withdrawn) degradation trend — were built on the assumption that the pruned read touched many files. It touches 34. The design tension I described is real and worth knowing (tiers genuinely are excluded from compaction to protect coverage tags), but it is not the cause of the dashboard-path latency. Eighth correction. Measuring |
Coverage survived the OOM; latency remains 4-18x the goal even warmCoverage: an OOM restart happened at 10:39 (124.6 GB anon, exit 137, Latency, same pruned 30-day query run back-to-back on a 47-minute-old process: Cache warming clearly helps (18.5 → 10.0), but the warm run is still 10s against a 1s goal — and with On variance: the spread is 4.3–18.5s, which is far too wide to support any trend claim — I withdrew one such claim already. I am reporting the range, not a direction. What is stable across every sample is the level: 4–18x the target, never close. Where this leaves the goal
The remaining question is unchanged and specific: why does opening one small tier file cost ~200-300ms even warm? That is the number that has to move, and neither compaction nor more coverage work will move it. |
Definitive: 8ms of CPU, 367 KB of data, 4-18s of wall clockFull Essentially 100% of the query is waiting, not computing. 8ms of CPU against 4-18s wall. I was wrong to rule out fragmentationTwo comments ago I saw These files average 8.5 KB. Each one costs a full object-store round trip to deliver a few kilobytes. 43 round trips at ~100-400ms each is precisely the observed 4-18s. The count is modest; the size is catastrophic. So tag-preserving tier compaction is back on as the correct fix, and its expected effect is large: consolidating 43 tiny files into one replaces ~43 round trips with one, which should move a 4-18s query into the sub-second range where the goal lives. Why the tier produces 8.5 KB filesEach rollup unit publishes its own file ( That closes the loop on the whole investigation: coverage ✅, routing ✅, and the latency gap is per-file round trips over 8.5 KB files, fixable by merging within a (project, date, generation) group while carrying the union of slice bounds forward. Ninth correction — and the lesson is precise: |
Major revision: the 30-day tier read is now ~1.1s, and per-file cost is cache-state, not file sizeScaling test across window sizes on the 1h tier: Two conclusions, both revising what I previously called definitive:
What this does to the fragmentation conclusionThe 8.5 KB files are still real and still make cold reads expensive — that part stands, and the 60s timeout on unfiltered scans is unchanged. But dashboard latency is dominated by cache residency, not by file size: the same 47 tiny files answer in 1.1s warm and took 4-18s cold. So tag-preserving compaction would help cold reads and unfiltered scans, but it is not the lever for the stated goal if dashboards run against a warm cache. The more relevant questions become: what is the real hit rate for tier files under production traffic, and how often does a dashboard query hit cold? Goal scorecard, revised
Tenth correction. The pattern that produced it is the same as all the others: I measured under one condition (cold), derived a per-unit constant, and treated it as a property of the system rather than of the condition. |
Current state: 30-day tier reads are 1-2s, not 4-18s — and two invalid measurements to discloseBoth land at 1-2s regardless of whether I had warmed that project. So the 4-18s range I measured earlier was not steady state — it was transient (process churn, OOM aftermath, cold process), not a property of the tier. The warm/cold framing in my previous comment is therefore also too strong: a project I had never touched answers in 1.9s. Revised reading: 30-day tier reads currently sit just above the 1s goal, not 5-18x over it. Per-file cost is ~24-39ms. Files are still tiny (some ~300 bytes), so compaction would still help, but the gap to the goal is far smaller than this PR has been claiming. Two invalid measurements, disclosed
Both were caught by the same check: a number that looked too good, followed by reading the raw output instead of a grep of it. Worth stating because a silent connection failure that returns fast is indistinguishable from success if you only look at timings. Net effect on the PR's conclusionsThe durable findings are coverage (30-day contiguity, survived 3 OOMs) and routing (91.5%). The latency story has moved three times — 26 TB irreducible → per-file latency → fragmentation by size → cache state → 1-2s, close to goal. Each step was measured, and each generalised beyond its conditions. Treat the current number as provisional too: it is a handful of samples on a system that restarts often. |
Firmer number: 30-day tier reads are 2.3-3.9s, not 1-2sFour samples, two projects, back-to-back: My previous comment said 1-2s, "close to goal", based on two readings (1.11s and 1.86s). Those were the fast end of a spread. With four samples the level is 2.3-3.9s — about 2-4x the 1s target. That is still a big improvement on the 4-18x this PR claimed for most of the day, and the direction of every correction has been the same: the problem is smaller than I said, and my confidence outran my sample size every time. I made that exact observation one comment ago and then repeated the mistake immediately. Where the latency actually stands
Tiny files remain real and compaction would still help, but the honest gap is 2-4x, not an order of magnitude. I would treat even this as provisional until someone runs a proper benchmark — fixed work, many samples, on a process that has been up for hours. Every number in this PR that I stated from fewer than ~5 samples has needed correcting. |
Proper benchmark: median ~1.3s, p90 ~2.9s — the variable is LOAD, not cache or file sizeSix fixed-work samples, same project, back-to-back: At the 1s goal — yet 30 minutes earlier the identical query on the identical project measured 2.3-3.9s. Same files, same bytes, same warm/cold status. So the variable driving this is concurrent load on the box, and it moves the number 4-5x. Not cache residency (I tested that), not file size (constant across all samples), not fragmentation (47 files throughout). Pooling every steady-state sample from today (n=12): Honest answer on the goalThe 30-day dashboard read meets the 1s target around the median and misses it by 2-4x at the tail, depending on what else the instance is doing. It is not a fixed 4-18x problem, and it is not reliably sub-second either. That also explains why this PR's latency story moved five times: I was sampling a load-dependent quantity 1-4 times per attempt and naming each snapshot as the level. Cold vs warm, fragmentation by size, per-file round trips — each was a real observation of a system under different momentary load, generalised into a property. What would actually be worth doingNot more of my ad-hoc timings. A p50/p90/p99 measured from real dashboard traffic over hours — the system already counts |
|
Follow-up: cannot resolve the hit-rate drop from outside, and a third explanation
A third explanation I should have listed: traffic mix. The 91.5% reading was taken ~03:00 and this one ~22:00. If different dashboards or query shapes dominate at different hours, the hit rate moves legitimately with no regression at all. Misses holding flat while hits collapse is consistent with that as well as with a regression. So the three candidates are: read-path regression, the known What would settle it, cheapest first:
Flagging rather than diagnosing, because "rollups always used" is one of the three goal components and 6.3% would mean it is not met — but I have been wrong often enough today that a two-sample comparison across an 19-hour gap is not evidence I would act on. |
Hit rate reproduces at ~7%, but the miss reasons say traffic mix, not regressionFresh process (36 min uptime, counters from zero): Consistent with the 6.3% measured on the previous process, so the low rate is real — not a one-process artifact. But the miss reasons changed completely: Misses are now dominated by filter-shape reasons, not coverage. Those are legitimate refusals — the query's filters don't qualify for rollup routing. That supports the traffic-mix explanation over a regression, and it also suggests the earlier Revised read on the earlier alarmI flagged a possible routing regression from 91.5% → 6.3%. With this second window I would now weight it as most likely traffic mix plus the I am still not calling it settled — the honest comparison is the same hour tomorrow. One concrete lead
|
Why
|
READ THIS FIRST — consolidated summaryThis PR accumulated ~20 comments and eleven corrections. Rather than read them in order, here is what survived and what did not. What is true (measured two or more independent ways)
What I got wrong (do not act on these)
The single failure mode behind all of them: measuring a load- or condition-dependent quantity a small number of times and naming the snapshot as the level. What is worth doing next
Methods that worked and are worth reusing
|
Tantivy reindex is DIVERGING, and the nightly reconcile did not runThis is the neglected item from the standing goal ("continue the tantivy reindexing to a conclusion"). It is not converging — it is losing ground. Why: the only drain is a daily cron, and it did not fireThe incremental path ( const_default!(d_tantivy_reconcile_schedule: String = "0 30 3 * * *"); // 03:30 daily
spawn_db_cron(&db, "Tantivy reconcile", …)Observed tonight: container up 6h (alive since ~21:43, so alive at 03:30), now 03:43 UTC. So it either never fired, or fired and built nothing. It logs only when Candidate causes, not yet separated:
Why it mattersSearch coverage degrades continuously: every file the reconcile misses stays unindexed forever, and queries fall back to raw scans for that data. At ~85/hour the gap widens by ~2,000/day. Cheapest next step: make the reconcile log unconditionally (including the |
Correction: the tantivy reconcile DID fire — I checked 13 minutes into a multi-hour passMy previous comment said the nightly reconcile "did not run". That was wrong. It fired exactly on schedule. I looked for the summary line ( What is actually wrong: the rate, not the firingThe reconcile is building at roughly ~100 files/hour against ~85/hour arriving, so net progress is ~14 files/hour against a 4,891 backlog — on the order of 350 hours to converge. And it is a daily cron. With prod restarting many times a day, each nightly pass is truncated partway through and the next attempt is 24 hours later. That is why the backlog has grown 3,031 → 4,891 over the period I have been watching: the drain exists, fires correctly, and is simply outpaced. What that changes
Cheapest fix: log reconcile start and periodic progress (files built / remaining). Second: the pass is nightly and unbounded — if it cannot finish before the next restart it should checkpoint progress, or run continuously at low priority rather than once a day. That is the twelfth correction in this PR, and the same shape as several others: I inferred an absence from a missing log line without checking whether the thing was still in progress. |
Tantivy: 2h into an active reconcile, the backlog is FLAT — it matches arrivals, it does not drainSame container (up 7h), pass started 03:30 and still running at 05:28: Flat within noise. My "net −14 files/hour" in the previous comment came from two points and does not survive a third — the same over-reading of a small sample that has produced most of the corrections in this PR. The accurate pictureWhile the reconcile runs, it builds at roughly the rate new files arrive: the backlog holds at ~4,900 rather than draining. It runs one pass per day, and prod restarts many times a day, so for most of each day nothing drains the backlog at all — which is why it drifted 3,031 → 4,900 across this session. So the shape is: steady-state when running, growth when not, convergence never. What would fix itNot "make the cron fire" (it fires) and not "log a summary" (though that would have saved me two wrong comments):
Any one of the three changes the sign of the trend; (1) and (3) together also make it robust to the restart rate, which is the environmental factor nothing else here controls. |
Tantivy: 4 hours of continuous reconcile, no measurable drainThe pass that started 03:30 is still running at 07:24 (zero Range 4,891–4,935. No measurable drain while the pass is actively running. The upward drift is within the spread so I will not call it growth — but it is plainly not clearing. This reorders the fixesI previously listed three options as roughly interchangeable. They are not:
Caveat on (2): Honest status of this threadThe tantivy goal item ("continue the tantivy reindexing to a conclusion") is not achieved and not close. Backlog ~4,935, no drain observed, and the mechanism that should drain it runs for hours without measurable effect. What I have contributed is the measurement and #208 to make future passes observable — not a fix. |
A live instance of the failure mode: 4.5h reconcile killed by a deploy, zero progress retainedThe pass that started 03:30 was still running when a deploy replaced the container at ~08:05. 4.5 hours of work, no completion event, nothing retained, and a 19.5-hour gap before the next try. Both failure modes in one instance:
This is not a rare interaction. Prod restarted ~20 times in the two days I have been watching (deploys plus 3 OOM kills), so the probability of a multi-hour nightly pass surviving to completion is low. The reconcile is effectively never completing. It also means my earlier "no measurable drain while running" may understate the problem: the drain I measured was during the only sustained window this backlog has had in days, and it still did not clear. Reinforces the ordering from the previous comment — throughput first (a pass must be able to finish), then checkpointing (so partial work survives the restart that is statistically certain to interrupt it). |
The tantivy number that matters: ~72 seconds per file, at concurrency 2Against an arrival rate of ~85 files/hour, that lands the pass at break-even — which is exactly the flat backlog measured over 4 continuous hours. 72s to index one parquet file is the headline. These files average single-digit MB (the rollup tier ones are ~8 KB; raw partition files are larger but not enormous). A minute-plus per file suggests fixed per-file overhead — fetch, extract, build, upload, manifest update — rather than indexing work proportional to content. Two levers, and the cheaper one is probably not concurrency
I am not changing the default. It is a tuning decision on a memory budget I do not own, on an instance with a documented history of budget-tree over-commit — and this PR already contains enough examples of me being confident and wrong. The numbers above should make it a short decision for whoever does own it. Note the dependency: evaluating either lever requires knowing how far a pass gets before a restart truncates it, which is unmeasurable today and is what #208 adds. |
OOMs cluster in pairs, minutes apart — consistent with a fatal query being RETRIEDNow observed on two independent occasions: All four: ~125 GB anon, exit 137, invoked by Tight pairs followed by ~19h of silence is not what independent random events look like. It is the signature of the same workload being re-attempted: a query kills the box, the service restarts, the client re-issues (or a retry fires), it kills the box again, and then the workload moves on or the client gives up. If that reading is right, it has a concrete implication: the second kill of each pair is preventable and the first is the one to attack. Prevention on the retry side (do not immediately re-admit a query shape that just preceded a fatal OOM) would halve the outages without needing to solve the underlying memory bound. It also connects to the previously recorded guard behaviour: Not claiming this as proven — I have four kills across two clusters, and the correlation with a specific query is not established. What would establish it: log the in-flight query shapes at OOM time, or check whether the same client/query appears immediately before both kills of a pair. That is a heap/query attribution task, not something I can settle from counters. |
|
Crashloop continues: 4 kills in 18 minutes, each process living 3-8 minutesWhat each boot does before dying: completes rollup coverage recovery successfully — Four such recoveries in 8 minutes, one per boot. They complete, so recovery is not dying mid-way — and ~11k entries does not plausibly account for 125 GB, so I am not attributing the OOM to it. What the timing suggests, hedgedA process that boots, runs 3-8 minutes, and dies at ~125 GB — repeatedly — points at work that resumes on startup climbing to the cgroup limit: WAL replay of buffered writes, or ingest picking back up. That is consistent with the recorded attribution of these OOMs to bulk INSERT rather than queries. Explicitly a hypothesis. I have attributed this OOM incorrectly twice today (first to an oversized scan 55 minutes stale, then to the wide-scan admission path which logged zero events during the kills). I cannot see RSS over time from outside the process, and the pgwire layer labels INSERTs as SELECT, so counters cannot separate ingest from query. What would actually settle it
Both are in-process changes. From outside, the honest summary is: recurring, signature known, trigger unknown, currently in a sustained crashloop. |
Tantivy: the growth model is quantitatively confirmedPredicted arrival rate was ~85/hour; observed growth with no reconcile running is ~83/hour. The model matches the measurement, which is the first time in this investigation a prediction has held on the first attempt. Consequence: the backlog has grown ~650 files since the truncated pass, and the next scheduled attempt is 03:30 tomorrow — by then ~6,500 files, i.e. larger than the backlog the previous pass already failed to clear in 4.5 hours. Each day the task gets harder while the mechanism stays the same. That is the sense in which this is diverging rather than merely slow: it is not a backlog being worked down at an inadequate rate, it is a backlog whose size grows faster than any single nightly pass can consume. The three fixes remain as stated, in order: cut per-file cost (~72s is the anomaly), raise concurrency from 2, checkpoint across restarts. Only the first two change the sign; the third stops each day's work being thrown away. |
Measured 2026-08-19 against the live prod journal and prod tiers.
The finding
rollup_min_contiguous_daysis stuck at 2 because ~4.9 TB of base-tier decode across 08-06..08-14 has not happened yet — not because the scheduler picks the wrong task. Every scheduling change of 08-17..19 acted downstream of that.1h coverage appears only where 1m is complete (08-15+: 12/12, 13/13; 08-12: 10 projects in 1m, 0 in 1h). The proof loop that refuses those days is correct and must not be "fixed" — it refuses because the 1m tier genuinely is not built. Several hypotheses this week went looking for a defect at that layer; there isn't one.
Scale: ~26 TB pending across all sources and 211 (source, project, day) cells.
A rejected fix, recorded so nobody re-derives it
split_time_taskdemotes a day unit's children from day-width to 180s, so they rank below every day-wide unit in history. I implemented inheritance of the parent's scheduling width — green regression test, all 60 coordinator tests passing — and it made the blocking day worse:Caught by replaying the (pure) comparator over the real journal offline, in seconds, before any deploy. A green targeted test is not evidence that a scheduling change helps. Branch
fix/split-inherits-backfill-prioritykeeps the work.Corrections and traps
derived_refusalisfirst_refused_sealed(...)— a sample, not a vetosealed_turnreservation worksattemptsresets on split, so 0 ≠ never claimeddocker service logs --since 24honly reaches back to the current containerWhat actually moves the number
Per-unit cost (99.8% of a unit is scan; compact a day before rolling it up) and deriving rather than rebuilding. Docs-only, so no deploy.