celilo/gascity

Fork 0

Every bead read costs 23-47s while 6-7 `gc dolt-state allocate-port` processes stand permanently open, and the provider state file records a dead pid for a server that is alive on the recorded port #34

New issue

Open

opened 2026-09-26 00:13:50 +00:00 by forgejo-admin · 1 comment

forgejo-admin commented

2026-09-26 00:13:50 +00:00

Owner

The measurement

gc bd show ce-trpw --json    exit 0 in 47s   (near-idle host)
gc bd show ce-trpw --json    exit 0 in 23s
gc bd show ce-trpw --json    exit 0 in 35s   (immediately after, same bead)

The second read of the same bead was slower than the first, so this is not cache-cold warm-up. It looks like queueing.

What is certainly abnormal

gc dolt-state allocate-port runs 6 to 7 concurrently, continuously, sampled three times at 3s intervals during a single gc bd show:

allocate-port procs mid-call: 7
allocate-port procs mid-call: 6
allocate-port procs mid-call: 6

These are not one-per-call transients that exit. There is a standing pile.

A candidate cause, NOT established

.gc/runtime/packs/dolt/dolt-provider-state.json reads:

{"running":true,"pid":37203,"port":59880,"data_dir":"...","started_at":"2026-09-23T12:51:24Z"}

pid 37203 is dead. The live server is pid 79387, started 2026-09-25 14:49:20, and it is listening on the same port the file records:

dolt  79387  TCP 127.0.0.1:59880 (LISTEN)

So the recorded port is correct and the recorded pid is not. If the provider-liveness check is pid-based, every gc invocation would conclude the provider is down and re-allocate, which would explain the standing pile. I did not verify that code path, so this is a hypothesis that fits the evidence, not a diagnosis.

There is exactly ONE dolt sql-server running. An earlier reading of mine suggesting four was a bad pgrep/lsof matching its own process; disregard any such claim.

A competing cause, also not excluded

celilo/gascity#8 (hq wisp table never sheds closed rows; dolt rewrites 313 MB of journal an hour and full-GCs every ~24 minutes) and #22 (reaper bulk prune never runs, so closed records accumulate) predict exactly this symptom. Current sizes:

.beads/dolt/hq   361M
.beads/dolt/ce   103M

hq being 3.5x the size of the busiest rig store is consistent with #8/#22 still being live. A dolt full-GC cycle would produce slow, variable, queue-shaped reads.

I cannot separate the two from here, and distinguishing them is the investigation this issue exists to hand off rather than to guess at.

Explicitly NOT recommending the obvious workaround

Hand-correcting pid to 79387 in the provider state file is the tempting one-field fix. I proposed it to the operator and then withdrew it, because:

Causation is unproven, so it may fix nothing while looking like a fix.
It is gc's runtime state, and this city has a written rule against hand-writing state files that blind readers then trust — .beads/backup/backup_state.json is the precedent, where a fabricated value would have armed a prune of 12,587 records.

If someone does try it, the discriminating test is whether the allocate-port pile disappears. If the pile goes and reads stay slow, the cause is #8/#22.

Why this matters beyond latency

The mayor's lift watcher polls the store and its queue-depth check does one gc bd show per queued bead. At 30s a read, a 5-deep queue takes 2.5 minutes per poll, so a watcher designed for a 2-minute cadence is effectively continuously hammering the store. Any tooling that loops over beads has the same shape. Slow reads here do not just cost time, they change the behaviour of everything built on top.

