From 3077f1b96e65a2993b468b9dd57feee80ec0dd9e Mon Sep 17 00:00:00 2001 From: Anthony Alaribe Date: Sat, 12 Sep 2026 12:35:04 +0200 Subject: [PATCH 1/2] Review group commit in production and record what it exposed MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Group commit works: journal_hold avg 5,452 -> 3,093 us and the lock's duty cycle 18.5% -> 14.5% at a comparable process age (NOT against the 29.6% from the 19h process — a mature process is not the comparator for a 44-minute one). PR #263 is separately confirmed by journal_stats_publishes at 0.80/s against a ~1/s target. The cost did not disappear, it became measurable. performed 30,075 + coalesced 30,506 = 60,581 waiters exactly, 11.4 fsync cycles/s is one per 88 ms, and 11.4 x 88 ms is the whole second — the commit pipeline runs at ~100% duty, so every arrival queues. block.journal_commit_wait averages 362 ms with a 10.7 s max, on the pre-ack path. The ~2x coalescing is OPTIMAL for arrival-rate x fsync-duration, so batching harder buys nothing; the lever is cost per commit. Three findings recorded: the deploy pipeline stranding merged code (observed live on #262, second instance after #251, fixed by #258); unbounded growth of Complete task history driving compact() under the global mutex; and the no-op rollup skip being defeated by restart frequency, which raises the value of the content-fingerprint tag follow-up. --- .../2026-09-12-group-commit-in-production.md | 126 ++++++++++++++++++ 1 file changed, 126 insertions(+) create mode 100644 docs/plans/2026-09-12-group-commit-in-production.md diff --git a/docs/plans/2026-09-12-group-commit-in-production.md b/docs/plans/2026-09-12-group-commit-in-production.md new file mode 100644 index 00000000..322c3c80 --- /dev/null +++ b/docs/plans/2026-09-12-group-commit-in-production.md @@ -0,0 +1,126 @@ +# Group commit in production: what it bought, and what it exposed + +2026-09-12. Reviewed against a 2,640 s (44 min) process running `1b391890` + +`16e925af` + PR #263, sampled from `timefusion_stats`. + +## Verdict: it works, and the remaining cost is now visible + +| metric | before (comparable age) | now | +|---|---:|---:| +| `journal_hold.avg_us` | 5,452 | **3,093** | +| `journal_hold` duty cycle | 18.5% | **14.5%** | +| `journal_lock_wait.avg_us` | 1,907 | 4,017 | +| `journal_stats_publishes_total` | n/a | **0.80/s** (target ~1/s) | + +Two separate wins are mixed in here and should not be conflated. PR #263 removed +the full-journal rescan from every checkpoint — `journal_stats_publishes` at +0.80/s against a design target of ~1/s says that is working exactly as intended. +Group commit moved the `fsync` **out from under the global mutex**, which is what +the duty-cycle drop measures. + +The comparison uses the 18.5%-at-34-min reading, not the 29.6% from the 19 h +process in the disk-flood doc. A mature process is not the comparator for a +44-minute one. + +## The cost did not disappear; it became measurable + +Group commit's own instrumentation is where the remaining cost now shows: + +| metric | value | +|---|---:| +| `journal_commits` | 30,075 (**11.4/s**) | +| `journal_commits_coalesced` | 30,506 | +| `block.journal_commit_wait.count` | 60,581 | +| `block.journal_commit_wait.avg_us` | **361,837 (362 ms)** | +| `block.journal_commit_wait.max_ms` | **10,687** | + +`performed + coalesced = 60,581` exactly, so every waiter is accounted for. + +**The coalescing ratio of ~2x is optimal, not disappointing.** 11.4 fsync cycles +per second is one per 88 ms; at 23 arrivals/s that is ~2 arrivals per cycle, and +a group can only contain what arrived before its leader read `covered`. Batching +harder buys nothing — the batch is already the whole arrival window. + +**The pipeline is at ~100% duty.** 11.4 commits/s × 88 ms = the entire second. +Every arrival therefore queues, which is what a 362 ms average with a 10.7 s +maximum means — and it is paid on the **pre-ack path**, so it is client latency. + +This is the correct diagnosis to carry forward: the lever is **cost per commit**, +not batch size. + +## Three fsyncs per commit, two of them optional + +A commit runs `TaskJournal::checkpoint` — one `sync_all` on the task WAL — and +then `persist_rollup_journal`, which calls `write_atomic_with(durable = true)`: +`sync_all` on the temp file, then `sync_all` on the parent directory after the +rename. **Two of the three are the rollup journal.** + +Only the task journal belongs in the pre-ack barrier: + +- `rollup_journal`'s module doc: *"scheduling state, not the read-side + correctness boundary … an absent dirty entry already means 'full rebuild + required' to the builder."* +- `maintenance_tasks` is documented as *"the finer-grained source of truth + coordinator workers consume"*, and is fsynced in the **same** commit. +- `rollup_dirty` has exactly one reader: requeueing partitions when bootstrap + tasks were *discarded*. + +So a lost second of the rollup journal weakens a backup whose primary is durable, +in the conservative direction. PR #265 throttles its write to once per second and +forces one at shutdown. + +**A content hash alone would have shipped inert.** `apply_rollup_hours` +increments the source epoch on *every* call, so the encoded journal genuinely +changes on every ingest invalidation. The hash covers the idle case only; the +time window is what covers the busy one. This was caught by the test failing +(13 writes where 1 was expected), not by reading the code. + +## Client latency, with the caveat stated + +| pgwire | 19 h process, pre-group-commit | 44 min, post | +|---|---:|---:| +| p50 | 1.0 s | **0.21 s** | +| p95 | 9.0 s | **3.5 s** | +| p99 | 47.9 s | **7.8 s** | +| p999 | 184.8 s | **16.8 s** | + +Directionally large and consistent with the fix, but **this is a 44-minute +process against a 19-hour one** and the journal, the queue and the caches all +differ. Treat as encouraging, not as the measurement. The number to re-read on a +mature process is `journal_commit_wait.avg_us`. + +## New findings + +**1. The deploy pipeline strands merged code — confirmed live, not historical.** +#262 merged 09:48Z, its `Build and Deploy` went green at 10:08:55Z having built +`be9722a5`, and the log ends `A newer master commit superseded this rollout; +production is unchanged.` The superseding commits were two **docs-only** pushes +at 09:56Z and 10:01Z, which start no rollout of their own. `docker service +inspect` reported `UpdatedAt=09:39:25Z` — merged code stranded for over an hour, +with a green job and nothing reporting the gap. This is the second observed +instance (the first was #251 on 09-10). **PR #258 fixes it and had been sitting +open since 09-10; merged today.** + +**2. Journal history grows without bound.** `tasks_complete` read 71,399 on +09-11 and 78,907 today — nothing prunes Complete tasks. `compact()` rewrites the +whole snapshot (48 MB on 09-11) under the global mutex at a size that tracks +history rather than load, which is where `journal_hold.max_ms` spikes of 3.5 s +come from. Bounded retention for Complete history is the fix; the audit value of +a two-week-old completed task is low against a cost paid on every commit. + +**3. The no-op rollup skip is being defeated by restart frequency.** +`rollup_noop_rebuild_skipped_total` read **0** on a 31-minute process and 38 on a +44-minute one, because boot-recovered coverage carries `content_fp: None`. +Production restarted **three times in two and a half hours** today. The +content-fingerprint tag follow-up in +`2026-09-11-noop-skip-production-result.md` is worth more than it looked when +written: it converts the skip from "effective after ~35 min of uptime" to +"effective immediately", and uptime is the scarce resource. + +## Not re-derived here + +The write-volume levers — tantivy `verify_blob` unpacking each index a second +time, and the unattributed DataFusion spill — already have a fix order in +`2026-09-11-write-latency-self-inflicted-disk-flood.md`. They remain the reason +an `fsync` costs 88 ms in the first place, and PR #265 only reduces how many of +them a client waits for. From ee1c37c4a40cf2d8cbd50e164f30867568513706 Mon Sep 17 00:00:00 2001 From: Anthony Alaribe Date: Sat, 12 Sep 2026 13:07:35 +0200 Subject: [PATCH 2/2] Record #262's production verification and how #258 unstranded it MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit #262 went live at 10:36Z once #258's merge pushed a non-ignored path — a docs merge deploys nothing, so stranded code needs a code push to land. At 31 minutes: 8 obsolete base files proven reproduced (no futile rebuild minted), 19 not (minted as before), base_generation_unverified = 15 retries over those 19 files. rollup_published_empty_over_full_base stayed 0 and rollup_median_contiguous_days stayed 30 — the silent-short-publish failure mode this change risked did not occur. --- .../plans/2026-09-12-group-commit-in-production.md | 14 +++++++++++++- 1 file changed, 13 insertions(+), 1 deletion(-) diff --git a/docs/plans/2026-09-12-group-commit-in-production.md b/docs/plans/2026-09-12-group-commit-in-production.md index 322c3c80..3ae456ac 100644 --- a/docs/plans/2026-09-12-group-commit-in-production.md +++ b/docs/plans/2026-09-12-group-commit-in-production.md @@ -99,7 +99,19 @@ at 09:56Z and 10:01Z, which start no rollout of their own. `docker service inspect` reported `UpdatedAt=09:39:25Z` — merged code stranded for over an hour, with a green job and nothing reporting the gap. This is the second observed instance (the first was #251 on 09-10). **PR #258 fixes it and had been sitting -open since 09-10; merged today.** +open since 09-10; merged today** (`d8944835`), and merging it was also what +finally rolled #262 — a docs merge deploys nothing, so stranded code needs a +push to a non-ignored path to land. + +#262 was verified live at 10:36Z and behaves as designed: at 31 minutes it had +refused 8 obsolete base files it could prove reproduced (no rebuild minted, no +32-minute livelock) and 19 it could not (rebuild minted, exactly as before), with +`retry.DerivedRollup.base_generation_unverified = 15` — one retry per unit over +those 19 files. **`rollup_published_empty_over_full_base` stayed 0 and +`rollup_median_contiguous_days` stayed 30**, which is the silent-short-publish +failure mode this change risked. The `reproduced`/`unreproduced` ratio should +improve as coverage matures; a young process has genuine holes, and prod has not +stayed up long enough today to read the steady state. **2. Journal history grows without bound.** `tasks_complete` read 71,399 on 09-11 and 78,907 today — nothing prunes Complete tasks. `compact()` rewrites the