Skip to content

docs(plan): the gap is decode, not scheduling - #206

Merged
tonyalaribe merged 3 commits into
masterfrom
docs/measured-rollup-gap
Aug 28, 2026
Merged

tonyalaribe merged 3 commits into
masterfrom
docs/measured-rollup-gap

Conversation

@tonyalaribe

Copy link
Copy Markdown
Contributor

Measured 2026-08-19 against the live prod journal and prod tiers.

The finding

rollup_min_contiguous_days is 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.

~4.9 TB pending base (1m) work across 08-06 .. 08-14
   -> those days' 1m tier is INCOMPLETE
   -> the proof loop skips any day still missing its base tier
   -> 1h derived tier gets ~0 coverage before 08-13
   -> 1h contiguity = 2

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_task demotes 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:

best rank of a 2026-08-10 task among 78,121 sealed pending
OLD:  5,375     NEW: 12,940

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-priority keeps the work.

Corrections and traps

  • derived_refusal is first_refused_sealed(...) — a sample, not a veto
  • sealed work is not starved to zero; the sealed_turn reservation works
  • attempts resets on split, so 0 ≠ never claimed
  • docker service logs --since 24h only reaches back to the current container
  • six deploys in ~2.5h on 08-19 → restarts every 15-20 min against 8-15 min units

What 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.

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).
@claude

claude Bot commented Aug 19, 2026

Copy link
Copy Markdown

Review

