Loop performance diagnosis (2026-09-22)

Verified persistence bottleneck

The deferred session save used an idle timer. During provider streaming, Emacs can already be idle longer than the configured 250 ms, so each new chunk could trigger another full JSON rewrite. The elapsed-time timer fix in magent-session.el coalesces updates without postponing the first save.

In an isolated Emacs 31.0.91 daemon, 40 synthetic chunks at 20 ms intervals gave these three-run medians with actual JSON encoding and disk writes:

Session JSON Previous saves Current saves Previous save time Current save time
About 24 KB 39 5 214 ms 21 ms
About 2 MB 12 4 885 ms 390 ms

The synthetic completion time changed little. A single 2 MB save still blocked Emacs for up to about 111 ms in both versions.

Stage evidence and limits

Magent already emits llm-request-start, llm-request-end, tool-call-start, and tool-call-end lifecycle events. A temporary sink and save wrapper measured one deterministic live smoke tool turn: about 83 ms from the first request start to its first provider event, 134 ms in emacs_eval, under 1 ms from tool completion to the continuation request, and about 1 ms for its terminal session save. This test stubs provider transport. A separate ACP smoke test issued three session updates; their combined local dispatch time was 2.2 ms. These small fixtures do not measure long agent-shell transcripts or a real model.

One recent persisted completed turn took 242 seconds with 22 tool items. The tool-item intervals total 36 seconds; reasoning-item intervals total 108 seconds. Ledger item intervals can overlap or contain provider waits, so their totals cannot be used to assign all remaining time to one cause.

Two isolated real-provider diagnostic turns failed before a provider event: that daemon could not decrypt its configured authinfo file because the required secret key was unavailable there. These failures are not performance samples. Keep real provider debugging in an isolated Emacs server as described in TROUBLESHOOTING.org.

Next measurement

Once an isolated server can use the configured provider, capture monotonic times for request start, first normalized event, tool completion, next request start, turn completion, session save, and ACP update. Record only event types, durations, counts, and sizes. Compare ordinary, tool-use, and long-history turns before changing provider continuation or session serialization. The previous save fix is supported by a real-timer live smoke test and the unit suite.

Root cause and fix: session persistence rewrote the whole conversation

Continued measurement showed the remaining cost was not the coalescing interval but the write itself. Every flush re-encoded the entire session, so a save cost the whole conversation while the change was one streaming chunk.

Attribution of one 43.6 ms save of a 1.4 MB session (Emacs 31.0.91, batch):

Stage Time Share
json-encode of the whole payload 33.0ms 76%
write-region to the temporary file 7.5ms 17%
ledger traversal 1.1ms 3%

A real-timer streaming replay (850 chunks over 6.5s, about 131 chunks/s) spent 1684 ms inside session saves, or 25.9% of wall time. The ledger already had append-event, apply-event, and replay, but streaming content bypassed the journal entirely: magent-thread-append-item-content updated only the materialized snapshot, so the journal could not represent the change and the whole state had to be rewritten.

The fix makes the log able to represent what actually happens:

  1. item-content-appended journals only the appended chunk, and applying it appends to the item, so persistence is proportional to the change.
  2. The journal is appended in constant time through a cached tail cons instead of walking it per event.
  3. Schema 7 splits persistence into <id>.json (small header), <id>.jsonl (append-only events), and <id>.snapshot (materialized state, rewritten only when the log passes magent-session-log-max-events).
  4. The header is rewritten only when its content actually changed, and magent-session-summary-title no longer materializes every item.

Same workload after the change, on a 1.4 MB session:

Metric Before After
Wall time inside saves 25.9% 1.6-2.3%
Mean save 93.5ms 4.3-6.1ms

Cost is now independent of conversation size, which is the property that matters. The same workload against ledgers of 1.6 MB, 2.8 MB, and 8.8 MB gave 6.5-10.4 ms (first run of the process, cold), 6.6 ms, and 6.6-8.1 ms per save, where the previous design grew from 44 ms at 1.4 MB to 116 ms at 5.8 MB.

The remaining per-save cost is the append itself. Note that write-region-inhibit-fsync is t in batch and nil interactively, so an interactive Emacs also fsyncs each append; that was left at the Emacs default to preserve the previous durability level.

Migration was verified against the real corpus: 977 session files copied to a temporary tree, migrated, and compared with a representation-insensitive comparison of every turn, item, input, output, and metadata value. 973 files were value-identical, 4 were not session files, and 0 values changed. 52 files differed only in that shadowed duplicate metadata keys, which readers already ignored through assq, are no longer written.