Measured 2026-09-25 00:00-00:20Z on the gc-scratch city by gastown.mayor. Every bead operation in the city is 23-47 seconds. It is not fatal — writes land and reads answer — but it gates the whole city: the refinery gates slowly, so its queue stays above the mayor's ceiling, so held work cannot be lifted. ## The measurement ``` gc bd show ce-trpw --json exit 0 in 47s (near-idle host) gc bd show ce-trpw --json exit 0 in 23s gc bd show ce-trpw --json exit 0 in 35s (immediately after, same bead) ``` The second read of the same bead was **slower** than the first, so this is not cache-cold warm-up. It looks like queueing. ## What is certainly abnormal `gc dolt-state allocate-port` runs **6 to 7 concurrently, continuously**, sampled three times at 3s intervals *during* a single `gc bd show`: ``` allocate-port procs mid-call: 7 allocate-port procs mid-call: 6 allocate-port procs mid-call: 6 ``` These are not one-per-call transients that exit. There is a standing pile. ## A candidate cause, NOT established `.gc/runtime/packs/dolt/dolt-provider-state.json` reads: ```json {"running":true,"pid":37203,"port":59880,"data_dir":"...","started_at":"2026-09-23T12:51:24Z"} ``` `pid 37203` is **dead**. The live server is pid `79387`, started 2026-09-25 14:49:20, and it is listening on **the same port the file records**: ``` dolt 79387 TCP 127.0.0.1:59880 (LISTEN) ``` So the recorded port is correct and the recorded pid is not. If the provider-liveness check is pid-based, every gc invocation would conclude the provider is down and re-allocate, which would explain the standing pile. **I did not verify that code path**, so this is a hypothesis that fits the evidence, not a diagnosis. There is exactly ONE `dolt sql-server` running. An earlier reading of mine suggesting four was a bad `pgrep`/`lsof` matching its own process; disregard any such claim. ## A competing cause, also not excluded celilo/gascity#8 (hq wisp table never sheds closed rows; dolt rewrites 313 MB of journal an hour and full-GCs every ~24 minutes) and #22 (reaper bulk prune never runs, so closed records accumulate) predict exactly this symptom. Current sizes: ``` .beads/dolt/hq 361M .beads/dolt/ce 103M ``` hq being 3.5x the size of the busiest rig store is consistent with #8/#22 still being live. A dolt full-GC cycle would produce slow, variable, queue-shaped reads. **I cannot separate the two from here**, and distinguishing them is the investigation this issue exists to hand off rather than to guess at. ## Explicitly NOT recommending the obvious workaround Hand-correcting `pid` to 79387 in the provider state file is the tempting one-field fix. I proposed it to the operator and then withdrew it, because: 1. Causation is unproven, so it may fix nothing while looking like a fix. 2. It is gc's runtime state, and this city has a written rule against hand-writing state files that blind readers then trust — `.beads/backup/backup_state.json` is the precedent, where a fabricated value would have armed a prune of 12,587 records. If someone does try it, the discriminating test is whether the allocate-port pile disappears. If the pile goes and reads stay slow, the cause is #8/#22. ## Why this matters beyond latency The mayor's lift watcher polls the store and its queue-depth check does one `gc bd show` per queued bead. At 30s a read, a 5-deep queue takes 2.5 minutes per poll, so a watcher designed for a 2-minute cadence is effectively continuously hammering the store. Any tooling that loops over beads has the same shape. Slow reads here do not just cost time, they change the behaviour of everything built on top.

forgejo-admin commented

2026-09-26 02:29:02 +00:00

Author

Owner

ROOT CAUSE FOUND, and it is neither of the two candidates in the issue body. THE DISK WAS FULL. Correcting this within the hour because the issue as filed sends the next reader after the wrong thing.

/dev/disk3s5   460Gi   410Gi   174Mi   100%   /System/Volumes/Data

174 megabytes free. Sequence, measured 2026-09-26 01:00-02:27Z:

.beads/dolt/hq grew 361M → 442M in under two hours. That is gascity#8's journal rewrite (hq never sheds closed rows) consuming the last of the volume.
dolt could not write its journal and crashed. .beads/dolt-server.log ends in a stack trace through nbs.(*ChunkJournal).Update → nbs.(*NomsBlockStore).updateManifest. Preserved as dolt-server.log.precrash.
After the crash: no dolt sql-server process, port 59880 refused, and every gc bead call returned Error: failed to open database: dolt circuit breaker is open: server appears down, failing fast (cooldown 5s).

So the 23-47s reads in the issue body were the precursor, not the defect: the volume was filling and every journal write was fighting for space. Then reads went from slow (exit 0) to failing (exit 1), and then the server died.

The allocate-port pile was a symptom, not a cause. I flagged 6-7 standing gc dolt-state allocate-port processes as "certainly abnormal". They are what gc does when the provider is unreachable, which it genuinely was. The stale pid 37203 in dolt-provider-state.json is real and still worth fixing — it is why gc would not START a replacement server, so it turned a recoverable crash into a hard stop — but it did not cause the slowness.

Recovery, for whoever hits this next. Freeing space alone did NOT bring it back; gc never restarts the provider. Two steps:

Free space. I cleared ~/.cache, ~/.bun/install/cache and ~/Library/Caches on the operator's approval: 174Mi → 7.3Gi.
Restart dolt from the data directory. dolt-server-config.yaml sets no data_dir, so dolt serves databases from its CWD. Started from .beads it comes up listening and then logs database not found: hq for every connection — it looks healthy on the port and serves nothing. It must be:

cd /Users/pbanka/gc-scratch/.beads/dolt
dolt sql-server --config /Users/pbanka/gc-scratch/.beads/dolt-server-config.yaml

After that: gc bd show exit 0 in 12s, answering from the rig "celilo" store, data intact across the crash (a bead merged minutes before it died reads closed correctly).

What should change in gc, in priority order:

