Skip to content

Token and latency costs along the Hook → capture → flush → recall chain: measurements and proposed changes #2040

New issue
New issue
Open
Open
Token and latency costs along the Hook → capture → flush → recall chain: measurements and proposed changes#2040

Description

@Fengzdadi
Fengzdadi
opened on Oct 17, 2026

Summary

While preparing the cross-host OFF/ON runs for #1705, I measured where an ON session spends tokens and wall time, stage by stage, on master 06794f66. Five groups ran on the e2e/bub paired harness with the project-decision-continuation workload (a fact stated in session 1, asked back in session 2), qwen/qwen3.7-flash through OpenRouter as the agent model on every host, and a local enforced Server with openai/text-embedding-3-small (OpenRouter) for embeddings. ON passed every trial, so this is about cost, not correctness.

group host Server generation model trials purpose
G1 Pi 0.82.1, OpenCode 1.18.33, Bub 0.5.1 deepseek/deepseek-v4-pro 2, 2, 1 baseline
G2 Pi qwen/qwen3.7-flash 2 does a faster generation model shorten the flush wait
G3 Pi deepseek/deepseek-v4-pro, local patch of the prepare embedding timeout to 2 s 2 effect of reliable Hook injection

Per arm-run, mean over trials. Agent time is Harbor's agent execution time; "flush wait" is the time the harness waited for flush_memory between the two sessions.

group arm pass wall agent time flush wait input tokens cached output tokens
G1 Pi OFF 0/2 48 s 19.2 s 0 15,466 10,880 867
G1 Pi ON 2/2 69 s 19.4 s 18.3 s 121,833 107,520 464
G1 OpenCode OFF 0/2 60 s 22.1 s 0 65,805 59,648 423
G1 OpenCode ON 2/2 130 s 20.2 s 43.7 s 77,560 68,864 253
G1 Bub OFF 0/1 92 s 45.7 s 0 49,020 n/a 2,115
G1 Bub ON 1/1 184 s 132.0 s in-turn 23,472 n/a 1,156
G2 Pi OFF 0/2 47 s 21.3 s 0 15,264 10,944 889
G2 Pi ON 2/2 116 s 16.9 s 72.8 s 103,088 88,960 411
G3 Pi OFF 0/2 116 s 20.9 s 0 15,146 13,056 816
G3 Pi ON 2/2 62 s 19.4 s 14.3 s 103,188 74,240 452

The G3 OFF wall time includes one trial whose npm install took 146 s; the other took 45 s.

Two things stand out before any stage detail: the agent's own time is the same in both arms (Bub excepted), so the ON wall-time gap is almost entirely waiting for Memory extraction; and the token gap is set by the host integration's per-call overhead, not by the task.

Findings by stage

1. Hook recall: prepare_context

Covered in #2039. The 0.25 s query-embedding budget silently drops the semantic path with a remote embedding provider; injection then succeeds by chance (3/10, 7/10 on replays; 0/10 behind a 300 ms delay; 10/10 at 2 s). Each failed injection costs one extra model call because the model calls pc_search instead: recall input tokens 56.4k with the fallback against 37.7k with injection on Pi (about 18.7k more), 42.6k against 28.3k on OpenCode (about 14.3k more).

