perf: intermittent multi-second query stalls — undiagnosed, and the first diagnosis was wrong

[vishr]

Split out of #232 (item 32).

Correction, before anything else

The first version of this issue said the stalls were "rollup/maintenance contention on the DuckDB write mutex". That mechanism does not exist. There is no writeMu; PR #207 (c3dc7d92 feat(storage)!: adopt authoritative Parquet) removed DuckLake, its SQLite catalog and that lock. git log -S writeMu -- internal/ ends at that commit.

The claim came from a stale mental model, not from a measurement. #232 item 32 said "consistent with rollup/maintenance contention on the write mutex" — an inference. Nothing timed a lock.

What the locks actually are today:

• writegate.WriteGate (internal/query/writegate/write_gate.go:28) serialises writes to the rebuildable rollup cache only. Taken at internal/query/duck.go:278, 551, 608, 729, 852 — all of them rollup or maintenance. No read takes it, and ingest never takes it (internal/ingest/server.go → store/writer.go:63 → repository.Commit → ParquetStore.CommitBatch; no DuckDB in that path).
• parquetReadGate (internal/query/parquet_gate.go:31) pins the Parquet directory set for readers across a compaction or prune rename. This is the only lock a read can wait on.

What is actually observed

One pass measured 9.0s for performance and 12.7s for logs at the 1h window, where repeat calls on the same window and the same data ran 440–550ms. Not correlated with data volume. That is all the evidence there is.

Candidate mechanisms, none yet confirmed

(a) Publish-gate queuing — design, with a bug-shaped blind spot. parquetReadGate admits readers while a publisher waits, but only for defaultWriterGrace = 30s (parquet_gate.go:13); after that, new readers queue so retention and compaction cannot be starved. Publishers arrive every 10s (parquetCompactionCycle, duck.go:83) whenever ≥8 batches are eligible, and hourly from maintenance. The grace was written for "ordinary dashboard traffic" — but the edge rollup is itself a reader that can hold the snapshot for tens of seconds, and it inherits the same grace (duck.go:1054-1065 admits no timeout can bound it from outside). If a publisher queues behind a long rollup, every API read pays the rollup's remaining hold. That widening is not justified by any comment, and is the part of this that is a defect rather than a trade-off. For it to yield 9–12s on a lightly loaded demo the rollup would have to hold ~40s, which nothing here shows.

(b) Connection-pool exhaustion — a plain bug if confirmed. The pool is sized at one connection per core, floor 2, cap 16 (internal/config/sizing.go:165). On the 4-vCPU reference host that is four connections, shared by API reads, the detector (every 60s), the alert engine (every 30s), readiness probes, and the rollup — which holds one for its whole pass. A dashboard fires ~5 widget queries at once. A queued request waits behind the slowest holder, and database/sql's WaitDuration is exported nowhere.

(c) DuckDB's own automatic checkpoint. The rollup re-deletes and re-inserts the trailing buckets every minute, which is steady WAL churn; nothing sets checkpoint_threshold, and a checkpoint blocks new transactions for its duration. Unmeasured.

(d) Cold Parquet bind. Every query re-expands batches/*<suffix>/<signal>.parquet with union_by_name (views.go:308), reading every footer. Cost scales with file count; unlikely while footers are in page cache.

How to settle it — mostly without writing code

Read /-/metrics on the instance that stalls:

• fanout_parquet_publish_wait_seconds (buckets to 60) and fanout_parquet_publish_timeouts_total. Mass above le="30", or any timeouts, proves (a) fired. None → (a) is dead.
• fanout_write_gate_hold_seconds{operation="rollup_edge"}. If the max hold never approaches 30s, the rollup cannot have closed the gate.
• Correlate slow-request timestamps against the 60s rollup cadence and the 10s compaction cycle. Grep the log for wait for Parquet publication and telemetry maintenance failed.

Then add the four series nobody has:

• fanout_parquet_read_wait_seconds in lockParquetRead (duck.go:1681) — the reader half of a wait/hold pair whose writer half already exists. This is the single most valuable line in the issue.
• Publish hold (the swap itself) around publish(swapCtx) (duck.go:1677).
• DB.Stats() WaitCount / WaitDuration / InUse as fanout_duckdb_pool_*.
• wal_size from PRAGMA database_size per rollup tick.

A stalled request then decomposes into gate wait + pool wait + execute, and whichever term carries the 9 seconds names the mechanism. The external harness at fanout-bench already samples /-/metrics each second and rotates these exact queries, so the new series only need adding to its sample list.

Fix, once a mechanism is named

Two changes are worth making regardless, because each removes a candidate outright:

1. Give background writers their own connection. Open a second handle with SetMaxOpenConns(1) and route the rollup and maintenance transactions through it, leaving the pool for reads. Both handles share one DuckDB instance, so views and cache tables are identical. This kills (b) and stops the rollup from eating a quarter of a small host's read capacity.
2. Bound the rollup's snapshot hold to one unit of work. Commit and release parquetMu after each edge sub-window rather than holding across up to eight of them. The resume cursor already makes each sub-window independently resumable; rawMaxProcessed must stay computed once per pass so the watermark safety lag is unaffected.

The thorough version of (a) is to make the gate reader-class aware: internal batch readers yield when a publisher is queued, so a publisher never waits more than one unit of work and the API grace never expires. API readers keep the 30s grace.

Do not tune the budgets. defaultWriterGrace, parquetDrainBudget and parquetSwapBudget are the symptom's ceiling, not its cause.

Separate finding, worth its own ticket

duck.go:564 runs the non-FORCE CHECKPOINT, which fails if any transaction is active. On a live instance with a detector, an alert engine, readiness probes and dashboards, the hourly maintenance pass likely errors intermittently and marks /readyz degraded. Check the demo log for telemetry maintenance failed before opening it.

[vishr]

Reproduced locally, with an A/B against main: same data, same load, same 4-connection pool — main peaks at 21.6s with 14 requests over 2s, the branch in #242 at 2.6s with one.

The mechanism is not the publish gate: over 29,737 admissions the snapshot wait averaged 8µs, with zero refusals and zero publish timeouts. It is connection-pool contention — 20,249 waits totalling 300s — with the edge rollup's transaction, which holds for 9.8s on average, occupying a read-pool connection on main.

Candidate (a) is effectively ruled out for this shape of load; (b) is confirmed as a real mechanism that produces exactly the reported signature (three independent endpoints stalling simultaneously). Details and the full table are on #242.