A disk-space precondition before any dolt write, and a distinct error when the volume is near full. Every message in this incident — circuit breaker open, server appears down, database not found, project_id could not be confirmed — describes a consequence. Nothing anywhere said "the disk is full", which is the one fact that explains all of them. That is the whole cost of this incident: hours of investigation pointed at bookkeeping.
gc should be able to restart a provider it believes is down. The circuit breaker fails fast forever against a running: true state file naming a dead pid, so the city cannot self-heal from a crash.
gascity#8 is now load-bearing, not a performance note. hq's unbounded growth is what filled a 460G volume. It should be treated as a stability bug.

Also still true and unrelated: ERROR native_store_unavailable gate=identity_match reason="database project_id could not be confirmed" scope=/Users/pbanka/hobby/celilo printed on every call both before and after recovery, while reads answer correctly from the rig store. That looks like its own defect and is not part of this.

**ROOT CAUSE FOUND, and it is neither of the two candidates in the issue body. THE DISK WAS FULL.** Correcting this within the hour because the issue as filed sends the next reader after the wrong thing. ``` /dev/disk3s5 460Gi 410Gi 174Mi 100% /System/Volumes/Data ``` 174 **megabytes** free. Sequence, measured 2026-09-26 01:00-02:27Z: 1. `.beads/dolt/hq` grew 361M → 442M in under two hours. That is gascity#8's journal rewrite (hq never sheds closed rows) consuming the last of the volume. 2. dolt could not write its journal and **crashed**. `.beads/dolt-server.log` ends in a stack trace through `nbs.(*ChunkJournal).Update` → `nbs.(*NomsBlockStore).updateManifest`. Preserved as `dolt-server.log.precrash`. 3. After the crash: no `dolt sql-server` process, port 59880 refused, and every gc bead call returned `Error: failed to open database: dolt circuit breaker is open: server appears down, failing fast (cooldown 5s)`. So the 23-47s reads in the issue body were **the precursor**, not the defect: the volume was filling and every journal write was fighting for space. Then reads went from slow (exit 0) to failing (exit 1), and then the server died. **The `allocate-port` pile was a symptom, not a cause.** I flagged 6-7 standing `gc dolt-state allocate-port` processes as "certainly abnormal". They are what gc does when the provider is unreachable, which it genuinely was. The stale `pid 37203` in `dolt-provider-state.json` is real and still worth fixing — it is why gc would not START a replacement server, so it turned a recoverable crash into a hard stop — but it did not cause the slowness. **Recovery, for whoever hits this next.** Freeing space alone did NOT bring it back; gc never restarts the provider. Two steps: 1. Free space. I cleared `~/.cache`, `~/.bun/install/cache` and `~/Library/Caches` on the operator's approval: 174Mi → 7.3Gi. 2. Restart dolt **from the data directory**. `dolt-server-config.yaml` sets no `data_dir`, so dolt serves databases from its CWD. Started from `.beads` it comes up listening and then logs `database not found: hq` for every connection — it looks healthy on the port and serves nothing. It must be: ``` cd /Users/pbanka/gc-scratch/.beads/dolt dolt sql-server --config /Users/pbanka/gc-scratch/.beads/dolt-server-config.yaml ``` After that: `gc bd show` exit 0 in 12s, `answering from the rig "celilo" store`, data intact across the crash (a bead merged minutes before it died reads `closed` correctly). **What should change in gc, in priority order:** 1. **A disk-space precondition before any dolt write, and a distinct error when the volume is near full.** Every message in this incident — circuit breaker open, server appears down, database not found, project_id could not be confirmed — describes a *consequence*. Nothing anywhere said "the disk is full", which is the one fact that explains all of them. That is the whole cost of this incident: hours of investigation pointed at bookkeeping. 2. **gc should be able to restart a provider it believes is down.** The circuit breaker fails fast forever against a `running: true` state file naming a dead pid, so the city cannot self-heal from a crash. 3. **gascity#8 is now load-bearing, not a performance note.** hq's unbounded growth is what filled a 460G volume. It should be treated as a stability bug. Also still true and unrelated: `ERROR native_store_unavailable gate=identity_match reason="database project_id could not be confirmed" scope=/Users/pbanka/hobby/celilo` printed on every call both before and after recovery, while reads answer correctly from the rig store. That looks like its own defect and is not part of this.

No labels

No milestone

No project

No assignees

1 participant

Notifications

Due date

The due date is invalid or out of range. Please use the format "yyyy-mm-dd".

No due date set.

Dependencies

No dependencies set.

Reference

celilo/gascity#34

No description provided.

Rows
Columns

Every bead read costs 23-47s while 6-7 gc dolt-state allocate-port processes stand permanently open, and the provider state file records a dead pid for a server that is alive on the recorded port #34