bulk-ingest WAL never truncates — the cached ephemeral writer keeps the process at two fsqlite connections, so the 512 MB PASSIVE bound backfills but never resets

[bitjson]

(Fable 5:)

Title: main (0.7.0): bulk-ingest WAL never truncates — the cached ephemeral writer keeps the process at two fsqlite connections, so the 512 MB PASSIVE bound backfills but never resets; a 6.5 h Codex ingest grew an 11.6 GB WAL that is re-read at every batch boundary (per-conversation cost 20 s → 2 min, 20+ GB RSS). Residual of #178; fix validated locally

Summary

Long incremental cass index runs that ingest many large conversations get slower the longer they run, and the slowdown tracks the size of agent_search.db-wal, which never shrinks during the run:

• Ingesting 1,325 Codex rollouts (37 GB of JSONL, 113 files > 100 MB, largest 560 MB) into a 5.6k-conversation / 1.3 M-message archive on a main build (a06d389, cass 0.7.0): after 6.5 h and 1,040 rollouts the db was 14.2 GB and the -wal was 10.8 GB and had never been truncated; per-conversation wall time went from ~20 s to ~2 min over the run (~1 MB/s of source), cgroup memory 25–37 GB.
• /proc/<pid>/io sampled over 5 s during the run: rchar +2.35 GB, syscr +571k → ~114k preads/s of 4,119 bytes (one WAL frame) = 470 MB/s of WAL re-reads; cumulative rchar 7.9 TB after 5 h. The process holds two fsqlite connections on the archive (two agent_search.db-fsqlite-ns-use fds): the primary FrankenStorage and the cached ephemeral writer.
• The same 4 × 100 MB synthetic rollouts ingest into a fresh data dir in 36 s at 2 GB peak RSS, so parsing/redaction/lexical work are not the bottleneck; the cost is proportional to the WAL.

#178 (closed 2026-04-11) reported the same symptom and was closed on the strength of frankensqlite#66's single-connection TRUNCATE fast path. This is the residual: during bulk ingest cass is not single-connection, so that fast path never applies. Two independent investigations (one from fresh clones) reached the same mechanism.

Mechanism

1. Bulk (non-watch) ingest defers checkpoints: wal_autocheckpoint = 65_536 pages (BULK_IMPORT_WAL_AUTOCHECKPOINT_PAGES, src/indexer/mod.rs:27354 at 557bb53) plus the v0.6.19: full index still peaks at 13.4G physical footprint on 16GB macOS host #320 bound maybe_checkpoint_bulk_ingest_wal (:27431-27455), which issues PRAGMA wal_checkpoint(PASSIVE) (:27455) once the WAL exceeds CASS_INDEX_INGEST_WAL_CHECKPOINT_BYTES (512 MB, :27416).
2. Every batch is written through with_ephemeral_writer (:27507), which takes the cached writer connection (storage.acquire_cached_ephemeral_writer(), src/storage/sqlite.rs:4818; release_cached_ephemeral_writer :4876 keeps it open between batches). So for the whole ingest the process holds two connections to the archive.
3. On the pinned engine (frankensqlite =0.3.8, Cargo.toml:63): PASSIVE and FULL checkpoints never reset the WAL write position, and TRUNCATE/RESTART are silently downgraded to FULL unless the pager's process-local shared_connection_count == 1 (crates/fsqlite-pager/src/pager.rs:25734-25745 at v0.3.8). With the cached writer open, the engine's own autocheckpoint does not even fire, and every checkpoint restarts from frame 0 (no persisted backfill mark). Reported with a standalone repro as frankensqlite#385: one idle second connection turns a 4–32 MB oscillating WAL into a 371 MB monotonically growing one and makes TRUNCATE a no-op.
4. Consequences inside cass: once the WAL passes 512 MB, maybe_checkpoint_bulk_ingest_wal fires at every batch boundary (trace of a 1 GB run: 10 checkpoints in 45 s, each backfilling the entire WAL — log_frames == checkpointed_frames 186k → 241k, 1.6 → 3.7 s — while the WAL still grew 766 → 992 MB); fresh helper connections pay an O(WAL) open (WalFile::open reads and checksums every frame: 36 s at 565 MB in the engine bench); and the WAL-proportional pager state drives RSS. On the 11 GB WAL the per-batch re-read alone is ~25 s at 470 MB/s, i.e. the observed floor of ~20 s per conversation, growing with the WAL.
5. The end-of-run wal_checkpoint(TRUNCATE) (run_final_wal_checkpoint, mod.rs:16047) does reset the WAL (it runs on a fresh connection after the storage handle is closed), but its cost grows superlinearly with the size of the existing database when the WAL is large — the busy thread does 24-byte preads at offsets descending by 4,120 bytes (the engine's scan_backwards_for_page, reached from the checkpoint's pooled-EOF / freelist-trunk fold): ~60k frames took 3 s on an empty db, 7 min at 265 MB, 11 min at 519 MB, 12.5 min at 760 MB (table below). Quantified in frankensqlite#385.