2. Where and how the context is injected

  • Design: recalled content is wrapped as untrusted historical evidence with citations. The Pi package appends it to the system prompt in before_agent_start; the Bub plugin prepends a system message before each model call.
  • Measured: when injection succeeds on Pi, the first recall call reports cacheRead 0 instead of 16,000, so that call pays the full 18.5k prefix; token use fell by one call but the step cost rose. The injected block is 180–189 tokens for a 94-token fact; the Server's own recall statistics report token_reduction −86 to −95 for it.
  • Proposed, to be verified: inject after the stable prefix where the host allows it (Pi's BeforeAgentStartEventResult accepts a message), keep the trust statement, and compact the envelope (short keys, no null fields, no revision when it is 1). The cache miss is measured; that a message-based injection keeps the cached prefix is an assumption about the provider's prefix caching that I have not tested. Verify with the first call's cache read and the Server's token_reduction.

3. The tool catalog carried by every model call

  • Design: host guidance is generated from the operation catalog (feat(integrations): generate and safely refresh host guidance #1877); integrations/capabilities.toml defines minimal, recommended and full profiles, Pi declares all three, OpenCode and Kimi Code only minimal. The Pi package registers 35 named pc_* tools regardless of profile, plus a /pc command and the powercontext-project-context Skill that routes the rarely used workflows.
  • Measured per model call: Pi ON 18,560 tokens vs OFF 1,536 (35 pc_* tool schemas plus the 6 KB guidance); OpenCode ON 13,696 vs 7,296; ZCode through the Server MCP (about 49 operations) 40k vs 18k, measured in a separate ZCode feasibility run on the same day with a different workload and model. The whole task used one tool, pc_search. The overhead is mostly cache reads after the first call, which is why cost grows about 3x while tokens grow 7x, but any cache miss, including the one injection causes, bills it in full.
  • Proposed: let the registered toolset follow the declared profile with recommended as the default and a setting that registers the full set; trim the guidance to the active profile, since the Skill already carries the handoff, review and external-Skill workflows. Verify with the per-call prefix and the OFF/ON input ratio.

4. Capturing Sources

  • Design: Hooks capture the user prompt as a Source; the Bub plugin's capture_events additionally captures the user prompt, each model result and each tool result as Sources.
  • Measured: Bub captured 15 Sources over two sessions and the Server spent 7 generation requests and 18.9k extraction input tokens on them; Pi captured 2 Sources per run, for 3 requests and 4.0k input tokens.
  • Proposed: with capture_events on, capture user prompts and final assistant messages by default and make tool results a separate switch, or fold one turn's events into one Source. Verify with Sources and generation requests per session.

5. Extraction and reconciliation on flush_memory

  • Design: extraction proposes candidates (kind, text, evidence_ids); the Atomic Memory reconciler compares them with related entries and decides create, revise, merge or noop; each structured operation may use up to GENERATION_MAX_REQUESTS provider requests.
  • Measured: one one-sentence Source costs 2 generation requests (extraction plus reconciliation, both under memory_extraction), 700–1,300 output tokens and 10–20 s on deepseek-v4-pro; one flush made 4 requests, 4,386 output tokens and 66 s. That flush produced two Memory entries; I did not determine whether its four requests were one extraction plus two reconciliations or included a retry. Switching the Server to qwen/qwen3.7-flash (G2) made it slower, 3,146–8,181 output tokens and 39–106 s per flush. The output schema itself is a few dozen tokens; the volume is model reasoning, and the wait tracks the output token count: roughly 40–80 output tokens per second of waiting across all runs, with no model clearly faster than another.
  • Proposed, to be verified: default or document generation settings that disable reasoning and cap output for extraction and reconciliation (GENERATION_MODEL_SETTINGS already carries provider settings), and state per provider what to set. That the extra output is reasoning is inferred from the size of the output schema, not read from the raw generations, and I have not measured extraction quality with reasoning off. Verify with generation output tokens and seconds per flush, with Memory content unchanged.
  • Question rather than proposal: when the related set is empty and the window has a single candidate, the reconciliation call only decides create versus noop. A lighter path would halve the requests for first-contact Scopes, but the reconciler also acts as the quality gate, so this needs a maintainer view.

6. Who waits for the flush

  • Design: flush_memory is synchronous by contract; the Pi package starts its flush at agent_end with a 1 s closing budget; the Kimi Code integration states "Server owns memory generation; the Hook does not flush"; POWERCONTEXT_SERVER_RUNTIME_MEMORY_SCHEDULE_SECONDS turns on automatic Memory admission on an interval; it is unset by default, and the Server reported automatic_processing_enabled: false in these runs.
  • Measured: the Bub plugin awaits a checkpoint flush every 5 captured events and again in save_state, inside the turn. These runs raised the plugin's client timeout to 150 s, as the harness README recommends, so every wait ran to completion; at the plugin's default of 10 s each checkpoint wait is capped at 10 s, the checkpoint is recorded as failed, and the Server finishes the extraction on its own. In the ON run its loop stalled 31.7 s and 14.6 s in the capture turn and 41.0 s and 28.2 s in the recall turn; the Server served 5 flushes for 101.5 s; the ON arm-run took 184 s against 92 s for OFF, with agent time 132 s against 46 s.
  • Proposed: give the Bub plugin the Pi pattern (bounded closing wait) or skip Hook flushes when the Server schedule is on; document MEMORY_SCHEDULE_SECONDS as the recommended deployment so Hooks only capture; keep the synchronous flush for an explicit "remember now". I have not run with the schedule enabled, so whether it makes the Hook flush unnecessary end to end is untested here. Verify with the gaps between Bub loop steps.

7. pc_search as the recall path of last resort

/v1/memory/search took 0.3–1.0 s and succeeded every time. It is fine as an explicit search; the problem is that today it is the de-facto recall path because of stage 1. Once stage 1 is fixed it should appear only when the user asks to search.

Out of scope here

Harness-side costs (container setup, npm install per trial, compose down) and the harness report's view of the recall path are tracked on the e2e/bub side.

Method notes

The harness is e2e/bub from the #2035 branch, master 06794f66 plus that PR's two commits. Numbers come from Harbor's per-step results, the hosts' own usage logs (per model call), the Server's access log (duration_ms per request) and POST /v1/stats per Scope (usage by purpose). The replay and delay-proxy scripts are small shell and Python files; I can attach them or turn the stable parts into a harness check on request.

Activity

  1. github-project-automation
    added this to PowerContexton Oct 17, 2026
  2. github-project-automation
    moved this to Todo in PowerContexton Oct 17, 2026

  3. Fengzdadi commented on Oct 23, 2026

    @Fengzdadi
    Fengzdadi
    on Oct 23, 2026
    ContributorAuthor

    Following up on the stage 5 question about reconciliation with an empty related set. I measured it and would like to turn it into a concrete proposal.

    What the call can do. When related is empty, the reconciler can only create (optionally rewording) or noop the candidate; revise and merge have no target. Only the first candidate of a window can see an empty set: later candidates receive the earlier ones as related, so in-window deduplication still happens. The extraction prompt already applies the same worthiness, language, time and evidence rules to the same evidence, so this call is a second sample of the extraction decision.

    Setup. Upstream master 464cd15, deepseek/deepseek-v4-pro through OpenRouter, the production prompts and pipeline assembly, full-text retrieval only. Synthetic Sources: 8 single statements, 8 noise messages, 4 multi-fact statements and one 10-step evolving Scope, 2 trials. An earlier run on c0c38de (full-text and hybrid, 112 empty-related calls) is included where noted.

    Cost. Empty-related reconciliation was 33 of 117 generation requests, 240 of 792 seconds and 18.2k of 61.6k output tokens.

    Replay. Each of the 33 recorded requests was sent 5 more times (198 samples including the original):

    Outcome Samples
    Identical create 179
    Absorbed a sibling candidate that extraction split from the same sentence 16, in 4 requests (2 to 6 of 6 samples each)
    Wording only 2
    noop of one half of a split preference; the other half stayed as its own candidate 1

    27 of the 33 requests returned an identical create in every sample. There were no language corrections, no dropped noise and no lost facts; the noise Sources produced no candidates at extraction. The earlier run had 104 identical results out of 112, one language correction (a Chinese candidate from an English Source), one dropped noise message, one candidate that lost context ("squash-merge only for pull requests" became "Squash-merge only"), four sibling absorptions and one punctuation change. In that run four other noise candidates, including "thanks, looks good!", were created.

    End state. I reran the same scenarios with the recorded extractions and empty-related reconciliation replaced by an identical create. 34 of 42 Scopes ended with the same memories. Of the 8 differences, 3 are granularity (one combined memory against two split ones with the same facts), 3 come from failures in the baseline run (provider unavailable, a 180 s timeout, and an invalid revise in a later reconciliation, see #2183), and 2 are variance in later reconciliations.

    Proposal. Skip reconciliation when a candidate has no related items and the Scope uses the built-in atomic_memory.reconcile prompt; keep the call when the Scope has a custom one, since an administrator may encode create/noop policy there. Expected effect: one fewer generation request for each window whose first candidate has no related items, which halves the requests of a single-candidate flush. Visible change: facts that extraction splits stay split unless a later comparison merges them, which matches the "keep facts that can change independently separate" rule in both prompts. With the skip applied locally, tests/builtin and tests/e2e fail only in two usage tests that count two requests for a single-candidate flush.

    Limits: one model, synthetic Sources, full-text retrieval only. A weaker extraction model may lean more on the second pass; the single language correction is that case.

    This removes a request rather than shrinking input, so it should be independent of #1991 (@hidb4ai, #1989). @frf12, unless you see a role for this call that I missed, I will open a PR.

  4. Fengzdadi commented on Oct 24, 2026

    @Fengzdadi
    Fengzdadi
    on Oct 24, 2026
    ContributorAuthor

    Following up on stage 3, the tool catalog. I prototyped the mechanical slimming of the Pi tool schemas and ran it through the live-model guidance evaluation. Short version: it removes a quarter of the catalog tokens, keeps validation identical, and makes the model break the empty-search rule about three times as often when the Skill body is not loaded. I am not opening a PR for it; the data is below so nobody has to repeat the runs.

    Where the tokens are. The Pi plugin registers 35 tools. Serialized as name, description and parameters (o200k_base), the catalog is 15,152 tokens: parameter schemas 12,986 (86%), descriptions 1,623 (11%), plus 1,069 for the guidance block. The heaviest tools are the handoff carriers (pc_handoff_acknowledge 2,554, pc_task_outcome 1,646, pc_handoff_finalize 1,476, pc_handoff_current 1,345), and all of them are in the recommended profile, so defaulting Pi to recommended would save about a quarter; only minimal removes most of it. Trimming descriptions cannot matter at 11%.

    The change. The schemas carry constraints the model never needs: 129 minLength: 1, 64 non-blank patterns, 55 printable-ASCII identifier patterns, 85 maxLength of 128 or 256 on identifiers the model copies from Server results, and TypeBox renders every union of literals as anyOf of const branches. The prototype keeps the complete schema for validation and gives the model a projection: anyOf-of-const becomes enum; minLength: 1, the non-blank and charset patterns, and maxLength <= 256 are dropped. prepareArguments runs pi-ai's validateToolArguments with the complete schema before execution, so a rejected call is rejected exactly as before. Catalog: 15,152 to 11,371 tokens (-25.0%); enum alone -5.2%, dropped constraints alone -19.8%. The same projection on the Server MCP catalog (56 tools, 34,944 tokens) would give -21.7%; I did not touch it, it is a public contract.

    Evaluation. scripts/evaluate_integration_guidance.py over the exported Pi catalog, qwen/qwen3.7-flash through OpenRouter, max_tokens 6000, Skill resource reads disabled, each case in en/zh with the Skill body loaded and unloaded, 2026-10-22/23. The full 12-case set twice per arm, routing plus arguments: baseline 44/48 and 46/48, candidate 45/48 and 45/48. Every recorded candidate call rescored against the complete schemas: 0 of 444 violate it. The failures outside empty_search are the same in both arms and unrelated to schemas: handoff carriers with an invented source_id or a missing evidence, and one truncated reply.

    Empty search is where it moves. The case asks "Search my saved memories for Aurora's deployment color" and the controlled reply has no hits. The guidance allows one focused reformulation and says an empty search does not authorize an inventory; a pass is a final reply after at most one reformulation. Three batches of 60 observations per arm (the first with a stopping rule set at 60 before it ran; the other two fresh, interleaved):

    Batch Pass, baseline Pass, candidate Escalated to pc_memory_list, baseline Escalated, candidate
    1 43/60 33/60 4 16
    2 (ablation) 45/60 37/60 4 13
    3 (control) 45/60 27/60 5 14
    Pooled 133/180 97/180 (p = 1e-4) 13/180 43/180 (p = 2e-5)

    Two-sided Fisher. The pass rate was the pre-set metric; the escalation count was chosen after batch 1 and then held on batches 2 and 3. Reformulation use rose with it (74 to 113 of 180). The model did not go silent: after its one reformulation it issued a third pc_search or, more often than before, an inventory call.

    The batch 2 ablation separates the two halves of the change: enum only escalated 15/60 (p = 0.011 against the batch's baseline 4/60), dropped constraints only 13/60 (p = 0.034), both 13/60. Dropped constraints change neither pc_search (its only change is mode becoming an enum) nor pc_memory_list, so the effect comes from the catalog as a whole, not from the definition of the two tools involved.

    The split by Skill mode is the sharpest result. With the Skill body loaded: pass 67/90 vs 64/90, escalation 4 vs 10 (p = 0.16). Unloaded: pass 66/90 vs 33/90, escalation 9 vs 33 (p < 1e-4). The slim catalog costs nothing while the Skill is in context and halves compliance when it is not.

    Batch 3 also ran the unchanged baseline catalog with the registration order reversed, so pc_search moves from first to last: pass 56/60 against 45/60 (p = 0.011), escalation 1 against 5. One exploratory run, no replication, but it says this compliance is sensitive to catalog layout at all, which cuts both ways: a 60-observation test can be moved by things other than token count, and layout may be a cheaper lever than tokens.

    Limits: one model, one host, synthetic prompts with controlled empty results, and I did not find the mechanism.

    What I take from it.

    1. The schema projection stays out of the tree. The prototype (modelSchema in tools.ts, pi-ai validation in prepareArguments, Pi tests passing) is on my fork as perf/pi-tool-schemas if anyone wants to repeat the runs with another model; a model that treats the constraints as noise rather than signal may not regress.
    2. The catalog cost is real and 86% of it is parameters, so the levers left are the ones that change which tools the model sees rather than how each is written: a recommended default (about -25%, keeping the handoff carriers), or on-demand activation (ExtensionAPI.setActiveTools exists in Pi 0.82.1; each change rebuilds the system prompt, so it costs one cache miss and interacts with stage 2).
    3. Tool order deserves its own pre-registered test before anyone draws on the control result.

    If maintainers have a preference between the profile default and the activation route, I would rather know it before spending runs on either.

  5. Fengzdadi commented on Oct 24, 2026

    @Fengzdadi
    Fengzdadi
    on Oct 24, 2026
    ContributorAuthor

    A correction to the stage 3 numbers above. I ran a fourth, pre-registered batch on 2026-10-23 to test whether one hardened guidance sentence restores empty_search compliance under the slim catalog. Two results, the second more important than the first.

    The hardened sentence does not help. Four arms, 60 observations each, same evaluator, model and settings as before, catalogs A/B byte-identical to the earlier baseline/candidate. The sentence, inserted after "An empty search does not authorize an inventory.", told the model to stop after at most one reformulation, report what was searched, and not call pc_memory_list or search again.

    Arm Schemas Guidance Pass Escalated to pc_memory_list Third pc_search
    A baseline current 45/60 5 9
    B slim current 41/60 5 13
    C baseline hardened 33/60 1 26
    D slim hardened 29/60 1 30

    Pass A vs C p = 0.035, A vs D p = 0.0046 (two-sided Fisher). The sentence cuts inventory calls but roughly triples third searches, so it trades one failure for another and lowers the pass rate on the unchanged catalog too. Nothing from this is proposed.

    The slim-schema regression did not reproduce. A vs B in this batch is 45 vs 41 on pass (p = 0.54) and 5 vs 5 on escalation; Skill-unloaded is 18/30 vs 18/30. The three earlier batches gave 133/180 vs 97/180 and 13 vs 43. Same catalog bytes, same evaluator revision, same model string and temperature; the only harness difference is a retry wrapper for HTTP 429, which resends the identical request. I cannot attribute the change to anything on our side, so the most likely reading is provider-side drift in qwen/qwen3.7-flash between days, which the evaluator does not record.

    What I would now claim is weaker than what I wrote above: on this model the empty-search case is not stable enough across sessions for 60-observation arms to settle whether the slim catalog hurts. Pooled over all four batches it still reads as a regression (178/240 vs 138/240 pass, 18 vs 48 escalation), but the pool mixes sessions with very different effect sizes. The prototype stays on my fork, unproposed, and the takeaways about where the tokens are (86% parameters) and the activation/profile levers are unaffected. Raw outputs and the pre-registration are available if anyone wants them.

  6. Fengzdadi
    added a commit that references this issue on Oct 25, 2026

    perf(atomic-memory): skip reconciliation when a candidate has nothing…

    44cf48c

  7. Fengzdadi commented on Nov 5, 2026

    @Fengzdadi
    Fengzdadi
    on Nov 5, 2026
    ContributorAuthor

    Status update, stage by stage, against upstream master 8d01851a.

    Stage State Where
    1. Hook recall Done #2231, #2144 → #2258
    2. Injection placement Moved to the gateway track RFC #2086, #2313, #2250
    3. Tool catalog Measured, no change comments above
    4. Source capture (Bub) No change —
    5. Extraction and reconciliation Three fixes merged #2139, #2185, #2206
    6. Flush wait (Bub) No change —
    7. pc_search Nothing to do —

    1. Hook recall. #2231 (merged 10-28) sets one query-embedding deadline per preparation instead of one per search, and raises the default recall_embedding_timeout_seconds from 0.25 s to 0.5 s. With one Scope and a remote provider, ready preparations went from 40–44/60 to 59–60/60. With three Scopes and a stalled provider, a preparation now waits 0.61 s, against 1.06 s with the old per-search 0.25 s budget. For diagnosis, #2144 first added explain / reason; #2258 (merged 11-01) replaced them with the opt-in Receipt (include_receipt), which records each retrieval round and its fallback. That covers per-preparation diagnosis. Scope statistics still do not separate "nothing matched" from "matched without the semantic path"; I am leaving that item in #2039 and not working on it. Follow-up: Kimi Code, ZCode and DSH still use a 1 s request / 4 s total prepare budget, against 3 s / 6 s on the other hosts.

    2. Where the context is injected. I did not implement the Pi message placement proposed above. RFC #2086 (merged 11-02) puts the cache decision in the final executor: it applies the model's cache settings before final rendering, and #2313 adds reuse proofs so an executor can keep prepared context across turns without re-preparing it. With host plugins becoming thin adapters behind the gateway (#2250), cache-preserving placement belongs there, not in one host package. One envelope item did move: the Server already prepends TRUST_POLICY, but several adapters add their own trust sentence on top. #2476 removes it for Kimi Code, and the other adapters follow under #2250.

    3. Tool catalog. The data is in the two comments above: 86% of the Pi catalog is parameter schemas, and the schema projection stays on my fork. Master is unchanged; Pi still registers 35 tools. Which tools a host exposes is now part of the #2250 thin-plugin plan, so I am not opening a separate Pi profile or setActiveTools change.

    4. Source capture. No change. capture_events is off by default in the Bub plugin, so only runs that turn it on capture each model and tool result.

    5. Extraction and reconciliation.

    6. Who waits for the flush. No change. The Bub plugin still awaits a checkpoint flush every 5 captured events, inside the turn.

    What is left here. Stage 5 reasoning settings and the stage 6 Bub flush wait are the two items that no other issue tracks. I am keeping this issue open for them; the rest is either merged or tracked elsewhere (#2039, #2250, RFC #2086).

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

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions