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:
item-content-appendedjournals only the appended chunk, and applying it appends to the item, so persistence is proportional to the change.- The journal is appended in constant time through a cached tail cons instead of walking it per event.
- Schema 7 splits persistence into
<id>.json(small header),<id>.jsonl(append-only events), and<id>.snapshot(materialized state, rewritten only when the log passesmagent-session-log-max-events). - The header is rewritten only when its content actually changed, and
magent-session-summary-titleno 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.