Skip to content

Bound eviction batches, refuse exports over the bound, store identical resends once - #17

Draft
RhysSullivan wants to merge 4 commits into
mainfrom
fix/motel-at-bound
Draft

RhysSullivan wants to merge 4 commits into
mainfrom
fix/motel-at-bound

Conversation

@RhysSullivan

@RhysSullivan RhysSullivan commented Nov 11, 2026 •

Copy link
Copy Markdown

Superseded by the smaller resend-only change in UsefulSoftwareCo/motel#18: three review rounds each found a new failure mode in the batch cap and admission check, which together amount to a redesign of the storage policy; kept open as a draft for Rhys to close.

Problem

A full store under steady export load fell behind. On Executor's self-host beta.40 at 2.4 MCP calls a second (about 250 spans a second), the bundled collector reached its 1 GiB bound after about 13 minutes. In the next 7 minutes the product logged 92 Telemetry export failed warnings (traces transport with timed_out, interrupted; app relay timeout). The collector refused exports as queueFull (4 of 4 pending) and as invalid with "Network connection lost", which is the product hanging up mid-export. An idle full store is fine; #14 fixed that.

Cause

Two parts that feed each other. The timings come from an instrumented copy of this collector serving that product under load:

  • One eviction batch had no size limit. A batch took the 100 oldest traces whatever their size. Product traces average about 70 spans, so one batch deleted 7,000–8,000 spans in one uninterrupted run of 1.6–4.8 s; DELETE FROM span_attributes WHERE trace_id IN … alone took 2.7–3.5 s. The 500 ms pass budget is checked only between batches. Every export waited behind the batch, past the exporter's 5-second timeout.
  • A resend was stored all over again. An exporter that times out sends the same export again. The collector deleted and rewrote every row and index entry of each span. One resent 1,000-span export took 16.6 s, 12.3 s of it deleting attribute rows.

Fix

  • Batches are capped by spans. A batch stops before the trace that would take it past MOTEL_OTEL_RETENTION_SPAN_BATCH spans (default 1,000).
  • The workerd collector refuses exports while the store is over its bound. The check lives in the store's ingestTraces and ingestLogs, which every stored export passes through, whatever route or path spelling it came by. The typed routes also store from /v1/traces/, //v1/traces, /v1/Traces and /v1/%74races; before, these skipped the collector's checks.
    • An export that finds the store over MOTEL_OTEL_MAX_DB_SIZE_MB runs one eviction pass. If the store is still over, the export is refused: 429 with Retry-After: 1 on the bounded ingest route, which every spelling of an ingest path now takes, counted as overBound in GET /api/ingest.
    • Capped passes can fall behind ingest, and storing anyway grew the store without limit. Refusing is the answer an OTLP exporter already handles: it resends after the delay, and drops the batch after its retries.
    • The final check and the write run in one synchronous step, so no other export is stored between them. Worst case, the store exceeds its bound by the rows one export writes. Product spans take about 5 times their export JSON when stored (about 4.7 KB a span against about 0.9 KB), so that is about 5 MB for the product's 1,000-span exports. An export at the 16 MiB size limit could add up to about 80 MB.
    • The WAL file is not counted in either figure.
    • The span-count bound is still held only by passes.
    • The option is off for the native daemon, which stores every export and holds its bound with its retention loop, as before.
  • The size bound wins over keeping running traces whole. When the store is over its bound and every trace still has a running span, a pass evicts the oldest traces anyway. Before, nothing was evictable, every export was refused, and the spans that would end those traces could never arrive.
  • The pass's index deletes no longer swallow errors. They are skipped only when the index does not exist. Any other failure fails the pass, and its transaction rolls back.
    • The span-count bound is still held by passes only, as before.
  • A pass's deletes commit in one transaction. On the native store, a failure between deleting a batch's spans and deleting their operation-index rows no longer leaves index rows for spans that are gone. workerd already committed them together.
  • The operation-index delete runs once per pass, as one statement for every trace the pass evicted.
  • A resent span is skipped when its stored row already holds exactly the exported values. A re-export that changes anything still replaces the row.

What is and is not bounded. The budget is checked between batches, so a pass's batches take at most the budget plus one batch. Several parts are not bounded by time:

  • A batch always takes its first trace whole, so a trace larger than the cap is one batch, however large.
  • After its batches, a pass runs one delete from the operation index. That index names its trace in an UNINDEXED column, so the delete reads the whole index: about half a second at 1 GiB on the hosts I measured.
  • A batch that deletes logs also runs the two log orphan sweeps, which read their whole tables. It has to: a deleted log's index rows are most of its size, and without the sweep the pass sees no room freed and deletes every log.

So a pass has no hard worst case under a 5-second exporter timeout. In practice the product's traces are far below the cap, and a full store under load holds almost no logs.

What the change looks like:

const overBound = () => opts.refuseOverBound === true && db.usedBytes() > maxDbSizeBytes
const makeRoom = Effect.suspend(() => (overBound() ? cleanupExpired() : Effect.void))
// in ingestTraces and ingestLogs:
yield* makeRoom
const stored = yield* Effect.sync(() => {
	if (overBound()) return null
	// ...the export's transaction
})
if (stored === null) return yield* Effect.fail(new StoreOverBound())
const stored = storedSpan.get(traceId, spanId)
if (stored !== null && sameStoredSpan(stored, row)) {
	insertedSpans += 1
	continue
}

Files worth reading: src/services/TelemetryStore.ts (cleanupExpired, makeRoom, ingestTraces) and src/workerd.ts (write, ingestPath).

How it was tested

New tests, each red before its fix:

