Relationships
#2419 gcs-datastore: push spends almost all its time in an untraced gap between index read and first upload (81s in the #2408 login, up to 836s)
Opened by hammz · 9/23/2026
Description
When gcs-datastore push misses the fast path, nearly all of its time is spent in a phase that emits no spans. The push reads the _index/* shards (traced as GCS getObject). Then nothing is traced for minutes. Then it uploads the files (traced as gcs-datastore pushFile, putObject and putObjectCas), which takes about a second.
We can't tell from the traces what the push is doing in that gap. We need spans for it.
Evidence
All data is from Axiom swamp-serve-traces on the ops.swamp-club.com serve instance (scope.name = @swamp/gcs-datastore).
The #2408 login push (trace 7378ad76a022df64f1a52d18bb93c982, 2026-09-23):
| Time (UTC) | What |
|---|---|
| 15:21:55.056 | gcs-datastore push starts: root span, fast_path_hit: false, files_pushed: 8, cas_retries: 0 |
| 15:21:55.056 – 15:22:00.63 | 552 GCS getObject reads of _index/*, ending with every _index/workflow-runs--<uuid>.json |
| 15:22:00.63 – 15:23:21.497 | 81 s with no child spans |
| 15:23:21.497 – 15:23:22.55 | 8 pushFile, 8 putObject, 2 putObjectConditional, 6 putObjectCas |
| 15:23:22.553 | Push ends (87.5 s) |
The 8 files are the server token that the login mint created (data/swamp/server-token/76dbcabe…/token-main/*, auto-definitions/swamp/server-token/oauth-34441afb.yaml), plus 4 older server-token/redeem outputs. So this gap is most of the 88 s login delay in #2408.
The same pattern holds across pushes. Over the last 24 h, 98 pushes took longer than 10 s. All of them missed the fast path (0 of 359 pushes in that period hit it):
| Push duration | Count | Share of time before the first pushFile |
|---|---|---|
| 10–30 s | 2 | 88% |
| 30–120 s | 17 | 96% |
| 2–10 min | 28 | 94% |
| > 10 min | 51 | 100% |
The median push took 651 s: 650 s before the first upload and 1.2 s after.
The slowest push (trace bffd0988174bdc9ca386cfb63cc087fb, 841 s, 142 files) has the same shape. Its index reads finish at 09:39:39. The next span is a pushFile at 09:53:36, 836 s later. Every other gap between its child spans is under 1 s. Its root span also has no files_pushed or cas_retries attributes, and its 142 pushFile spans come with only 106 putObject spans. That push may not have finished normally.
What the gap is not
- Not the serve sync gate. ops.swamp-club.com runs core
375d7eca, which predates the gate (see #2418). - Not waiting on the poller pulls. During the 81 s gap, the pollers'
gcs-datastore pullspans (trace0c75cc64…) left idle windows of 10–15 s (15:22:09.6–15:22:24.4, 15:22:39.9–15:22:54.4, 15:23:10.8–15:23:21.5). The push didn't resume in any of them. - Not a stalled process. Other spans kept arriving in 30 s bursts throughout the gap.
- Not a traced lock wait. Neither trace contains a
gcs-datastore lock acquireorswamp.lock.acquirespan, although those spans exist elsewhere in the dataset (p95 about 67 s over 6 h). If the push waits on the datastore lock, that path doesn't emit the span.
What we want traced
Child spans under gcs-datastore push for every phase between reading the index and the first upload. Each span should carry attributes that show where the time goes. For example:
- Any lock or lease acquisition: wait time, attempts, backoff.
- Working out what changed: walking the local mirror, stat or hash of each file, and comparing against the index (files scanned, bytes read, dirty paths found).
- Index assembly or merge, and any conflict or retry loop.
- Any other waits, sleeps or retries.
Also:
- Set the push span's result attributes (
files_pushed,cas_retries) and status on every exit path, including errors and aborts. - Record a span event when the push misses the fast path, with the reason (for example sidecar vs remote
commitSeq, orlazyPullActive; see #2418 and #2242).
Steps to reproduce
- On a serve instance using
@swamp/gcs-datastorethat misses the push fast path, do anything that pushes, for exampleswamp auth server-login. - In the exported traces, open the
gcs-datastore pushspan. The index reads are followed by a long gap with no child spans before the firstpushFile.
APL for the per-push breakdown:
['swamp-serve-traces']
| where name in ('gcs-datastore push', 'gcs-datastore pushFile')
| summarize pushes=countif(name == 'gcs-datastore push'),
push_start=minif(_time, name == 'gcs-datastore push'),
push_dur=maxif(duration, name == 'gcs-datastore push'),
first_upload=minif(_time, name == 'gcs-datastore pushFile')
by trace_id
| where pushes == 1 and push_dur > 10sRelated
- #2408: slow
server-login; this gap is where most of its time goes - #2417: missing request and login spans in serve
- #2418: lazy hydration stops the fast path from being used
- #2242: fast-path misses and
commitSeqnot advanced after scoped pushes
Upstream repository: https://github.com/systeminit/swamp-extensions
Environment
- Extension:
@swamp/gcs-datastore@2026.09.23.1 - swamp:
20260923.142649.0-sha.379bb5f0 - OS:
linux(x86_64) - Deno:
2.9.7 - Shell:
/usr/bin/zsh
Open
No activity in this phase yet.
Sign in to post a ripple.