Because CASS_INDEX_INGEST_WAL_CHECKPOINT_BYTES only changes when a PASSIVE checkpoint runs, it cannot bound the WAL at all on this engine; the #320 fix as shipped bounds nothing.

Reproduction (synthetic, no real sessions)

Generator — writes Codex-shaped rollouts (session_meta + response_item/event_msg lines, tool outputs with a real-shaped size distribution: p50 ≈ 0.7 KB/line, p99 ≈ 90 KB, max ≈ 2 MB, ~14k lines per 100 MB):

#!/usr/bin/env python3
# gen_rollouts.py OUTDIR --files N --mb-per-file M [--seed S]
import argparse, json, os, random, uuid, datetime

WORDS = ("cargo build error warning src/lib.rs fn let mut impl trait struct enum match "
         "Ok Err Some None Result Vec String usize i64 tokio async await frankensqlite "
         "index conversation message tantivy commit rollback wal page cursor btree").split()

def text(rng, nbytes):
    out, n = [], 0
    while n < nbytes:
        w = rng.choice(WORDS)
        if rng.random() < 0.08:
            w = f"{w}_{rng.randrange(10**6)}"
        out.append(w); n += len(w) + 1
    return " ".join(out)[:nbytes]

def rollout(path, target_bytes, rng, session_id, started):
    ts, n = started, 0
    with open(path, "w") as f:
        def emit(obj):
            nonlocal n
            line = json.dumps(obj, separators=(",", ":")); f.write(line + "\n"); n += len(line) + 1
        stamp = lambda t: t.isoformat(timespec="milliseconds").replace("+00:00", "Z")
        emit({"timestamp": stamp(ts), "ordinal": 0, "type": "session_meta",
              "payload": {"session_id": session_id, "id": session_id, "timestamp": stamp(ts),
                          "cwd": "/tmp/project", "originator": "codex-tui", "cli_version": "0.149.0",
                          "source": "cli", "model_provider": "openai",
                          "base_instructions": {"text": text(rng, 4000)}}})
        ordinal, call = 1, 0
        while n < target_bytes:
            ts += datetime.timedelta(seconds=rng.randint(1, 30)); s = stamp(ts); kind = rng.random()
            if kind < 0.06:
                emit({"timestamp": s, "ordinal": ordinal, "type": "response_item",
                      "payload": {"type": "message", "role": rng.choice(["user", "assistant"]),
                                  "content": [{"type": "input_text" if rng.random() < .5 else "output_text",
                                               "text": text(rng, rng.randint(80, 1500))}]}})
            elif kind < 0.36:
                emit({"timestamp": s, "ordinal": ordinal, "type": "response_item",
                      "payload": {"type": "reasoning", "summary": [{"type": "summary_text",
                                  "text": text(rng, rng.randint(100, 900))}], "content": None,
                                  "encrypted_content": text(rng, 400)}})
            elif kind < 0.66:
                call += 1
                emit({"timestamp": s, "ordinal": ordinal, "type": "response_item",
                      "payload": {"type": "custom_tool_call", "status": "completed",
                                  "call_id": f"call_{call}", "name": "shell",
                                  "input": json.dumps({"cmd": text(rng, rng.randint(20, 200))})}})
                ordinal += 1
                r = rng.random()
                size = (rng.randint(200_000, 2_000_000) if r < 0.015
                        else rng.randint(20_000, 120_000) if r < 0.115
                        else rng.randint(300, 12_000))
                emit({"timestamp": s, "ordinal": ordinal, "type": "response_item",
                      "payload": {"type": "custom_tool_call_output", "call_id": f"call_{call}",
                                  "output": text(rng, size)}})
            else:
                emit({"timestamp": s, "ordinal": ordinal, "type": "event_msg",
                      "payload": {"type": rng.choice(["agent_reasoning", "token_count", "agent_message"]),
                                  "text": text(rng, rng.randint(50, 600))}})
            ordinal += 1