Test Red on Green on
stores an identical resent export without rewriting its rows main (rows deleted and reinserted) this branch
holds its size bound under ingest faster than its capped eviction passes: 1 ms budget, 200-span batches, 100 sequential 400-span exports, asserts stored bytes this branch's first commit: 64,548,864 bytes against at most 5,242,880 this branch
rolls back a retention pass that fails part-way: injects a failure after a batch's deletes on the native store this branch's first commit: spans deleted, two search rows left this branch
The bounds test above, with exports alternating /v1/traces, /v1/Traces, /v1/%74races and //v1/traces/ 770fe2c: 75,796,480 bytes against at most 5,242,880 this branch
over its bound with only running traces evicts them rather than refuse every export 770fe2c: no export accepted this branch
fails and rolls back a retention pass whose search-index delete fails 770fe2c: spans deleted, index rows kept this branch
  • daemon.test.ts configured size retention evicts oldest logs first failed on the first fix commit, in CI. It passes now.
  • bun run test: 225 pass, 0 fail, on b8993a4. The benchmark below ran on 770fe2c; the changes since touch only over-bound exports, eviction of running traces and index-delete failures, none of which its runs reach.

Replay benchmark: Motel only, with beta.40's workerd and bindings, on copies of one full 1 GiB store of real product 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. Runs alternate between main and this branch on a shared WSL2 host whose load changed from run to run, so compare neighbours, not rows far apart. The replay sends no logs, and the store holds none.

Run, in order (4 min each) Host load Spans stored Exports lost Attempts timed out Stored MiB, peak / end
500 spans/s, main busy (load about 44) 17,590 23 of 49 95 1,013 / 985
500 spans/s, this branch falling 124,363 0 of 180 7 1,017 / 977
500 spans/s, main quiet (load about 7) 124,115 0 of 178 3 1,024 / 989
500 spans/s, this branch quiet 124,658 0 of 182 1 1,020 / 974
1,000 spans/s, main quiet 40,059 39 of 91 148 1,021 / 1,021
1,000 spans/s, this branch quiet 99,123 3 of 112 46 1,022 / 983
1,000 spans/s, first commit only (15d8fbd) quiet 162,560 2 of 176 84 1,023 / 995

Peak stored MiB is read from the store's header every 10 s, so it can lag the WAL; end is exact. Every run stayed within the 1 GiB bound, and this branch refused nothing as overBound: at shipped defaults, with 1,000-span exports, eviction kept up. The new bounds test shows the case where it does not. The first pair's host load changed during the runs, so read it as indicative only. On a quiet host at 500 spans/s both versions keep up. At 1,000 spans/s main loses 39 exports, this branch 3. A lost export also stops the exporter for 60 s, so "spans stored" also reflects those pauses. The first-commit-only row stores more because it never refuses; the bounds test shows what that costs in a store with a 1 ms budget.

Not done:

  • An indexed delete for the operation index: key its rowid to spans.rowid, with a one-off rebuild on existing stores.
  • idx_span_attributes_trace_span duplicates the primary key's prefix; dropping it would save a write per attribute row.
  • Resends whose JSON keys arrive in a different order are not recognised as identical and are rewritten.
  • Comparing a changed span against its stored JSON costs time in proportion to the payload.
  • At the bound, every size-driven pass deletes the 5,000 oldest logs whatever their age.
  • Separate, not caused here: an idle collector's process memory grows by about 10–25 MB an hour (measured on Executor beta.37/39 local and beta.40 self-host).

Stored bytes over time and spans stored per matched run, main against this branch

A full store of large traces evicted the 100 oldest in one uninterrupted batch, which took seconds and held every export behind it. Exports timed out, the exporter sent them again, and storing each resend rewrote every row and index entry of its spans, so the collector slowed further. Each batch now stops at MOTEL_OTEL_RETENTION_SPAN_BATCH spans (1000), so the pass budget bounds a pass; the deletes that read a whole table (the operation index and the log orphan sweeps) run once per pass rather than once per batch; and a resent span identical to the stored one is not written again.
…tion pass at once

Capped eviction passes could fall behind ingest, and every export was still stored, so the store grew past its size bound without limit. An export that finds the store over its bound now runs one eviction pass and, if the store is still over, is refused with 429 and Retry-After, counted as overBound. Stored bytes stay within the bound plus the exports already admitted. A pass's deletes now commit in one transaction, so a failure between deleting spans and deleting their operation-index rows no longer leaves index rows for spans that are gone, and the operation-index delete runs once per pass for every evicted trace.
A deleted log's attributes and body index rows are most of its size and only the orphan sweeps remove them. Sweeping once after the batches left each batch measuring no room freed, so a size-bound pass deleted every log, the newest included (daemon test: configured size retention evicts oldest logs first). A batch that deletes logs now sweeps before it measures the store; a pass that deleted none still sweeps once.
@RhysSullivan RhysSullivan changed the title Bound eviction batches by spans and store identical resent exports once Bound eviction batches, refuse exports over the bound, store identical resends once Nov 11, 2026
…ge on running traces

The over-bound check sat on the collector's exact /v1/traces and /v1/logs paths, and the typed routes also store from /v1/traces/, //v1/traces, /v1/Traces and /v1/%74races, so those spellings bypassed it. The check now runs in the store's ingestTraces and ingestLogs, in the same synchronous step as the write, behind a refuseOverBound option the workerd collector sets; the native daemon keeps storing every export and holding its bound with its retention loop. The collector also sends every spelling of an ingest path down its bounded route. A store over its bound whose traces all still have running spans now evicts them, oldest first, rather than refuse every export forever. The pass's deletes from the operation and log body indexes no longer swallow errors: a failure fails the pass, and its transaction rolls back.
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