#3968 serve: workflow.history.get rescans every behavior definition (incl. auto-definitions) per request to authorize step outputs; latency grows with catalog size, multiplies under overlap, and cancel does not stop it

Summary

On an authenticated serve, workflow.history.get re-reads and YAML-parses every behavior definition, including every auto-created one, on every request. The first output-ownership check triggers this scan (dataReadPolicy → CanonicalResources.dataOwners → #definitionsById → YamlDefinitionRepository.findAllIncludingAutoGlobal()). The index is memoized only for that one request. Nothing shares it across requests, nothing caches it across requests, and cancelling the request does not stop it.

As a result, output-resolution time grows linearly with the size of the definition catalog. It does not depend on the run's resource count. Overlapping requests each run their own scan on the same event loop, so their latency multiplies. @swamp/ci-uat/run makes the catalog grow without bound: every default run auto-creates 73 behaviors (uat-vms-<run>, ur-<run>-<slot>, ut-<run>-<shard>).

This is distinct from #3959, which covers behavior output history rescanning definitions for each missing ID. Related, but not duplicates: #3741 (added the current spans), #3742 (client poll stacking, shipped), and #3779 (the same per-request full-scan pattern inside an authorization filter, but for extension workflows in workflow.search).

Affected revisions

• origin/main at commit 4c4327b42 (primary reproduction)
• commit b4dd513d, ops build 20261025.114930.0-sha.b4dd513d. Reproduced with the same numbers. Between b4dd513d and main, history_get.ts, run.ts, resource_resolution.ts, workflow_handlers.ts and yaml_definition_repository.ts are byte-identical. step_output_resolver.ts only drops an unused vault option.
• The code path predates both. The historical ops data below is from 9a065cc6.

Present-day ops observation (b4dd513d, 2026-10-26 07:58 CDT)

Trace 917dcd9b39a2924ed6498f4ec1a132ce: completed @swamp/ci-uat/run run 95d70d16-…, filesystem datastore, engine v2, user principal, 2 active requests, event-loop lag 2.2 ms.

Ops has no child spans inside output resolution. Its per-phase split is therefore not observed directly. The split below comes from the local reproduction.

Historical ops observations (9a065cc6, Friday 2026-10-23). Kept separate from today's case.

• 579 output-resolution spans: median 32.6 s, max 137.2 s. Output resolution was a median 95% of the request.
• The same completed run (ee54cbd7-…, 76 resources) took 3.24 s with 1 active request (trace cf871398…) and 136 s with 35 active requests (trace 6fa43d9a…). The peak was 45 overlapping output resolutions on one connection.
• 87 of 579 requests replied cancelled although their output-resolution spans completed OK.

Local reproduction

Fixture

The fixture is synthetic, contains no secrets and uses no sleeps. It is a local extension with @repro/uat/workers and @repro/uat/runner plus a workflow @repro/uat/run that copies @swamp/ci-uat/run's jobs, steps, forEach fan-out and per-run model names (uat-vms-${{ run.id }}, ur-${{ run.id }}-${{ self.slot }}, ut-${{ run.id }}-${{ self.shard }}). Each step writes one JSON resource, so:

• the default inputs (23 shards + 13 side shards) give 4 + 36 ready + 36 shards = 76 resources
• 12 shards and no side shards give 4 + 2×12 = 28 resources

These match ops's counters exactly. Shard resources carry a 150-line log tail (about 16 KB each; the 76-resource run has 660 KB of output content).

The datastore is the default filesystem one (v2 engine). Serve ran with --auth-mode token, a non-admin user:repro-reader granted read on workflow:*, data:* and model:*, plus an admin token for comparison. A local OTLP collector captured serve's own spans. A temporary instrumented copy added timers inside output resolution and a span around findAllIncludingAutoGlobal. 101 real workflow runs produced 7,404 definitions; the 22k and 74k levels add clones of those real auto-definition files with fresh IDs and names.

Commands

These run from the reproduction directory: the sw wrapper runs main.ts from the chosen source tree with -A --unstable-bundle, and the tools/*.ts scripts sit beside it.

./sw repo init repo --tool none
# extensions/models/uat.ts, extensions/models/uat_runner.ts, workflows/workflow-uat-run.yaml (attached in the repro dir)
./sw workflow validate '@repro/uat/run' --repo-dir repo
./sw workflow run '@repro/uat/run' --repo-dir repo                       # 76 resources
./sw workflow run '@repro/uat/run' --repo-dir repo \
  --input 'shards=["cli-1","cli-2","cli-3","cli-4","cli-5","cli-6","cli-7","serve-1","serve-2","serve-3","quality","club"]' \
  --input 'sideShards=[]'                                                # 28 resources
./seed-runs.sh repo 100                                                  # +73 auto-definitions per run
./sw access token mint repro-reader --principal user:repro-reader --repo-dir repo
#   grants/repro.yaml: allow read on workflow:*, data:*, model:* for user:repro-reader
deno run -A tools/collector.ts 14318 results/spans.jsonl &               # OTLP/HTTP JSON sink
OTEL_EXPORTER_OTLP_ENDPOINT=http://127.0.0.1:14318 OTEL_BSP_USE=1 \
  ./sw serve --repo-dir repo --host 127.0.0.1 --port 19191 --no-schedule \
  --auth-mode token --admins user:repro-admin &
deno run -A tools/client.ts --url ws://127.0.0.1:19191 --token-file token-reader.txt \
  --run <run-id> --n 45 --concurrency 45 [--cancel-after-ms 100]
python3 -I tools/summarize.py results/spans.jsonl
python3 -I tools/clone_definitions.py repo-scaled 74000                  # scaling control
deno run -A tools/bench_definitions.ts <src> repo-scaled 5 1             # scan alone

The machine was a 32-core Linux host shared with other test suites, with load average 3–12 throughout. The scan's user+system CPU time roughly equals its wall time, so the scan is CPU-bound here (warm page cache).

Results: one request at a time, completed runs, non-admin user

• The scan alone (findAllIncludingAutoGlobal, outside serve): 152 ms at 7,404 definitions, 456 ms at 22,000 and 1,533 ms at 74,000. That is linear, about 20.7 µs per definition on this host.
• Resource count is not the driver. 28 and 76 resources cost the same within noise. Reading 660 KB of content for 76 resources takes under 20 ms.
• The scan comes from read authorization. With --auth-mode none (where filterByResources returns early) the same 76-resource request at 7,404 definitions takes a median of 30 ms (68 ms for the first request) instead of 175 ms.
• Admin vs non-admin: the same (159–178 ms at 7,404). An admin still pays for owner resolution.
• main vs b4dd513d at 7,404: 167/178 ms vs 176/188 ms (28/76 resources). Same within noise.
• No nested-run reads (findChildRun 0 calls). Ops's counter showed 0 denied, which matches.

Results: overlapping requests on one connection (76-resource run, uninstrumented main)

Throughput stays the same while latency multiplies: each request runs its own full scan, and the scans take turns on serve's event loop. In the 45-way batch, output resolution was 4.94–5.14 s per request, active requests rose to 45, and the recorded event-loop lag peaked at 454 ms. Ops's slow historical trace showed 543 ms lag with 33 active. Workflow authorization and redaction stayed small, while run lookup rose to about 610 ms because it waits behind the same event loop.

Results: cancellation

Ten concurrent requests (7,404 definitions) each sent cancel 100 ms after the request. All ten replied cancelled, but only after 1.33–1.38 s. Inside each one, the definition-index load ran to completion (1.08–1.24 s) and the output-resolution span ended OK. handleWorkflowHistoryGet checks controller.signal.aborted only after consumeStream finishes, and output resolution never receives the signal. This reproduces the ops pattern of cancelled roots with completed OK output spans: cancelled requests keep competing for the event loop.

Running vs completed

Nothing in output resolution branches on run status: the same per-request scan happens either way. A running run hurts more only because the run page re-reads it while it is live. A running run was not measured separately.

Causal mechanism (source, main 4c4327b42)

1. handleWorkflowHistoryGet (src/serve/handlers/workflow_handlers.ts) always passes includeOutputs: true, and passes dataReadPolicy(socket, ctx, principal). That builds a fresh canonicalResources(ctx) per request.
2. StepOutputResolver.resolveResources (src/domain/workflows/step_output_resolver.ts) calls canRead(ref) before each read. The first call goes through filterByResources → canonical.dataOwners(ref) → modelOwners → #definitionsById (src/serve/handlers/resource_resolution.ts). Because the repository has findAllIncludingAutoGlobal, this builds an id → definitions index by reading every file under models/ and the datastore's auto-definitions/. It awaits each Deno.readTextFile, then runs parseYaml and Definition.fromData (collectAllDefinitions in src/infrastructure/persistence/yaml_definition_repository.ts).
3. The index lives on the per-request CanonicalResources. The next request, including one sent concurrently for the same run, builds it again.
4. @swamp/ci-uat/run names its behaviors after the run ID, so each run leaves 73 new auto-definitions (default inputs), and the scan keeps growing.

What matches ops, and what remains uncertain

Matches:

• filesystem datastore with the v2 engine
• an authenticated user principal, with 0 denied
• a completed @swamp/ci-uat/run-shaped run with exactly 28 and 76 output resources
• output resolution as 90–97% of the request
• no nested-run reads
• identical code at b4dd513d
• overlap amplification with high active_requests and event-loop lag
• cancelled replies whose output spans completed OK

Not established:

• The ops definition count is unknown. At this host's 20.7 µs per definition, 6.27 s would take about 300k definitions. Ops's other spans run slower than this host: run lookup 74 ms vs 5–17 ms locally. On ops's VM disk, the serial per-file reads may also cost more than here. So ops plausibly needs far fewer, but how many is unmeasured. The isolated same-workflow latency also rose from 3.24 s (Friday) to 6.27 s (Monday). That is consistent with a growing catalog but does not prove it: the revisions and other load differ.
• Ops's own phase split is not observed. Ops may also pay other costs that this fixture lacks, such as extension-workflow walks (#3779). Those would explain ops's 467 ms authorization and 129 ms redaction, versus about 1 ms and 0.1 ms here.
• To confirm on ops (read-only): count *.yaml files under the datastore's auto-definitions/ and under models/, and time one findAllIncludingAutoGlobal. Or deploy a span around the index load, with the definition count as an attribute.

Suggested fix direction

1. Stop scanning the whole catalog per request to find owners. Look up definitions by ID without a full scan, or keep one serve-level id → owners index. Invalidate it when definitions are written, deleted, or pulled from the datastore, and share it single-flight between concurrent requests. Ownership must still be decided on current definitions: keep #2675's guarantee that owners are judged now, by ID.
2. Observe cancellation in output resolution. Pass the request's AbortSignal into resolveStepOutputs and the resolver loop. Check it before the index load and between resources, and reply as soon as the request is cancelled.
3. Consider coalescing identical in-flight history.get requests per connection and principal, or caching the resolved outputs of a terminal run per authorization snapshot.
4. Telemetry: add a span for the definition-index load with a definition-count attribute, and attributes for content reads, bytes and child-run reads under swamp.workflow.step_outputs.resolve.
5. Separately, outside this fix: per-run auto-created behavior names in ci-uat grow the catalog without bound. That is worth a lifecycle or retention decision, but serve should not be quadratic in it.

Regression criteria

On the fixture above, with a non-admin token:

• history.get for the 76-resource completed run at 74,000 definitions stays within 2× of its latency at 98 definitions. Today it is about 1.7 s vs about 30 ms.
• 45 concurrent history.get requests for the same run at 7,404 definitions: median per-request latency stays under 3× the serial latency. Today it is 5.8 s vs 0.175 s. At most one definition scan runs for the whole batch, or none if the index is kept warm.
• A cancel sent 100 ms after the request gets its cancelled reply within 100 ms of the cancel, and no definition scan starts after the cancel.
• A unit or integration test counts findAllIncludingAutoGlobal (or the replacement lookup) calls across N history.get requests and asserts that the count does not grow with N.
• Grants that deny on definition tags or name are still honoured for outputs: a denied resource stays out of the outputs, and denied counts still reach the span.

Reproduction artifacts (local): fixture repos, harness scripts, collector JSONL, per-trace span summaries and the instrumentation patch are kept in the reporter's worktree under .repro/run-detail-outputs/.