def main():
    ap = argparse.ArgumentParser()
    ap.add_argument("outdir"); ap.add_argument("--files", type=int, default=4)
    ap.add_argument("--mb-per-file", type=float, default=100); ap.add_argument("--seed", type=int, default=1)
    a = ap.parse_args(); rng = random.Random(a.seed)
    base = datetime.datetime(2026, 7, 1, 12, 0, 0, tzinfo=datetime.timezone.utc)
    for i in range(a.files):
        started = base + datetime.timedelta(days=i)
        d = os.path.join(a.outdir, "sessions", f"{started:%Y}", f"{started:%m}", f"{started:%d}")
        os.makedirs(d, exist_ok=True)
        sid = str(uuid.UUID(int=rng.getrandbits(128), version=7))
        rollout(os.path.join(d, f"rollout-{started:%Y-%m-%dT%H-%M-%S}-{sid}.jsonl"),
                int(a.mb_per_file * 1e6), rng, sid, started)

if __name__ == "__main__":
    main()

Scaling loop — ingest 40 × 25 MB in four batches into one growing data dir (isolated HOME, only the synthetic CODEX_HOME is discoverable), watching the WAL and the per-batch wall time:

python3 gen_rollouts.py /tmp/cass-synth/gen --files 40 --mb-per-file 25 --seed 7
mkdir -p /tmp/cass-synth/home /tmp/cass-synth/codex-home/sessions /tmp/cass-synth/data
files=($(ls /tmp/cass-synth/gen/sessions/2026/*/*/*.jsonl | sort)); i=0
for b in 1 2 3 4; do
  for k in $(seq 10); do f=${files[$i]}; i=$((i+1)); rel=${f#/tmp/cass-synth/gen/sessions/}
    mkdir -p /tmp/cass-synth/codex-home/sessions/$(dirname $rel); ln -f $f /tmp/cass-synth/codex-home/sessions/$rel; touch /tmp/cass-synth/codex-home/sessions/$rel; done
  env -i PATH=/usr/bin:/bin HOME=/tmp/cass-synth/home USER=$USER CODEX_HOME=/tmp/cass-synth/codex-home \
      CASS_DATA_DIR=/tmp/cass-synth/data CASS_INDEX_STALL_ABORT_SECS=0 \
      CASS_TRACE_FILE=/tmp/cass-synth/b$b.trace CASS_TRACE_FILTER='warn,coding_agent_search=info' \
      /usr/bin/time -v cass index --json > /tmp/cass-synth/b$b.progress 2> /tmp/cass-synth/b$b.err
  echo "batch $b: $(grep -E 'Elapsed|Maximum resident' /tmp/cass-synth/b$b.err | tr '\n' ' ') db=$(stat -c %s /tmp/cass-synth/data/agent_search.db)"
  jq -c 'select(.fields.message|tostring|test("checkpoint|indexing_complete")) | {t:.timestamp[11:23],m:.fields.message[:50],f:(.fields|del(.message)|del(.db_path))}' /tmp/cass-synth/b$b.trace
done
# to see the in-run PASSIVE bound firing at every batch boundary without shrinking the WAL, run all 40 files in ONE run instead
# (WAL passes 512 MB around file 20) and watch: while sleep 2; do stat -c '%s' /tmp/cass-synth/data/agent_search.db-wal; done

Observed (Linux x86-64, cass 0.7.0 main a06d389, ext4)

batch	files total	ingest (index_ms)	total wall	max RSS	db after	final TRUNCATE checkpoint
1	10	16.5 s	19 s	1.5 GB	265 MB	60,399 frames, ~3 s
2	20	21.3 s	7 min 22 s	2.5 GB	519 MB	59,751 frames, ~7 min
3	30	24.7 s	11 min 33 s	3.4 GB	760 MB	~11 min
4	40	26.2 s	12 min 40 s	4.4 GB	1.01 GB	~12 min

Ingest is flat at ~11–13 MB/s; everything else is the end-of-run wal_checkpoint(TRUNCATE), whose busy thread issues 24-byte preads on the -wal fd at offsets descending by 4,120 for minutes (strace -p <tid>: ~30k such reads per second). During a single 40-file run the WAL passes 512 MB around file 20 and then bulk ingest passive WAL checkpoint fires at every batch boundary backfilling the whole WAL (log_frames == checkpointed_frames, growing) while -wal keeps growing to ~1 GB; on the real archive the same loop produced the 11.6 GB WAL and the 470 MB/s of re-reads.

Fix (validated locally on a06d389 + 3 unrelated analytics patches; ~140 lines)

Three steps in maybe_checkpoint_bulk_ingest_wal / with_ephemeral_writer; all three are needed on fsqlite 0.3.8:

1. Close the idle cached ephemeral writer before the checkpoint so the process holds one connection (new FrankenStorage::close_idle_cached_ephemeral_writer(&self) -> bool: takes the Cached variant out of cached_ephemeral_writer and closes it best-effort; leaves InUse alone), then issue PRAGMA wal_checkpoint(TRUNCATE) instead of PASSIVE (env CASS_INDEX_INGEST_WAL_CHECKPOINT_MODE=PASSIVE|FULL|RESTART|TRUNCATE, default TRUNCATE), log wal_bytes_after, WARN when the WAL did not shrink (an external reader pinning it is then visible instead of silently "bounded"). Keep persist_in_progress asserted across the synchronous checkpoint — a threshold-sized checkpoint on this engine can take minutes and emits no heartbeats, so dropping watchdog grace there would turn the fix into a new false-stall abort.
2. Refresh the primary connection's commit clock between closing the writer and the checkpoint — one point read is enough (SELECT value FROM meta WHERE key = 'schema_version'). Without it the run wedges: the primary sat idle with a cached read snapshot while the writer committed, and on this engine wal_checkpoint(TRUNCATE) stamps the database-header change counter from the checkpointing pager's own clock, so after the reset every BEGIN in the process derives a snapshot below the shared MVCC commit index and every insert fails with database is busy (snapshot conflict on pages: N) (mvcc write rejected due to stale snapshot … snapshot_high=25 commit_seq=49 conflict_reason=fcw_base_drift) until the run gives up with exit 7. Reproduced standalone and reported as frankensqlite#384; a PASSIVE checkpoint first or PRAGMA data_version do not repair it, any statement that begins a pager transaction (a read, BEGIN IMMEDIATE; COMMIT, a write, or reopening the handle) does.
3. Stay at one connection afterwards: mark the storage handle (bulk_single_connection) and have with_ephemeral_writer run later batches on the primary handle (apply the writer's busy-timeout / checkpoint-policy / foreign_keys = OFF pragmas to it) instead of re-opening the cached writer. A connection opened after the reset would derive the same stale clock (frankensqlite#384, "C" in its repro); and with one connection the engine's own wal_autocheckpoint (65,536 pages) picks TRUNCATE by itself, so the WAL stays small for the rest of the run.

Measured on the same 40-file / 1 GB synthetic single run (default 512 MB bound):

	index_ms	max RSS	in-run checkpoints	final TRUNCATE	exit
unpatched	129.3 s	4.4 GB	10 × PASSIVE full backfills, WAL grew 766 → 992 MB	240,863 frames, 8.5 s	0
CASS_INDEX_INGEST_WAL_CHECKPOINT_BYTES=0 (mitigation)	99.7 s	—	none, WAL ~1 GB	240,863 frames, 8.5 s	0
steps 1+3 only	—	—	1 × TRUNCATE 544 MB → 32 B (4.2 s), then every write rejected	—	7
steps 1+2+3	99.5 s	3.4 GB	1 × TRUNCATE 544 MB → 32 B (4.1 s, 132k frames), then the engine autocheckpoint keeps it small	6,252 frames, ~1 s	0

Same 4 × 10-file scaling loop as above with the fix (per-batch wall; index_ms stays flat at 18–26 s in every row):

batch	unpatched	fixed, default 512 MB bound	fixed, CASS_INDEX_INGEST_WAL_CHECKPOINT_BYTES=134217728 (128 MB)
1	19 s	20.9 s	17.6 s
2	7 min 22 s	7 min 33 s	4 min 08 s
3	11 min 33 s	11 min 17 s	6 min 12 s
4	12 min 40 s	10 min 06 s	5 min 41 s

And on a copy of a real 1.9 GB / 652k-message archive plus 4 × 100 MB synthetic rollouts (fixed build, default bound): exit 0, ingest 25.6 s, one in-run TRUNCATE 549,826,392 B → 32 B in 7.5 s, no stale snapshot line; peak RSS 22.9 GB and 3 h 27 m of wall were the unrelated open-time analytics rebuild of that copy (#424), not the WAL path.

The WAL never exceeded the bound in any fixed run and no stale snapshot line appears in any trace. What remains in those walls is the engine's checkpoint fold on a database the process opened with existing content (24-byte backward WAL-header reads at ~577k/s on the checkpointing thread, 218–341 s per TRUNCATE of a ~150 MB WAL on a 0.5–1 GB db; frankensqlite#385) — it runs once per batch either way (at the end on the unpatched/512 rows, mid-run on the 128 row where the end-of-run checkpoint then folds 4 frames). A lower default bound (128 MB) is worth considering: it halves the batch walls here and keeps the WAL, RSS and the final checkpoint small.

Also worth doing:

4. Make the bound conditional on the WAL actually having shrunk since the last checkpoint, so a pinned WAL (another process holding a read) does not trigger a full re-backfill at every batch boundary.
5. Cosmetic, same run: the rebuild_pipeline block of --json progress events (controller_mode, controller_reason, process_rss_bytes) is frozen at the values of the DB→lexical rebuild that ran before the scan and is never refreshed during streaming ingest — controller_mode: pressure_limited / pending_batch_conversations_98_reached_limit_32 with pending_batch_conversations: 0 for 6 h sends people looking at the wrong subsystem. Either refresh the snapshot from the streaming path or null the block when the rebuild pipeline is idle.

Workarounds (unpatched builds)

• CASS_INDEX_INGEST_WAL_CHECKPOINT_BYTES=0 for bulk ingests: removes the per-batch full-WAL backfill (the ~25 s/conversation floor on an 11 GB WAL) while changing nothing else; the WAL still grows until the run ends.
• Slice big ingests into many short cass index runs (per directory / per day): each run's end-of-run TRUNCATE resets the WAL because the cached writer is closed at exit — keep slices small, the end-of-run TRUNCATE cost grows with the archive (7–12 min per ~60k frames at 0.5–1 GB db here).
• Expect the final checkpoint of a long run to take a long time; do not interrupt it (CASS_INDEX_STALL_ABORT_SECS large).

Severity / scope

High for any archive that ingests more than ~0.5 GB of WAL in one run (large Codex/Claude transcripts, recovery re-ingests, first index of a big corpus): throughput degrades linearly with run length, RSS grows with the WAL (25–37 GB here), and the run ends with a multi-minute-to-hours TRUNCATE. No corruption observed; all data was committed. Code paths unchanged at main 557bb53.

[Dicklesworthstone]

Thanks for the mechanism trace and the validated three-step fix. The two-connection detail (the cached ephemeral writer keeping the engine's shared_connection_count above 1, so TRUNCATE silently downgrades and the 512 MB PASSIVE bound backfills without ever resetting) explains why #178's single-connection fast path never applied during bulk ingest, and the stale-snapshot trap in your step 2 is exactly the kind of engine interaction that makes this something to land deliberately with the engine side (frankensqlite#384/#385) rather than as a quick patch.

It is being considered on that basis; no timeline yet. Until then CASS_INDEX_INGEST_WAL_CHECKPOINT_BYTES=0 for bulk ingests is the honest workaround, as you note, together with slicing very large ingests into shorter runs so the end-of-run TRUNCATE stays small.

[Dicklesworthstone]

Fixed on main by cd3248c and the follow-up close-failure hardening in d29f882. The bulk-ingest path now closes the idle cached FrankenSQLite writer, refreshes the primary MVCC clock, performs a single-connection WAL checkpoint (TRUNCATE by default), remains on the primary connection afterward, and defers repeat attempts when an external reader prevents shrinkage. Focused regression coverage includes the checkpoint-mode parser, cached-writer close behavior, and an end-to-end oversized-WAL shrink/preflight write test in src/indexer/mod.rs. This is source-level closure on main; it is not yet available in a tagged release.