Skip to content

Store a resent span once instead of rewriting it - #18

Merged
RhysSullivan merged 1 commit into
mainfrom
fix/store-resends-once
Nov 12, 2026
Merged

RhysSullivan merged 1 commit into
mainfrom
fix/store-resends-once

Conversation

@RhysSullivan

Copy link
Copy Markdown

Problem

An exporter that times out waiting for the collector's acknowledgement sends the same export again; OTLP requires it, and Effect's exporter resends up to three more times. The store found each span already stored and deleted and rewrote its row, its attribute rows and its operation-index entry. At its size bound under traffic, the collector answers slowly, so exports time out and are resent, and every resend costs more than the original. On Executor's self-host beta.40, an instrumented copy of this collector stored one resent 1,000-span export in 16.6 s, 12.3 s of it deleting attribute rows. A collector that was already too slow got slower with each resend.

Fix

A span whose stored row already holds exactly the exported values is skipped: one indexed lookup instead of a delete and rewrite. A re-export that changes anything still replaces the row, as before.

const stored = storedSpan.get(traceId, spanId)
if (stored !== null && sameStoredSpan(stored, row)) {
	insertedSpans += 1
	continue
}
if (stored !== null) replacedSpans.push([traceId, spanId])

Nothing else changes: not eviction, not batch sizes, not admission or routing. File worth reading: src/services/TelemetryStore.ts, ingestTraces.

Notes from review:

  • A skipped span still counts in insertedSpans: it is stored, and the exporter's acknowledgement should say so.
  • Identity is exact. A resend whose attribute keys arrive in a different order serialises differently and is rewritten, as before.
  • Comparing a span against its stored JSON costs time in proportion to its payload, so a changed span costs a lookup and a compare on top of the rewrite.

How it was tested

  • New stores an identical resent export without rewriting its rows (telemetry.test.ts): on main the second export deletes and reinserts every attribute row; here the row ids are unchanged. The existing replaces a re-exported span's operation in the search index once still passes.
  • bun run test: 220 pass. refuses ingest beyond its queue and size bounds failed once with ECONNRESET on its oversized body and passed on rerun; it fails the same way on main.
  • Replay benchmark below.

Replay benchmark. The collector alone, with beta.40's workerd and bindings, on copies of one full 1 GiB store of product-shaped traces. The exporter behaves like the product's: 1 s interval, 1,000-span batches, 5 s timeout, three resends, 60 s pause after a lost batch. Each run is 4 minutes on a shared Linux host. There is one run per row, main then this change, so neighbouring rows ran under similar load.

Rate Version Spans stored Exports lost Attempts timed out Disk writes Written per stored span
500 spans/s main 46,226 (193/s) 21 of 89 94 67.6 MiB/s 359 KiB
500 spans/s this change 119,288 (497/s) 0 of 153 25 127.2 MiB/s 262 KiB
1,000 spans/s main 39,336 (164/s) 39 of 90 169 98.2 MiB/s 614 KiB
1,000 spans/s this change 66,500 (277/s) 24 of 105 123 89.2 MiB/s 330 KiB
  • At 500 spans a second, about twice what the product exports at 2.4 MCP calls a second, the resends turned slow eviction batches into a collapse. Without the rewrite there is none: no export was lost and every span was stored.
  • At 1,000 spans a second this change stores 70% more and loses fewer exports, but it does not prevent the collapse. Past that rate the eviction batches themselves are the limit (first follow-up below).
  • Disk writes per second rise with the spans actually stored. Writes per stored span fall by 27% at 500 spans a second and by 46% at 1,000, because resends are no longer rewritten.
  • The store stayed within its bound in every run: peak used 1,021–1,023 MiB.

Relation to other PRs

Follow-ups: the collector as shipped

Found while investigating Executor issue #2194; none is changed here.

  • Eviction holds the collector. At the bound under traffic, a batch of the 100 oldest traces took 1.6–4.8 s, and every export waited behind it.

  • Write volume. The collector writes about 0.26 MiB per stored span at the bound (WSL2 measurement). The causes:

    • resource attributes are copied into every span's attribute rows;
    • each attribute row is written to four b-trees, and idx_span_attributes_trace_span duplicates the primary key's prefix;
    • the operation index is keyed by an UNINDEXED trace_id, so each eviction batch reads the whole index;
    • every page is written twice, to the WAL and then by the checkpoint.

    On a shared disk this volume slows other processes' writes.

  • Storage amplification. Stored spans take about 5× their export JSON for product spans, and up to about 70× for an export whose resource attributes are shared by many spans (a 76,789-byte export stored about 5.5 MB).

  • Log orphan sweep. A pass's sweep is capped by attribute rows, not by deleted logs.

  • Pending exports. Executor's local CLI collector allows 16 pending exports of up to 16 MiB each; self-host allows 4.

  • Bound with nothing left to evict. FTS segment pages can keep a store over its bound when no rows remain to evict (details below).

A store over its bound with nothing left to evict (probe on main, workerd, 4 MiB bound).

  • One valid 2.98 MB export of 1,000 spans whose operation names hold about 300 distinct words each was accepted. Eviction then removed every span and search row, but about 1,900 FTS segment pages left the store at about 8 MB used.
  • Each of the next 115 exports was acknowledged with 200, stored, and evicted again in the same request: the eviction pass after an export takes the oldest completed trace, which is the one just stored. Reading /api/traces/<id> right after each export found nothing.
  • The store recovered only when incremental FTS merging (100 pages per pass, after each export and every 10 s) had reclaimed the segment pages. After that, new traces were kept.
  • Until then the collector looks empty to its user while it acknowledges every export. How long that lasts scales with the FTS backlog.

An exporter that times out waiting for the acknowledgement sends the same export again. The store found each span already stored and deleted and rewrote its row, its attribute rows and its operation-index entry. On a full store under traffic one resent 1,000-span export took 16.6 s, so a collector already too slow to answer got slower with every resend. A span whose stored row already holds exactly the exported values is now skipped; a re-export that changes anything still replaces it.
@RhysSullivan
RhysSullivan marked this pull request as ready for review November 12, 2026 16:35
@RhysSullivan
RhysSullivan merged commit b4638ef into main Nov 12, 2026
1 check passed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant