Skip to main content
← Back to list
01Issue
BugOpenExtensionsPublic
AssigneesNone

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 pull spans (trace 0c75cc64…) 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 acquire or swamp.lock.acquire span, 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, or lazyPullActive; see #2418 and #2242).

Steps to reproduce

  1. On a serve instance using @swamp/gcs-datastore that misses the push fast path, do anything that pushes, for example swamp auth server-login.
  2. In the exported traces, open the gcs-datastore push span. The index reads are followed by a long gap with no child spans before the first pushFile.

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 > 10s
  • #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 commitSeq not 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
02Bog Flow
◉OPEN○TRIAGED○IN PROGRESS○SHIPPED

Open

9/23/2026, 5:21:38 PM

No activity in this phase yet.

03Sludge Pulse

Sign in to post a ripple.