This is a docs-only PR (one new file, docs/plans/2026-08-19-the-gap-is-decode-not-scheduling.md, 169 lines, no code changes), so the usual code-quality/perf/security/test-coverage checklist mostly doesn't apply. Reviewed it as an investigation writeup instead, following this repo's established docs/plans/* convention (there's no CLAUDE.md in this repo, so I looked at the sibling plan docs for style).

Strengths

  • Clear causal chain (pending decode → incomplete 1m tier → proof loop skip → 0 coverage → contiguity stuck at 2), backed by two data tables (per-day 1m/1h project coverage, per-day pending base_rollup decode) rather than assertion alone.
  • The quoted database.rs snippet matches the current source almost verbatim (src/database.rs:10183-10186) — good, this doc won't rot into a misleading reference the moment someone skims it instead of the code.
  • The "implemented and rejected" section is the most valuable part: it records a plausible-looking fix (inherit backfill_priority_micros on split) that passed a green regression test and all 60 coordinator tests, but made the target metric measurably worse when replayed against real queue state (best rank 5,375 → 12,940). Writing this down, with the actual before/after numbers, is exactly what prevents someone from re-deriving and re-shipping the same regression next week. Good discipline pointing at "a green targeted test is not evidence a scheduling change helps."
  • The "three corrections" and "two measurement traps" sections are concrete and falsifiable (specific field names, specific docker behavior), not vague hedging.

Nits / things worth double-checking before merge

  • The fix/split-inherits-backfill-priority branch referenced as where the rejected work lives doesn't appear to exist in this repo's remote branches (at least not visible from here). If it was only ever local/already deleted, worth either pushing it (since the doc explicitly tells future readers to look there "so nobody re-derives it") or adjusting the pointer so it doesn't dangle.
  • The comparator tuple in the doc is given as (class, starved, -width, -recency). The actual code has a fills_a_hole priority component between starved and width in at least one of the two ordering call sites (maintenance_coordinator.rs:1346-1347). Doesn't change the doc's conclusion (width/recency is still what flips the outcome), but a reader diffing the doc against the code line-by-line might be confused by the mismatch — could tighten the description or note it's simplified.
  • "26 TB across 211 (source, project, day) cells" and the 37 TB "overlap-corrected" figure being called out as wrong are good, but since these are point-in-time prod measurements, it may be worth a one-line note on how they were derived (query/script) or a link to it, for reproducibility next time someone needs to re-check the number.

Nothing here blocks merging — it's a well-evidenced, honest writeup (including the negative result), consistent with the rest of the docs/plans/ series.

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.
@tonyalaribe

Copy link
Copy Markdown
Contributor Author

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.

date consol pending consol complete base_rollup pending
2026-08-06 0 37 1376
2026-08-10 1 34 2353
2026-08-13 9 49 1985

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 (project_id, date, timestamp + dedup keys + tiebreak + tombstone + dimensions + measure columns).

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 scan_ms=481682 for a unit producing 142 rows — and not restarting mid-unit. Pushed as a commit on the branch.

…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.
@tonyalaribe

Copy link
Copy Markdown
Contributor Author

Measured the binding constraint: decode throughput is 7.6 MB/s.

128 units published in 20 minutes carried 9.11 GB of estimated decode:

effective decode throughput   7.6 MB/s      (0.027 TB/hour)
  -> 4.9 TB gating work       ~179 hours    (~7.5 days uninterrupted)
  -> 26 TB total              ~40 days

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 ~408 file-opens/sec at ~389ms each finding and scan_ms=481682 for a unit producing 142 rows.

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.

@claude

claude Bot commented Aug 19, 2026

Copy link
Copy Markdown

Review

This PR adds a single docs-only file: docs/plans/2026-08-19-the-gap-is-decode-not-scheduling.md (218 lines, no code changes). No CLAUDE.md exists in this repo to check against, so this review focuses on accuracy and clarity of the write-up itself.

Code references check out. I diffed the two inline snippets against current src/database.rs:

  • The base-tier-gating condition (*date >= today || missing.iter().any(...derive_from.is_none())) matches src/database.rs:10184 almost verbatim (only the closure param is renamed iindex in the doc — harmless).
  • The decode-estimate scaling (decoded * projected_numerator / projected_denominator) is a faithful simplification of the real saturating_mul/div_ceil arithmetic at src/database.rs:10448-10449, and the * 12 decode-inflation constant is accurate.

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:

  • The causal chain diagram up top is a good executive summary before the detail dump — a reader can stop after two paragraphs and have the right mental model.
  • Explicitly recording the rejected backfill_priority_micros fix (with before/after rank numbers: 5,375 → 12,940) is valuable — it prevents a future contributor from re-deriving and re-shipping a change that looks correct locally (green test, 60/60 passing) but is empirically worse against the real queue. The framing "a green targeted test is not evidence a scheduling change helps" is a strong, quotable lesson.
  • The "measurement traps" section (docker logs --since only reaching the current container; throughput numbers being invalidated by a restart every 15-20 min) is the kind of thing that's easy to rediscover painfully if it isn't written down.
  • Distinguishing refuted hypotheses (compaction, estimator inflation) from the actual lever (decode throughput / request latency) with data for each is well organized and keeps the doc from reading as just a data dump.

Minor points, non-blocking:

  • The doc asserts the per-unit estimate was "independently verified on prod at 515 MB actual against 491 MB predicted" but doesn't show how that measurement was taken (log line, query, etc.) — a pointer would let a skeptical reader reproduce it, consistent with the rest of the doc's evidence-first tone.
  • fix/split-inherits-backfill-priority is referenced as the branch holding the rejected work, but I couldn't confirm it exists as a remote branch from this checkout — worth double-checking the branch was actually pushed before merging, so the "nobody re-derives it" claim holds.
  • The 7.6 MB/s effective throughput figure is explicitly caveated as including restart overhead, which is good, but the doc doesn't give a best-case/instantaneous figure to bound how much of the gap restarts vs. raw per-file latency account for. Not required for this doc, but would sharpen the "which lever to pull first" recommendation in a follow-up.

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.

@tonyalaribe

Copy link
Copy Markdown
Contributor Author

The next step is blocked on something non-technical: prod needs a quiet window.

Eight images today (01caa46 → 35bd1cf → 0920aaf → 441421a → 032d64b → ae22152 → 02a6120 → fd4c3ef). I have twice tried to read cache/latency counters and gotten a container aged 50 seconds, then 1 minute.

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:

l2_used_bytes  128.8 GB     entry_count 2084     evictions 5744
hits 0    inner_gets 0    bytes_served 0

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 foyer.hits and foyer.inner_gets are still 0 after real maintenance has run, every parquet read is paying full object-storage latency and that is the whole ~100× throughput gap. If they climb normally, the latency is elsewhere and per-file request sizing is the next thing to attack.

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.

@tonyalaribe

Copy link
Copy Markdown
Contributor Author

CONFIRMED: the main Foyer data cache serves zero reads

This is the cause of the 7.6 MB/s, and it is now a finding rather than a hypothesis.

One process, one timefusion_stats read:

foyer_metadata:  hits 11,000   misses 634   bytes_served 3.67 GB
foyer (main):    hits 0        misses 0     bytes_served 0
                 inner_gets 0  range_hits 0  range_misses 0
                 l2_used_bytes 128.8 GB    entry_count 2,467 and CLIMBING

misses = 0 is the decisive number. Any read attempted through the cache registers as a hit or a miss. Zero of both means the data cache is not on the read path at all — while it is actively being written (entry count climbing, 5,744 evictions, 125 GB of foyer-storage-direct-fs-* on the host with today's mtime).

Ruled out — instrumentation gap. Both rows come from the same struct and the same rendering code in server/pg_compat.rs:

[("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 metadata reports 11,000 hits through it.

Ruled out — the wide-scan bypass. scan_bypass_scope has exactly one production caller (the wide-scan query path), so it cannot explain queries and maintenance both reading zero.

Reproduce in 30 seconds: run the stats query above, then a bounded query that really reads parquet (I used a 1-day count on otel_logs_and_spans_rollup_dashboard_1h_v2, 1,800 rows). foyer_metadata moves; foyer stays at zero.

Why this dwarfs everything else in this PR

Decode 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 caveat

I 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 object_store(None) on the Delta log store in the rollup path versus whatever the metadata cache wraps.

This has happened before

There 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 foyer.hits == 0 && entry_count > 0, which is trivially detectable and has now cost two investigations.

@tonyalaribe

Copy link
Copy Markdown
Contributor Author

Measured properly: the cache is HEALTHY, and the latency framing was wrong too

Got the authoritative log line (fed by combined_stats, a proper .read().await, so it cannot silently zero):

main:      hit rate 96.60%   hits 208,632   misses 7,354
           range hits 208,222   range misses 4,930
           bytes served 32.06 GB   inner bytes read 37.39 GB
metadata:  hit rate 96.81%   hits 11,286     (matches the stats-table value)

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/s

The 7.6 MB/s is real but I mis-framed what it measures: it is rollup progress (published units × estimated_decoded_bytes), not the machine's read capability. The IO subsystem is delivering ~150 MB/s while rollup accounting advances at 7.6 MB/s.

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:

  • maintenance is getting a small share of a box mostly serving queries
  • per-unit fixed overhead dominates (recall scan_ms=481682 for a unit producing 142 rows, and the separately-recorded finding that the per-unit cost is the commit)
  • estimated_decoded_bytes on published units undercounts the work actually done

Running correction count in this PR

Three 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.

@tonyalaribe

Copy link
Copy Markdown
Contributor Author

Prod is also OOM-killing itself — interval has shortened to ~2.4h

Not all of today's restarts were deploys. Two exit 137 OOM kills:

[Aug 19 13:10:17] tokio-rt-worker invoked oom-killer
[Aug 19 15:34:15] tokio-rt-worker invoked oom-killer
                  Killed process (timefusion) anon-rss:125,394,240 kB  (125.4 GB)

Same signature as the recorded series (~125 GB anon, exit 137, tokio-rt-worker = query/ingest path, not maintenance). What is new is the frequency: previously one every 7-15 hours, today two ~2.4 hours apart.

Combined with 9 distinct images deployed, prod has restarted roughly 11 times in ~3 hours.

Why this matters for the rollup goal specifically

A 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.

@tonyalaribe

Copy link
Copy Markdown
Contributor Author

Possible contributor to the shortened OOM interval: oversize scan rate is up

A 48-second sample on the current container:

wide_scan_oversize events:  30   (~2,250/h extrapolated; previously recorded ~1,392/h)
largest admitted scan:      selected_files=1317  selected_mb=2872
                            → ~2.2 MB average file, against a 256 MB target

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:

  1. The guard bounds scan concurrency, never one scan's size — so a rising admission rate translates fairly directly into peak memory.
  2. 1,317 files for 2.9 GB is the fragmentation problem showing up on the query side: ~2.2 MB average file against a 256 MB target. Same root cause as the maintenance-side finding, which is why file-count reduction helps queries and rollups both.

I am not claiming this is the OOM cause — the driver is the query path (tokio-rt-worker, 125 GB anon) and that has been true for weeks. It is a correlation worth checking against a longer window once a container survives one.

@tonyalaribe

Copy link
Copy Markdown
Contributor Author

Live demonstration: 149 units published, depth +3 days, contiguity +0

Fifteen minutes on a container that finally survived, same image:

published units:  149          (~10/min)
depth:            1h 16 → 18,  1m 27 → 29   (+3 days)
contiguity:       1h 2,        1m 5          UNCHANGED

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

  • tier_days (depth) counts any (project, day) that has output.
  • rollup_min_contiguous_days requires consecutive days back from today, for the WORST project.

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 87576849 to 5ce1c976, which also confirms no single tenant was ever gating this — the earlier derived_refusal was only ever a sample.

What this implies for the fix

To 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.

@tonyalaribe

Copy link
Copy Markdown
Contributor Author

The two days that actually gate G1 — and the 1h one is not a throughput problem

Depth 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:

1m: project 00000000, 2026-08-13 → 0 rows   (blocks at 5; everything back to 07-21 exists)
1h: project 5ce1c976, 2026-08-16 → absent   (08-14,15,17,18,19 present; blocks at 2)

Thin days still count — 08-15 has only 5,747 buckets for 00000000 yet sits inside the counted run — so the metric needs presence, not completeness. A single absent day is holding the run at 5 while 07-21 onward already exists.

The two blockers have completely different causes

5ce1c976 / 2026-08-16   138 tasks, ALL COMPLETE
                        50 base_rollup complete, 14 derived_rollup complete
                        ...and the 1h tier has NO rows for that day

00000000 / 2026-08-13   507 base_rollup PENDING + 506 superseded
                        the bisection pattern; work genuinely not done

The 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:

  1. the documented "publishes rows=0 and is then marked complete" trap (same shape as the untagged-base-file bug), or
  2. the project genuinely had no data that day, in which case contiguity is counting a legitimately-empty day as a hole — the "empty partitions read as coverage" item already noted in the architecture plan.

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 PR

The 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.

@tonyalaribe

Copy link
Copy Markdown
Contributor Author

Settled: the 1h blocker is a METRIC ARTIFACT, not missing work

Answered from the journal's own publication records — no prod query needed:

5ce1c976 / 2026-08-16
  base_rollup:     50 tasks — 49 published 0 rows, 1 published 1 row   (1 row, all day)
  derived_rollup:  15 tasks — 14 published 0 rows

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

rollup_min_contiguous_days takes the worst project. One near-empty tenant with a quiet day therefore caps the fleet-wide metric at 2, regardless of how good coverage is for tenants that actually have data. Note the worst project has already shifted once today (875768495ce1c976) — the metric keeps finding whichever tenant happened to be quiet.

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 (00000000 / 08-13, 507 pending fragments — that one is real work).

What I would change

  1. A day with no source rows should count as covered, not as a hole. Otherwise a sparse tenant makes the goal unreachable by construction, and no amount of maintenance throughput can ever satisfy it.
  2. Report contiguity weighted by tenants that have data, or publish per-tenant alongside the min, so one quiet tenant cannot mask fleet-wide progress.

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.

@tonyalaribe

Copy link
Copy Markdown
Contributor Author

Correction to my previous comment: it is not purely a metric artifact

I said the 1h blocker was "a metric artifact, not missing work". That overstated it. Digging into the slices:

BASE unit that published rows>0:   slice 00:00→00:00 (day-wide), 1 row
DERIVED units:                     14 units, all published 0 rows
derived hours covered:             00:00, then 11:00–23:00
                                   → hours 01:00–10:00 have NO derived unit at all

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:

  1. the tenant has ~1 row that day (genuinely near-empty),
  2. derived-unit minting is incomplete for that day (a real, if microscopic, bug),
  3. the metric scores any hole as a full day and then takes the worst tenant.

(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.

@tonyalaribe

Copy link
Copy Markdown
Contributor Author

Retracting correction (2): there is NO derived-minting gap

I misread my own output. Checking derived-unit widths across project-days:

units per (project,day):  2 → 52 cases,  25 → 29 cases,  1 → 12 cases
widths present:           [3600, 86400]

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 00:00 and I read it as an hourly one. So hours 01:00–10:00 were never uncovered, and the "14 of 24 hours" defect does not exist.

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 —

  • 1m is gated by 00000000 / 2026-08-13, 507 pending fragments — real work
  • 1h is gated by a near-empty tenant-day, and the worst-project metric turns that into a fleet-wide 2
  • the ~4.9 TB / ~26 TB backlog and the 1m→1h derivation chain are unaffected by any of this churn

@tonyalaribe

Copy link
Copy Markdown
Contributor Author

Final datapoint: depth +2 days in 20 minutes, the blocking day still untouched

depth:       1m 32 → 34 days   (~2 days per 20 min, container surviving)
contiguity:  1m 5, 1h 2         unchanged
00000000 / 2026-08-13:          still 0 rows

This 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 00000000 / 08-13 that is ~507 fragments — bounded, specific work, and it should take 1m contiguity from 5 to roughly 29 in one step, since everything behind it back to 07-21 already exists.

@tonyalaribe

Copy link
Copy Markdown
Contributor Author

Sizing the recommendation: the gating day is 143 GB, ~5 hours

00000000 / 2026-08-13   507 pending units
                        143.0 GB estimated decode
                        widths 120/180/300s  (all split fragments)
   at the observed 7.6 MB/s aggregate → ~5.2 hours of focused work

The 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 00000000's own run to ~29 (everything back to 07-21 exists), but the fleet metric then becomes whatever the next-worst project allows — possibly much lower, and note the 1h worst project has already migrated once today. The gain is real; its magnitude is not guaranteed, and the honest way to find out is to fill the day and re-read the metric.

This also suggests a cheap operational test that needs no code change: run those 507 units off-box or with a targeted run-unit sweep, then observe whether 1m contiguity jumps. That would validate the entire goal-directed thesis for ~5 hours of compute and zero risk to the scheduler.

@tonyalaribe

Copy link
Copy Markdown
Contributor Author

Hedging my own OOM claim: no recurrence in 3.5 hours

Earlier 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 tokio-rt-worker (query/ingest path, not maintenance) — consistent with the long-recorded attribution. Only the frequency regression is withdrawn.

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.

@tonyalaribe

Copy link
Copy Markdown
Contributor Author

✅ Prediction confirmed: 1m contiguity went 5 → 30 when the identified day filled

1m tier:   contiguous_days = 30    (was 5)   ← the full 30-day goal
00000000 / 2026-08-13:  976 rows   (was 0)   ← the blocking day filled
1h tier:   contiguous_days = 2, worst 5ce1c976   ← still the sparse-tenant artifact

This validates the analysis end to end. I named 00000000 / 2026-08-13 as the single day gating 1m contiguity, sized it at 143 GB / ~5h, and predicted that filling it would take the metric from 5 to ~29 because everything behind it back to 07-21 already existed. It filled, and the metric went 5 → 30.

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 1m base tier has met the 30-day target. That is the tier the 1h tier derives from.
  • The 1h tier is still reported as 2, pinned by 5ce1c976 — the tenant with ~1 row/day — while its actual depth is 23 days. Real 1h coverage is therefore far better than the metric says, and the remaining gap is dominated by the "an empty day counts as a hole, and the metric takes the worst tenant" artifact rather than by missing work.

The one change I would still make

Make 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 (875768495ce1c976). Until that changes, G1 will keep understating coverage and misdirecting effort.

@tonyalaribe

Copy link
Copy Markdown
Contributor Author

Correcting my own recommendation: the empty-day guard ALREADY EXISTS

I have repeated "make a day with no source rows count as covered" several times in this PR. It is already implemented. min_contiguous_days has:

// 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 rollup_coverage_contiguity log calls that same function. So that recommendation was wrong — the code already does it.

The actual residual, which is narrower

5ce1c976 / 2026-08-16 does hold a source partition (~1 row), so the guard does not apply. The 1h tier published 0 rows for that day, so it scores as a hole. Two possibilities:

  1. a tiny aggregation gap — 1 base row that should have produced ≥1 rollup row and did not; or
  2. the day's rows legitimately produce no rollup output (they do not match the spec's measures/filters), in which case the day is permanently a hole that no amount of work can fill.

(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)

1m contiguity   30      goal met, durable across restarts
1h contiguity    3      up from 2, now capped by the above
derived_pending 25, derived_unproven 25    (from 409)

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.

@tonyalaribe

Copy link
Copy Markdown
Contributor Author

Closing state: the remaining defect is the enqueue veto, and it is now isolated

After ~2h uptime with no deploys and no OOMs:

1m contiguity   30      goal met, durable
1h contiguity    3      depth 24, so ~21 days present but not contiguous
cells_missing  210
cells_wanted     0
cells_admitted   0
derived_pending 20

The planner sees 210 missing cells and wants none of them, while only 20 derived tasks are queued.

The code comments that cells_missing>0 with cells_wanted=0 means "the work is queued and the question is why it is not CLAIMED". The numbers contradict that reading: 210 missing against 20 pending. So the already-queued veto (want.retain(...) against queued_tables) appears over-broad — suppressing cells that are not in fact queued.

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 missing_tiers against queued_tables for a specific (project, date, table) that shows as missing, and find out which of the two is wrong. I have not done it because it wants a careful read of the veto's key construction rather than another inference from counters — and this PR already contains five corrections earned by exactly that kind of inference.

@tonyalaribe

Copy link
Copy Markdown
Contributor Author

FOUND IT: Superseded tasks veto backfill re-enqueue forever

The over-broad veto I suspected in the previous comment is real, and the mechanism is specific.

pub fn blocks_rollup_backfill(task: &MaintenanceTask) -> bool {
    matches!(task.key.operation, Dedup | BaseRollup | DerivedRollup)
        && task.state != TaskState::Complete      // <-- includes Superseded
}

Superseded is terminal — it is what split_time_task sets on a parent when it is replaced by children. It will never run and never complete. But it is not Complete, so it counts as "queued" in queued_tables and vetoes its cell out of want forever.

Measured against the real journal (logs source, keyed exactly as the veto keys it — project, date, physical_table):

cells with a non-Complete task but NO active work (vetoed forever):  357
cells with active work:                                              359
cells all-complete:                                                  591

Examples, all on the 1h tier:

('94c5dc1f', '2026-08-16', 'hboard_1h_v2')  {'complete': 14, 'superseded': 1}
('87576849', '2026-08-15', 'hboard_1h_v2')  {'complete': 24, 'superseded': 1}
('dcad860a', '2026-08-16', 'hboard_1h_v2')  {'complete': 14, 'superseded': 1}

Every real unit finished; one leftover superseded parent keeps the cell permanently unqueueable. 357 vetoed cells against cells_missing=210 — consistent magnitude, and it explains cells_wanted=0 with only 20 tasks actually pending.

The fix, and the risk

Narrow the predicate so only genuinely-live states block:

matches!(task.state, TaskState::Pending | TaskState::Retry | TaskState::Running)

The risk to check before shipping: Superseded is load-bearing elsewhere — coarsen_sealed_slices deliberately keeps it blocking so a split parent cannot be rebuilt and re-split in a loop (an existing test pins that, and it caught a too-broad change of mine earlier). That is a different function, so narrowing blocks_rollup_backfill should not affect it, but the loop question deserves a deliberate answer: if a cell is re-enqueued, splits, supersedes, and is still missing its tier, does it re-enqueue indefinitely? It would at least be making progress or surfacing a real failure rather than silently never running — but that should be a decision, not a side effect.

I have not implemented it. This is a one-line predicate change in code you are actively editing, and it should be validated by replaying the veto over the journal (the same method that killed my earlier scheduling fix) before deploying.

@tonyalaribe

Copy link
Copy Markdown
Contributor Author

Correcting my attribution: the 1m jump was probably a code fix, not just uptime

I 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.

d50b2c3, deployed 17:41, is:

fix(maintenance): estimate a slice by the share of each file it covers

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.

@tonyalaribe

Copy link
Copy Markdown
Contributor Author

Milestone: both tiers now at 30 days of DEPTH; the metric still reads 3

1m_tier_days = 35   contiguity 30   (goal met on both counts)
1h_tier_days = 30   contiguity  3   worst 5ce1c976
cells_missing 210, cells_wanted 0, derived_pending 20

The 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:

  1. 5ce1c976, ~1 row/day, whose dataless days score as full-day holes and pin the worst-project minimum;
  2. 357 cells vetoed forever by a terminal Superseded task (previous comment) — which is why cells_missing=210 never converts to cells_wanted.

Neither is a throughput problem, and neither needs more compute.

The question I am deliberately not answering

Whether 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.

@tonyalaribe

Copy link
Copy Markdown
Contributor Author

✅ GOAL MET: all four tiers at 30-day contiguity

otel_logs_and_spans_rollup_dashboard_1m_v3   contiguous_days = 30
otel_logs_and_spans_rollup_dashboard_1h_v2   contiguous_days = 30    (was 3)
otel_metrics_rollup_metrics_1m_v2            contiguous_days = 30
otel_metrics_rollup_metrics_1h_v2            contiguous_days = 30

cells_missing = 0        1h tier: 31 distinct dates in the last 30 days

rollup_min_contiguous_days — the goal metric, at 2 for this entire session and 0 for much of the week — is now 30 on every tier, including the 1h tier that governs 14d/30d dashboard latency. The worst project is 00000000 (the largest tenant) at 30, so the sparse-tenant artifact is no longer binding either.

Retraction: my "357 cells vetoed forever" claim

cells_missing went 210 → 0, so those cells did fill. My previous comment argued that a terminal Superseded task permanently vetoes its cell out of want, and predicted those cells could never be re-enqueued. That prediction was wrong. The work happened. The observation (357 cells with a non-Complete task and no active work, keyed exactly as the veto keys them) was real, but my inference about its consequence was not — those cells evidently get work through another path.

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 there

Not my work. In order of apparent contribution:

  1. d50b2c3 — "estimate a slice by the share of each file it covers", which fixed the byte estimate counting whole files. That was causing the fragment explosions (928 and 507 units on single project-days) that I spent the evening documenting.
  2. Sustained uptime. Once deploys stopped landing every ~15 minutes, units survived long enough to commit, and depth climbed steadily.
  3. The other maintenance fixes landing through the day.

What this PR is still worth

The 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 ~26 TB framing, the throughput analysis, and the Superseded claim should all be read with the corrections attached.

@tonyalaribe

Copy link
Copy Markdown
Contributor Author

Rollups are being USED: 91.5% hit rate on live traffic

Coverage 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:

rollup_hits_full_total     17,000
rollup_hits_hybrid_total   19,722     → 36,722 hits
rollup_misses_total         3,399     → 91.5% hit rate

misses:  not_built 2,492 · tiny_interior 819 · unknown_filter 46
         filter_not_eligible 22 · stale_coverage 20

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

not_built is 2,492 of 3,399 misses (73%). There is a recorded precedent where not_built was inflated to 5,454 of 5,516 purely because a date-level lookup that always misses after a restart poisoned miss.unwrap_or(<real reason>). Given coverage is now complete and the process is only 2h old, some of this is plausibly that same artifact rather than genuine gaps — worth checking before anyone treats 2,492 as real missing coverage.

tiny_interior (819) is a legitimate refusal — the query window is too small for the rollup's bucket to help.

What is still unmeasured

Latency. "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.

@tonyalaribe

Copy link
Copy Markdown
Contributor Author

The remaining gap is LATENCY on the rollup tier itself: 4.5–8.4s, not 1s

Measured 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;
38,297 buckets returned
run 1: 7.36s    run 2: 4.52s    run 3: 8.42s

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

goal component status
rollups up to date ✅ 30-day contiguity, all four tiers, cells_missing=0
rollups always used ✅ 91.5% routing hit rate on live traffic
14d/30d dashboards fast (~1s) 4.5–8.4s on the rollup tier alone

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 check

Whether 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.

@tonyalaribe

Copy link
Copy Markdown
Contributor Author

Why the rollup tier is slow to read: it is fragmented BY DESIGN and never compacted

Following the latency finding, I checked whether the rollup tiers get compaction. They do not, and it is deliberate. From plan_compaction_debt:

Every table EXCEPT a rollup tier. Packing a tier destroys the coverage [tags]. A tier file carries the identity tags recover_rollup_coverage reads — source, project, generation, source_fingerprint, slice_start … 119 HotPacking/SealedConsolidation claims targeted tier tables — and reported rollup_miss_not_built_total +45 as its sole miss reason.

So tier packing was tried, it stripped the identity tags, and it broke coverage — hence the exclusion. Meanwhile:

  • every rollup unit writes its own file (output_files=1 on every publication sampled)
  • publications run at ~10/min
  • nothing ever consolidates them

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 naming

The coverage mechanism and the read latency are in direct conflict:

  • coverage recovery needs per-file identity tags (source, project, generation, fingerprint, slice bounds)
  • read latency needs few, large files
  • the current compaction path cannot do both, so tiers were excluded from it

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 recover_rollup_coverage still finds what it reads.

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.

@tonyalaribe

Copy link
Copy Markdown
Contributor Author

Escalation: a full-table aggregate on the 1h tier now TIMES OUT at 60s

A coverage probe started failing (~30 min). It is not a false alarm, and it is not server load:

SELECT 1                                           → 0.27s     (server healthy, 46min uptime, no new OOMs)
SELECT min(date) FROM …_rollup_dashboard_1h_v2     → TIMEOUT at 60s

For comparison, the same tier with partition pruning (project_id = … AND date >= CURRENT_DATE - 30) returns in 4.5–8.4s. So:

  • pruned 30-day read: 4.5–8.4s (already 5-8x the goal)
  • unpruned full-tier aggregate: >60s, cannot complete

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.

@tonyalaribe

Copy link
Copy Markdown
Contributor Author

The tier is measurably degrading: +56% latency on +0.36% data

Re-ran the same pruned 30-day read ~4 hours after the first measurement:

                 earlier          now
rows returned    38,297     →    38,434     (+0.36%)
query time       ~6.8s avg  →    10.6s      (+56%)
contiguity       30 / 30    →    30 / 30    (holding)

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:

  • tiers are excluded from compaction (deliberately — packing strips the coverage tags)
  • every rollup unit writes its own file, ~10 publications/min
  • nothing consolidates them, ever
  • so read cost grows monotonically with time, not with data

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.

@tonyalaribe

Copy link
Copy Markdown
Contributor Author

Correction: the "+56% degradation" was noise, not a trend

I claimed the tier was measurably degrading (6.8s → 10.6s). A further sample contradicts that:

samples: 7.36s · 4.52s · 8.42s · 10.6s · 4.35s

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:

  • the result set is not stable between runs (38,434 rows, then 31,045), so I was comparing different amounts of work
  • each timing includes psql connect and is a single sample

What still stands, on better evidence

The level is not in dispute, and neither is the structural cause:

  • pruned 30-day read: 4.3–10.6s, against a 1s goal — every sample is 4-10x over
  • unfiltered aggregate on the same tier: times out at 60s (reproduced, server otherwise healthy at 0.27s for SELECT 1)
  • parquet.files_planned = 2,205,268 over parquet.scans = 21,582~102 files planned per scan
  • tiers are excluded from compaction by design, every unit writes its own file, nothing consolidates

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.

@tonyalaribe

Copy link
Copy Markdown
Contributor Author

Correction: the pruned tier read is NOT fragmentation-bound — it scans 34 files

EXPLAIN ANALYZE on the same pruned 30-day query:

files_scanned = 34

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 ~389ms per file open / 408 opens/sec measurement on the raw side.

The sharper diagnosis

The 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:

  • ❌ not "compact the rollup tiers" (34 files is already good, and packing breaks coverage tags)
  • ✅ reduce per-file cost: why does opening a small tier file cost ~200ms when the Foyer cache reports a 96.6% hit rate? Either these tier files are missing the cache, or the per-open path has fixed overhead beyond the fetch.

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 invalidates

The 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 files_scanned directly took one query and would have prevented the last three comments' worth of theory.

@tonyalaribe

Copy link
Copy Markdown
Contributor Author

Coverage survived the OOM; latency remains 4-18x the goal even warm

Coverage: an OOM restart happened at 10:39 (124.6 GB anon, exit 137, tokio-rt-worker — the known query-path series, ~19h after the previous, i.e. a normal interval). Both tiers still report 30-day contiguity afterwards. Coverage has now survived multiple deploys and a crash — it is durable.

Latency, same pruned 30-day query run back-to-back on a 47-minute-old process:

run 1: 18.5s     run 2: 10.0s
all samples to date: 4.3 · 4.4 · 4.5 · 7.4 · 8.4 · 10.0 · 10.6 · 18.5 s

Cache warming clearly helps (18.5 → 10.0), but the warm run is still 10s against a 1s goal — and with files_scanned=34, that is ~294ms per file warm. So the per-file cost is not purely fetch latency; there is fixed overhead per file open that caching does not remove.

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

component status
rollups up to date ✅ 30-day contiguity, all tiers, durable across restarts and an OOM
rollups always used ✅ 91.5% routing hit rate
dashboards ~1s ❌ 4.3–18.5s; ~294ms per file even warm, 34 files

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.

@tonyalaribe

Copy link
Copy Markdown
Contributor Author

Definitive: 8ms of CPU, 367 KB of data, 4-18s of wall clock

Full EXPLAIN ANALYZE operator timings on the pruned 30-day tier query:

count_files_scanned = 43
bytes_scanned       = 367.3 KB          → ~8.5 KB per file
elapsed_compute:  DedupExec 4.19ms · DeltaScanExec 2.13ms · DataSourceExec 740µs
                  ProjectionExec 598µs · FilterExec 470µs · AggregateExec 44µs
                  → TOTAL ≈ 8ms
wall clock        = 4–18s

Essentially 100% of the query is waiting, not computing. 8ms of CPU against 4-18s wall.

I was wrong to rule out fragmentation

Two comments ago I saw files_scanned=34 and concluded the tier was "not fragmentation-bound — 34 files is a healthy layout", and that compaction would not help. That was wrong, because I judged fragmentation by file COUNT and not by file SIZE.

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 files

Each rollup unit publishes its own file (output_files=1), a unit covers a narrow slice, and tiers are excluded from compaction to protect the coverage identity tags. So tiny files are the designed output and nothing ever merges them.

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: files_scanned alone was not enough. bytes_scanned / files_scanned is the number that matters, and it took one more field from the same query output to see it.

@tonyalaribe

Copy link
Copy Markdown
Contributor Author

Major revision: the 30-day tier read is now ~1.1s, and per-file cost is cache-state, not file size

Scaling test across window sizes on the 1h tier:

1 day    →  1 file,  17.5 KB  →  0.282s
7 days   → 24 files, 118 KB   →  0.307s
30 days  → 47 files, 371 KB   →  1.112s

Two conclusions, both revising what I previously called definitive:

  1. Warm per-file cost is ~13-24ms, not 200-300ms. 24 files costs essentially the same as 1 file (0.307 vs 0.282s) — file count is nearly free once cached. The ~200-300ms/file I derived earlier was cold-cache cost, and I generalised it as if it were the steady state.

  2. The 30-day read is now ~1.1s — essentially at the goal. Earlier samples ranged 4.3-18.5s. Either the recently deployed read-path fix (37a87e2 fix(read): columns are immutable by default, so point lookups reach the scan) improved it, or my repeated querying warmed the cache. I cannot separate those two from here, and I am not going to claim the one that flatters the analysis.

What this does to the fragmentation conclusion

The 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

component status
rollups up to date ✅ 30-day contiguity, durable through 3 OOMs and many deploys
rollups always used ✅ 91.5% routing hit rate
dashboards ~1s ~1.1s warm ✅ / 4-18s cold ❌ — depends entirely on cache state

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.

@tonyalaribe

Copy link
Copy Markdown
Contributor Author

Current state: 30-day tier reads are 1-2s, not 4-18s — and two invalid measurements to disclose

project 94c5dc1f (NOT queried by me before), 30 days:
  48 files, 14.27 KB total (~300 bytes/file), 516 rows   → 1.861s

project 00000000 (queried repeatedly), 30 days:
  47 files, 371 KB                                       → 1.112s

Both 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

  1. Three timings just before this were connection failures, not fast queries — PGURL was empty because the shell had reset to a directory with no .env, so psql fell back to a local socket and failed in ~30ms. "29ms cold read" was a broken command.
  2. One before that used project_id LIKE 'prefix%', which this codebase's own notes flag as changing the plan shape versus equality. Also invalid.

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 conclusions

The 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.

@tonyalaribe

Copy link
Copy Markdown
Contributor Author

Firmer number: 30-day tier reads are 2.3-3.9s, not 1-2s

Four samples, two projects, back-to-back:

00000000:  2.83s · 3.94s
94c5dc1f:  2.32s · 2.29s

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

measurement value
30-day tier read, current steady state 2.3-3.9s (n=4, two projects)
goal 1s
earlier readings during process churn 4-18s (transient, not steady state)
files scanned 47-48
bytes scanned 14 KB - 371 KB (i.e. ~300 B - 8 KB per file)

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.

@tonyalaribe

Copy link
Copy Markdown
Contributor Author

Proper benchmark: median ~1.3s, p90 ~2.9s — the variable is LOAD, not cache or file size

Six fixed-work samples, same project, back-to-back:

1.552 · 0.721 · 1.034 · 0.940 · 1.669 · 0.867     median ≈ 0.99s

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):

0.72 · 0.87 · 0.94 · 1.03 · 1.11 · 1.55 · 1.67 · 1.86 · 2.29 · 2.32 · 2.83 · 3.94
median ~1.3s      p90 ~2.9s      range 0.72-3.94s

Honest answer on the goal

The 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 doing

Not more of my ad-hoc timings. A p50/p90/p99 measured from real dashboard traffic over hours — the system already counts rollup_hits_*, so the latency histogram belongs next to it. Without that, any single measurement of this system (including all twelve of mine) is a coin flip between 0.7s and 3.9s.

@tonyalaribe

Copy link
Copy Markdown
Contributor Author

⚠️ Possible routing regression: hit rate 91.5% → 6.3%

On a 3-hour-old process, coverage verified at 30/30 contiguous on both tiers:

rollup_hits_full_total       9
rollup_hits_hybrid_total   129        → 138 hits
rollup_misses_total      2,052        → 6.3% hit rate

earlier today (2h process): 36,722 hits / 3,399 misses → 91.5%

Hits fell ~99% (36,722 → 138) while misses stayed comparable (3,399 in 2h → 2,052 in 3h). So this is not "less traffic" — queries are still attempting rollup routing at a similar rate and now failing to route.

Miss breakdown:

not_built           1,775   (86%)
filter_not_eligible   153
unknown_filter         94
tiny_interior          29
unaligned_bucket        2

not_built dominates — despite 30-day contiguous coverage being confirmed minutes earlier on the same process.

Two explanations I cannot separate from outside the box

  1. A genuine routing regression. 37a87e2 fix(read): columns are immutable by default, so point lookups reach the scan landed recently and touches the read path. If routing now takes a different path for these queries, this is the shape it would have.
  2. The known not_built artifact. There is precedent in this system for not_built being inflated to ~99% of misses by a date-level lookup that poisons miss.unwrap_or(<real reason>). If so, the real reason is masked and the hit-rate drop may be partly bookkeeping.

Given (2) has burned an investigation here before, I am not claiming a regression — but the hit rate is the metric the goal depends on ("rollups always used"), and it has moved by an order of magnitude in the wrong direction. That is worth a look before trusting the 91.5% figure earlier in this PR.

Cheapest next step: rollup_miss_sampled renders the actual refused plan. That is what turned a previous "97% missing_project" mystery into a one-line fix, and it would immediately distinguish (1) from (2).

@tonyalaribe

Copy link
Copy Markdown
Contributor Author

Follow-up: cannot resolve the hit-rate drop from outside, and a third explanation

rollup_miss_sampled — the diagnostic that renders the refused plan — logged 0 events in 30 minutes, so it is not firing and cannot distinguish the cases. I am also not running a dashboard-shaped query to test routing directly: that is the exact path that OOMed this instance three times today.

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 not_built bookkeeping artifact, or a diurnal traffic-mix shift. I cannot separate them safely from here, and I am not going to pick one.

What would settle it, cheapest first:

  1. make rollup_miss_sampled actually fire (it appears gated or sampled to zero) — it renders the refused plan and has previously turned this exact class of mystery into a one-line fix
  2. compare hit rate at the same hour tomorrow — controls for traffic mix without touching prod
  3. a latency/routing histogram beside rollup_hits_*, which is the durable fix for all of this

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.

@tonyalaribe

Copy link
Copy Markdown
Contributor Author

Hit rate reproduces at ~7%, but the miss reasons say traffic mix, not regression

Fresh process (36 min uptime, counters from zero):

hits:   5 full + 3 hybrid = 8
misses: 102                        → 7.3% hit rate

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:

this process:      filter_not_eligible 38 · unknown_filter 28 · not_built 24 · tiny_interior 12
previous process:  not_built 1,775 (86% of misses)

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 not_built-dominated window was the known bookkeeping artifact rather than real missing data, since coverage measured 30/30 in both windows.

Revised read on the earlier alarm

I 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 not_built artifact, not a regression from 37a87e2. Two independent windows at ~7% with different miss profiles is more consistent with "different queries arrive at different hours" than with "the read path broke".

I am still not calling it settled — the honest comparison is the same hour tomorrow.

One concrete lead

unknown_filter = 28 (27% of misses) is a catch-all meaning the router did not recognise a filter at all. That is not a refusal on the merits; it is a gap in the matcher, and it is the single largest addressable miss category in this window. Worth pointing rollup_miss_sampled at it — though note that diagnostic logged zero events in 30 minutes and may itself be broken or gated off.

@tonyalaribe

Copy link
Copy Markdown
Contributor Author

Why rollup_miss_sampled logs nothing: fixed 1-in-512 sampling, calibrated for a 50x higher miss rate

pub fn sample_rollup_miss() -> bool {
    const ROLLUP_MISS_SAMPLE: u64 = 512;   // 1 in 512 misses
    ...
}

The comment at the call site records why it was added: prod sat at ~2.7 misses/second (~9,700/hour), where 1-in-512 yields ~19 samples/hour — a reasonable trickle.

Current miss rate is ~170/hour (102 misses in 36 min). At 1-in-512 that is one sample every ~3 hours, which is why 30 minutes of logs contained zero.

The general shape, which is worth fixing

A fixed sampling ratio goes silent exactly when the diagnostic becomes most useful. While misses were a flood, 1-in-512 was right. Now that misses are a trickle, the survivors are precisely the interesting cases — the unknown_filter 27% that represents a real gap in the matcher — and the sampler hides them.

Options, cheapest first:

  • rate-based rather than ratio-based: sample at most N per minute, so the log rate is bounded whether misses are 3/sec or 3/min
  • sample per reason: one sample per MissReason per interval, so a rare-but-actionable reason is never crowded out by a common one
  • simply lower the constant, which fixes today's rate and breaks again at tomorrow's

This is the diagnostic that previously turned "97% missing_project" into a one-line fix, so restoring it is high leverage relative to its size — and it is the blocker on identifying what the unknown_filter misses actually are.

Filed as an observation rather than a patch: it is a one-line change in code others are actively editing, and the right choice among the three options is a judgement about log volume that belongs to whoever owns that budget.

@tonyalaribe

Copy link
Copy Markdown
Contributor Author

READ THIS FIRST — consolidated summary

This 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)

Coverage 30-day contiguity on all four tiers. Durable through 3 OOM kills and ~20 deploys. cells_missing=0.
What achieved it d50b2c3"estimate a slice by the share of each file it covers". The byte estimate had been counting WHOLE FILES, so a 10-minute slice estimated what a whole day would decode. Not my work.
Latency median ~1.3s, p90 ~2.9s, range 0.72–3.94s (n=12). Driven by instance load, which moves it 4-5x.
Routing 91.5% at 03:00; ~7% at 22:00–23:00 (reproduced across two processes). Most likely traffic mix, not regression.
OOMs ~125 GB anon, exit 137, query path (tokio-rt-worker). Bursty, not periodic — 19h gap, then two 10 min apart. Takes ssh down with it for ~10 min.

What I got wrong (do not act on these)

  1. "26 TB of irreducible decode" — real number, wrong framing. It was downstream of the estimator bug above.
  2. "Time-bisection is inherently wrong for whale days" — no; the estimate was wrong, so bisection fired when it should not have.
  3. "The Foyer data cache serves zero reads" — a try_read().unwrap_or_default() artifact. The cache runs at 96.6%.
  4. "~100x too slow, per-file latency bound" — the box does ~150 MB/s.
  5. "357 cells vetoed forever by a Superseded task" — observation real, consequence false; the cells filled.
  6. "The tier is fragmented, compaction is the fix""not fragmentation-bound" → both too strong; see latency row above.
  7. A scheduling fix I implemented and rejected — passed its regression test, made the target metric worse (blocking day's rank 5,375 → 12,940). Killed by journal replay before deploy. Branch fix/split-inherits-backfill-priority.

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

  1. Fix rollup_miss_sampled — fixed 1-in-512 sampling, calibrated for a 50x higher miss rate, so it now fires once per ~3 hours and shows nothing. Make it rate-based or per-reason. It blocks identifying the unknown_filter misses (27% of the addressable ones).
  2. A latency histogram beside rollup_hits_* — p50/p90/p99 from real traffic. Every ad-hoc measurement of this system, including all twelve of mine, is a coin flip between 0.7s and 3.9s.
  3. Compare routing hit rate at the same hour tomorrow — the controlled test for the 91.5% → 7% question.

Methods that worked and are worth reusing

  • Replay the pure comparator over the real journal in Python. Seconds, no build, no deploy — and it killed a wrong fix that had a green test.
  • Read publication.rows from the journal offline to distinguish "work never ran" from "work ran and found nothing".
  • EXPLAIN ANALYZEbytes_scanned / files_scanned, not files_scanned alone.
  • Check process uptime before reading any counter. docker service logs --since 24h only reaches back to the current container.

@tonyalaribe

Copy link
Copy Markdown
Contributor Author

Tantivy reindex is DIVERGING, and the nightly reconcile did not run

This is the neglected item from the standing goal ("continue the tantivy reindexing to a conclusion"). It is not converging — it is losing ground.

tantivy_uncovered_files:  3,031 → 4,074 → 4,870 → 4,905   (growing)
incremental indexing:     ~26 files/hour (tantivy_wave_reindex_complete)
net growth:               ~85 files/hour

Why: the only drain is a daily cron, and it did not fire

The incremental path (reindex_wave_outputs) only indexes files a maintenance wave just committed — it never touches the backlog. The backlog drain is a daily cron:

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.

"nightly reconcile" log lines in a 90-min window covering 03:30:   0
tantivy_uncovered_files across that window:                        4,870 → 4,905 (GREW)

So it either never fired, or fired and built nothing. It logs only when built/removed/blobs are non-zero (Ok((0,0,0)) => {}), so a no-op pass is silent — but with 4,905 uncovered files a working pass should have built plenty.

Candidate causes, not yet separated:

  • the cron did not fire (schedule parsing, or the 6-field sec min hour form not matching the parser's expectation)
  • tantivy_reconcile_table ran but its notion of "needs building" differs from the census's "uncovered"
  • let Some(svc) = db.tantivy_indexer() else { return } — silent early return; unlikely here, since the incremental waves prove an indexer is attached

Why it matters

Search 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 (0,0,0) case) with the count it considered. Right now a pass that does nothing and a pass that never ran are indistinguishable from outside — which is exactly the ambiguity I could not resolve here, and the same shape as the rollup_miss_sampled silence in #207.

@tonyalaribe

Copy link
Copy Markdown
Contributor Author

Correction: the tantivy reconcile DID fire — I checked 13 minutes into a multi-hour pass

My previous comment said the nightly reconcile "did not run". That was wrong.

03:30:33, 03:30:37, 03:30:40 …   "tantivy reconcile gc: table=…"  (11 lines)

It fired exactly on schedule. I looked for the summary line (tantivy nightly reconcile: table=… built=…), which only prints when a whole table finishes — and fair_tantivy_backfill_work applies no cap, so a pass over ~4,900 files runs for hours. I sampled 13 minutes in and read "no summary line" as "never ran".

What is actually wrong: the rate, not the firing

03:43  uncovered = 4,905
04:36  uncovered = 4,891      → net −14 files in ~53 minutes

The 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

  • ❌ "the reconcile never fires" — withdrawn, it fires on schedule
  • ✅ the divergence is real, and is a throughput problem: the drain is ~1.2x the arrival rate, so it cannot recover a backlog while also keeping up
  • the earlier point still stands that Ok((0,0,0)) => {} makes a no-op pass silent — but here the silence was a pass in flight, which is arguably worse: there is no "started" log and no progress log, so a running pass and an absent one look identical for hours

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.

@tonyalaribe

Copy link
Copy Markdown
Contributor Author

Tantivy: 2h into an active reconcile, the backlog is FLAT — it matches arrivals, it does not drain

Same container (up 7h), pass started 03:30 and still running at 05:28:

03:43  uncovered 4,905
04:36  uncovered 4,891
05:28  uncovered 4,905      ← back up
summary line:  not yet (pass still in flight, ~2h)

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 picture

While 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 it

Not "make the cron fire" (it fires) and not "log a summary" (though that would have saved me two wrong comments):

  1. Run it continuously at low priority instead of nightly. A pass that merely matches arrivals is useless once a day and sufficient if always on.
  2. Raise its build concurrency (timefusion_tantivy_build_concurrency) so a pass clears meaningfully more than arrivals — currently it is roughly break-even.
  3. Checkpoint progress, so a restart mid-pass resumes rather than restarting the sweep 24 hours later.

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.

@tonyalaribe

Copy link
Copy Markdown
Contributor Author

Tantivy: 4 hours of continuous reconcile, no measurable drain

The pass that started 03:30 is still running at 07:24 (zero tantivy_backfill_pass completion events in 3h). Backlog across that window:

03:43  4,905
04:36  4,891
05:28  4,905
06:20  4,928
07:24  4,935

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 fixes

I previously listed three options as roughly interchangeable. They are not:

  1. run continuously instead of nightlyinsufficient alone. A pass that does not drain in 4 continuous hours will not drain in 24.
  2. raise throughput (timefusion_tantivy_build_concurrency, or reduce per-file build cost) — now the primary lever. Nothing else changes the sign.
  3. checkpoint across restarts — still worth having, but it preserves progress that is currently ~zero.

Caveat on (2): budget.tantivy_peak_mb is 1536 and this instance OOMs at ~125 GB anon on the query path. Raising build concurrency raises peak memory, so it should be paired with a measurement of what a pass actually costs — which is precisely what #208's progress logging would make visible.

Honest status of this thread

The 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.

@tonyalaribe

Copy link
Copy Markdown
Contributor Author

A live instance of the failure mode: 4.5h reconcile killed by a deploy, zero progress retained

The pass that started 03:30 was still running when a deploy replaced the container at ~08:05.

03:30   reconcile starts (gc lines)
07:24   still running, backlog 4,935, zero completions
08:05   container replaced (deploy) — pass killed mid-flight
08:06   new container up 39s, backlog 4,945
next attempt: 03:30 tomorrow, ~19.5 hours away

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:

  • throughput — the pass could not finish 4,900 files in 4.5 hours
  • no checkpoint — whatever it did build is not recorded as progress, so tomorrow's pass starts over

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).

@tonyalaribe

Copy link
Copy Markdown
Contributor Author

The tantivy number that matters: ~72 seconds per file, at concurrency 2

timefusion_tantivy_build_concurrency = 2      (default, src/config.rs)
observed pass throughput            ≈ 100 files/hour
→ per worker                        ≈ 50 files/hour
→ per file                          ≈ 72 SECONDS

Against 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

  1. Reduce per-file cost. If 72s is dominated by round trips rather than CPU, this is where the order of magnitude is. Worth a profile of one build_index_for_file before assuming otherwise.
  2. Raise concurrency 2 → 4. Doubles throughput to ~200/hour, comfortably above the ~85/hour arrival rate, and would begin draining the 4,945 backlog. Memory cost looks modest: budget.tantivy_peak_mb is 1536, while the OOMs on this box occur at ~125 GB anon and are driven by the query path (tokio-rt-worker, bulk INSERT / wide scans), not tantivy.

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.

@tonyalaribe

Copy link
Copy Markdown
Contributor Author

OOMs cluster in pairs, minutes apart — consistent with a fatal query being RETRIED

Now observed on two independent occasions:

Aug 20:  14:10:43 · 14:20:04     (10 min apart)
Aug 21:  09:34:17 · 09:37:41     ( 3 min apart)
gap between clusters: ~19h

All four: ~125 GB anon, exit 137, invoked by tokio-rt-worker (query/ingest path).

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: gate_if_wide bounds scan concurrency but never one scan's size, and it logs wide_scan_oversize while admitting the scan anyway. A query large enough to OOM the box is admitted, killed, and then admitted again on restart.

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.

@tonyalaribe

Copy link
Copy Markdown
Contributor Author

⚠️ Crashloop: 3 OOM kills in 12 minutes — and NO oversized scans

09:34:17 · 09:37:41 · 09:45:43     three kills, ~125 GB anon each, exit 137
task states: Failed 12m ago · Failed 8m ago · Failed 45s ago · Running 39s

This is worse than the two-kill clusters seen previously — prod is cycling through roughly one-minute availability windows.

The negative result that matters

wide_scan_oversize events in the 15 min covering all three kills:  0
largest selected_mb:                                               (none logged)

No oversized scan was admitted during the crashloop. That rules out the wide-scan path I connected this to one comment ago — gate_if_wide admitting a 30 GB scan is not what is happening here.

It does not disprove the retry reading (a retried bulk INSERT would fit, and there is prior evidence that ingest, not queries, drives these — with pgwire mislabelling INSERTs as SELECT). But the specific mechanism I proposed is wrong for this cluster, and I would rather say so immediately than let it stand.

Where that leaves it

  • ✅ OOMs cluster (now 3, not 2 — clusters can be longer than pairs)
  • ✅ ~125 GB anon, exit 137, tokio-rt-worker every time
  • not attributable to oversized scans in this instance
  • ❓ ingest vs query still unresolved from outside

The attribution needs in-process evidence — in-flight statement shapes at OOM time, or a heap dump. Counters cannot separate "a query did this" from "an INSERT did this" when the pgwire layer labels them the same way.

Flagging rather than diagnosing: this is an availability event in progress, and the honest position is that I know it recurs, know its signature, and cannot name the trigger.

@tonyalaribe

Copy link
Copy Markdown
Contributor Author

Crashloop continues: 4 kills in 18 minutes, each process living 3-8 minutes

09:34:17 · 09:37:41 · 09:45:43 · 09:52:31      (~125 GB anon, exit 137, each)
process lifetime between kills: 3, 8, 7 minutes

What each boot does before dying: completes rollup coverage recovery successfully —

rollup_coverage_recovered  recovered=11,360  (otel_logs_and_spans)
rollup_coverage_recovered  recovered=11,233
rollup_coverage_recovered  recovered= 9,845  (otel_metrics)

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, hedged

A 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

  • in-flight statement shapes logged at OOM time
  • or RSS sampled per-second across a boot→kill cycle, which would show whether memory ramps steadily (replay/ingest) or spikes (a single allocation)

Both are in-process changes. From outside, the honest summary is: recurring, signature known, trigger unknown, currently in a sustained crashloop.

@tonyalaribe

Copy link
Copy Markdown
Contributor Author

Tantivy: the growth model is quantitatively confirmed

03:43  4,870
08:05  4,945     ← the 4.5h reconcile was killed by a deploy here
15:03  5,523     ← +578 in ~7h  =  ~83 files/hour

Predicted 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.

@tonyalaribe
tonyalaribe merged commit bda0a68 into master Aug 28, 2026
12 checks passed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant