Skip to content

applyFlushedStatuses deep-clones every marked tool part on every pass, freezing large sessions for up to 73 s per message #703

Closed

Description

@maxbrunet

What happened

Posting a message into a large edit-heavy session freezes the instance for seconds, up to 73 s in the worst logged pass. The freeze tracks one stage. applyFlushedStatuses is slow on every transform of two such sessions: 1.3–58.7 s across 941 logged passes on one, and 2.7–73.0 s across 287 passes on another. A third, small session in the same install runs the same stage in 0.2–4 ms across 203 passes:

transform stage: stage=applyFlushedStatuses elapsed=2713.7ms
transform stage: stage=applyFlushedStatuses elapsed=4490.0ms
transform stage: stage=applyFlushedStatuses elapsed=31270.4ms
transform stage: stage=applyFlushedStatuses elapsed=73015.2ms
transform stage: stage=batchFinalize:flushed elapsed=3579.0ms
transform stage: stage=applyFlushedStatuses elapsed=3.6ms      (small session, same install)

A host-stall profiler report captures the stack inside the stage: structuredClone ← clonePart ← clampCloneInPlace ← applyEditMarker ← applyFlushedStatuses. The chain accounts for 543 of 1,549 samples in an 18.0 s stall window and 313 of 4,057 samples in a 47.4 s window (10 ms sampling interval), matching the stage elapsed logged for the same passes (6,305.1 ms and 3,793.3 ms).

Why

  • For each dropped tag in edit_marker mode, applyFlushedStatuses calls applyEditMarker, which loops over every occurrence and calls clampCloneInPlace (clonePart, clampCloneInPlace, applyEditMarker). That deep-clones the part with structuredClone before the marker mutates anything.
  • The marker then writes only top-level fields: state.output (assignment), optionally state.attachments (assignment), and top-level string diffs in state.input (editMarkerToolPart, applyEditMarkerToInput); for the other part formats the same function handles, it rewrites args (tool-invocation) or input (tool_use) in place. Nothing under state.metadata is ever touched, but the deep clone copies it anyway. In these sessions that metadata is large: one measured part carried 5.4 MB (~121k scalar fields).
  • There is no early exit. An occurrence that was already marked on an earlier pass is cloned again on every pass, because the clone happens in clampCloneInPlace while the marker's idempotency checks run after it. The pristine part is never mutated, so every transform pays the full cost again.
  • Scale: the two sessions carry 207 and 183 dropped tags in edit_marker mode, plus 24 across the skeleton modes, and roughly 200 occurrence clones per pass over parts of up to several MB each.
  • Micro-measurement (same machine, Node 24, synthetic replica of the measured part shape, ~0.9M scalar fields): structuredClone(part) 183–198 ms; clonePart's JSON fallback 101–153 ms; a shallow copy-on-write of just the fields the marker mutates ~0 ms.
  • Memory evidence: across the 47.4 s stall window, RSS went 8.4 GB → 3.4 GB and heap size 12.7 GB → 16.9 GB. Repeated multi-megabyte clone churn feeds GC.

Affected harnesses

  • OpenCode 1 (TUI, desktop, and web share one server plugin): measured, as described above.
  • OpenCode 2: same shared transform pipeline (createTransform → runPostTransformPhase → applyFlushedStatuses); identical code path.
  • Pi / Oh My Pi: call the shared applyFlushedStatuses and replay dropped edit_marker tags through it (their own code comments say so). Same clone cost applies; not measured on Pi.
  • Rust transform mode (OpenCode 1): unaffected. It returns before the TypeScript post-pass ("Rust returns before the TypeScript post-pass hook below").

Fix ideas

  • Make the clone copy-on-write: shallow-copy the part, its state, and the input subtrees the marker rewrites (state.input, plus args for tool-invocation and input for tool_use parts) instead of deep-cloning the whole subtree.
  • Skip the clone for occurrences already in marked form (early exit before cloning).
  • Or reuse the served copy across passes; clampCloneInPlace already tracks occurrence.served.

Related observation (different root cause, same windows)

The same two reports show a second, larger cost: refreshTailHygieneBaseline (tail-hygiene-walk.ts L1190) via measureWithReplay → excludedSnapshot → safeStableStringify → stableStringify accounted for 3,343 of 4,057 samples (82.4%) of the 47.4 s window, dominated by the recursive writeStable writer. That is a different root cause and not the subject of this report; it is flagged here only because it dominates the same profiler windows.

Environment

Plugin 0.48.0 installed; the involved functions are byte-identical in v0.49.6 and master. Bun 1.4.2, macOS arm64, OpenCode 1.18.x. Two stall reports (stack frames, timings, and memory counters only) available as a gist: https://gist.github.com/maxbrunet/619f375b9eadf59af9134e11806eb08d. The local profiler store keeps only its 50 newest reports, so the gist is the durable copy.

Activity

  1. magic-alfonso commented on Oct 16, 2026

    @magic-alfonso

    Thanks, this is an excellent report: the profiler stacks, the per-stage timings and the micro-measurement make the cause clear. Agreed on the mechanism: the deep clone runs before the marker's idempotency checks, copies state.metadata the marker never touches, and is paid again on every pass. A fix is in progress (copy-on-write of only the fields the marker rewrites, and no clone for occurrences already in marked form), checked for byte-identical output against the current build on OpenCode 1, OpenCode 2 and Pi. We'll post here when it ships.

  2. changed the title [-]applyFlushedStatuses deep-clones every marked tool part on every pass — multi-second freezes in large sessions[/-] [+]applyFlushedStatuses deep-clones every marked tool part on every pass, freezing large sessions for up to 73 s per message[/+] on Oct 16, 2026
  3. magic-alfonso commented on Oct 17, 2026

    @magic-alfonso

    Fixed in v0.49.8. Reapplying drop placeholders no longer deep-copies each edit output's display-only data. It now copies only the fields it changes and skips outputs that are already marked. On a synthetic session with 200 marked 2.9 MB outputs, a normal turn went from about 3.9 s to under 1 ms, and requests stay byte-identical. Thanks for the profiles.

    The measurement freeze from #704 is fixed separately and ships in the next patch.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Type

    No type

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions