feat(agent): stamp elapsedMs on durable run events at emission - #3483
Conversation
📝 WalkthroughWalkthroughThe conversation event encoder now supports optional monotonic elapsed-time stamping. The chunk mirror enables it by default. Tests cover clocked, unclocked, and normalized events. Public exports and API references were updated. ChangesConversation event timing
Estimated code review effort: 3 (Moderate) | ~20 minutes Sequence Diagram(s)sequenceDiagram
participant ConversationRunChunkMirror
participant ConversationRunEventEncoder
participant EncodedEvent
ConversationRunChunkMirror->>ConversationRunEventEncoder: create default encoder with performance.now()
ConversationRunEventEncoder->>ConversationRunEventEncoder: capture creation timestamp
ConversationRunEventEncoder->>EncodedEvent: encode and stamp elapsedMs
Suggested reviewers: 🚥 Pre-merge checks | ✅ 5✅ Passed checks (5 passed)
✨ Finishing Touches📝 Generate docstrings
🧪 Generate unit tests (beta)
Comment |
There was a problem hiding this comment.
Actionable comments posted: 1
🧹 Nitpick comments (2)
src/agent/ag-ui/browser-encoder.ts (1)
69-75: 📐 Maintainability & Code Quality | 🔵 Trivial | ⚡ Quick winUse the required public-copy form.
Replace
SupplywithUse. Replace the em dash with ASCII punctuation.As per coding guidelines, public TypeScript copy must use
usefor actions and must not use em dash characters.🤖 Prompt for AI Agents
Verify each finding against current code. Fix only still-valid issues, skip the rest with a brief reason, keep changes minimal, and validate. In `@src/agent/ag-ui/browser-encoder.ts` around lines 69 - 75, Update the public documentation for nowMs to use “Use” instead of “Supply” and replace the em dash with ASCII punctuation, without changing the option’s behavior or type.Source: Coding guidelines
src/agent/ag-ui/browser-encoder.test.ts (1)
831-859: 📐 Maintainability & Code Quality | 🔵 Trivial | ⚡ Quick winAdd timed finalization coverage.
These tests only exercise
mapRuntimeStreamEventToAgUiBrowserEvents. Add a clocked test forfinalizeAgUiBrowserEventsthat assertselapsedMson the synthesized closing event andRunFinished. This protects the separate finalization stamping path.As per coding guidelines, behavior changes must include focused tests.
🤖 Prompt for AI Agents
Verify each finding against current code. Fix only still-valid issues, skip the rest with a brief reason, keep changes minimal, and validate. In `@src/agent/ag-ui/browser-encoder.test.ts` around lines 831 - 859, Add a focused clock-controlled test for finalizeAgUiBrowserEvents, using createAgUiBrowserEncoderState with nowMs and advancing the clock before finalization. Assert that both the synthesized closing event and RunFinished receive the expected elapsedMs, covering finalization stamping separately from mapRuntimeStreamEventToAgUiBrowserEvents.Source: Coding guidelines
🤖 Prompt for all review comments with AI agents
Verify each finding against current code. Fix only still-valid issues, skip the
rest with a brief reason, keep changes minimal, and validate.
Inline comments:
In `@src/agent/ag-ui/chunk-encoder-bridge.ts`:
- Around line 21-22: Update the nowMs documentation in
src/agent/ag-ui/chunk-encoder-bridge.ts:21-22 to describe it as optional and
state that omission preserves unstamped events. Apply the same opt-in wording in
src/agent/ag-ui/runtime-event-encoder.ts:22-26, removing the false
performance.now and deterministic-test default claims; no implementation changes
are needed.
---
Nitpick comments:
In `@src/agent/ag-ui/browser-encoder.test.ts`:
- Around line 831-859: Add a focused clock-controlled test for
finalizeAgUiBrowserEvents, using createAgUiBrowserEncoderState with nowMs and
advancing the clock before finalization. Assert that both the synthesized
closing event and RunFinished receive the expected elapsedMs, covering
finalization stamping separately from mapRuntimeStreamEventToAgUiBrowserEvents.
In `@src/agent/ag-ui/browser-encoder.ts`:
- Around line 69-75: Update the public documentation for nowMs to use “Use”
instead of “Supply” and replace the em dash with ASCII punctuation, without
changing the option’s behavior or type.
🪄 Autofix
Fix all unresolved CodeRabbit comments on this PR:
- Push a commit to this branch (recommended)
- Create a new PR with the fixes
ℹ️ Review info
⚙️ Run configuration
Configuration used: Repository UI
Review profile: CHILL
Plan: Pro Plus
Run ID: 5d4772c4-c57a-4f92-95cd-fc25b017d4fe
📒 Files selected for processing (5)
docs/api-reference/veryfront/agent.mdsrc/agent/ag-ui/browser-encoder.test.tssrc/agent/ag-ui/browser-encoder.tssrc/agent/ag-ui/chunk-encoder-bridge.tssrc/agent/ag-ui/runtime-event-encoder.ts
There was a problem hiding this comment.
💡 Codex Review
Here are some automated review suggestions for this pull request.
Reviewed commit: 3dc1731279
ℹ️ About Codex in GitHub
Your team has set up Codex to review pull requests in this repo. Reviews are triggered when you
- Open a pull request for review
- Mark a draft as ready
- Comment "@codex review".
If Codex has suggestions, it will comment; otherwise it will react with 👍.
Codex can also answer questions or update the PR. Try commenting "@codex address that feedback".
`agent_run_event.created_at` is `DEFAULT now()` -- the row's database insert time. No event carried an emission timestamp, so nothing downstream could say when an event actually happened, and every duration derived from an export described the writer rather than the run. That is not theoretical. A post-mortem of production run 2f7ae3d4 built a phase waterfall on created_at and concluded the run spent 52% of its wall clock stalled mid-generation. It had not. Three signatures in the same data are impossible under the runtime's own state machine and are what exposed it: a streaming_input -> pending_input -> streaming_input burst inside 60ms when pending requires 5s of idle, TOOL_CALL_ARGS rows beginning 200s after the streaming_input that marks the first delta, and a metronomic ~30ms cadence. ConversationRunEventEncoder is the right place because it is the encoder whose output is persisted: ChatStreamEvent -> encode() -> flat run-event records -> normalizeConversationRunEvents -> flushConversationRunEventBatches -> POST. The AG-UI browser encoder is a separate lane that feeds live SSE to a connected client, and a scheduled run has no client attached, so stamping there would never have reached the database. Stamping happens on the way out of encode() rather than in each case arm, so every emitted record is treated alike -- including the ones this encoder synthesises, such as the terminal result for a provider-executed call the provider never resolved. Elapsed is measured from encoder creation. One encoder spans a whole run: it carries stepCount and the active message across every step, which is why run 2f7ae3d4's five steps share one. So elapsedMs is run-relative and needs no per-attempt anchor, and `agent_run.started_at + elapsed_ms` reconstructs wall clock for any event. Monotonic rather than wall clock: a Date.now() reading can step backwards under NTP, which across thousands of events yields negative durations. Injected rather than captured, so timing stays deterministic in tests the way policy.clock already does for the stream lifecycle runner. The chunk mirror owns one encoder per run, so installing the clock there is what makes production events carry the stamp. Callers injecting their own encoder choose their own clock, or none -- the three mirror tests that assert exact durable events pin an unclocked encoder, since their subject is the mirror rather than timing. A stamp that does not survive normalization never reaches the API, so that is covered directly: an oversized delta splits into parts that each keep the elapsed of the event they came from.
3dc1731 to
faa8ec5
Compare
ConversationRunEventEncoder is re-exported from veryfront/agent but its new options type was not, so consumers importing through the supported entrypoint could not name the constructor parameter, and the type was missing from the generated API reference. Raised by Codex review against the superseded AG-UI revision of this PR. The type it named no longer exists, but the same gap applied to the encoder this PR now changes.
|
Addressed. All five review threads were filed against commit Rather than close them as outdated, I checked whether each concern still applies to the new code. Fixed — the concern carried over. "Export the new encoder state options type" (Codex, P2). Checked — does not apply. "Remove the false default-clock claim" (CodeRabbit) and "Correct the advertised default clock" (Codex, P2). Both were right about the old revision: the JSDoc promised a "Replace em dashes in the public API comment" (Codex, P1). Correct for the old JSDoc. The new comments in "Preserve elapsedMs through the AG-UI SSE schemas" (Codex, P2). The sharpest of the five, and worth spelling out because it prompted a check that closes a gap I had flagged as unverified. It was correct that
I had been flagging "verified in unit tests but not observed reaching Postgres" as an open risk on this PR. Those three checks close the schema half of it. What remains is only observing a live run, which the first export after merge will show. |
There was a problem hiding this comment.
Actionable comments posted: 2
🤖 Prompt for all review comments with AI agents
Verify each finding against current code. Fix only still-valid issues, skip the
rest with a brief reason, keep changes minimal, and validate.
Inline comments:
In `@src/agent/conversation/run-chunk-mirror.ts`:
- Around line 163-169: Add a focused test for createConversationRunChunkMirror
that omits input.encoder, emits a chunk, and verifies the prepared durable event
has a nonnegative elapsedMs, covering the default ConversationRunEventEncoder
clock behavior.
In `@src/agent/conversation/run-events.ts`:
- Around line 63-74: Update the documentation comments for
ConversationRunEventEncoderOptions and the related elapsed-time logic near the
encoder implementation to remove references to internal tables, columns, and
persistence fields such as agent_run_event, created_at, agent_run.started_at,
and elapsed_ms. Describe only the public elapsed-time behavior and its
relationship to encoder creation and run timing.
🪄 Autofix
Fix all unresolved CodeRabbit comments on this PR:
- Push a commit to this branch (recommended)
- Create a new PR with the fixes
ℹ️ Review info
⚙️ Run configuration
Configuration used: Repository UI
Review profile: CHILL
Plan: Pro Plus
Run ID: 6c39b03a-0117-487a-818a-0fa50da0bed7
📒 Files selected for processing (6)
docs/api-reference/veryfront/agent.mdsrc/agent/conversation/run-chunk-mirror.test.tssrc/agent/conversation/run-chunk-mirror.tssrc/agent/conversation/run-events.test.tssrc/agent/conversation/run-events.tssrc/agent/index.ts
…a names Two review findings on the current revision. The mirror's default encoder was unproven. Changing that default is what makes production events carry elapsed, but the three existing mirror tests pin an unclocked encoder to keep their exact-event assertions deterministic, so nothing exercised the default. Adding a test that omits `encoder` and asserts a finite, nonnegative elapsed. Verified it fails with "the default encoder must stamp elapsedMs" when the default clock is removed. The option's JSDoc explained itself by naming the API service's table and columns. This package is published, so a consumer reading it was pointed at storage they cannot see and do not own. Reworded to describe the behaviour they can act on: a persisted event otherwise carries only the time it was stored, which tracks the writer rather than the run. The reasoning is unchanged, the foreign schema names are gone.
|
Both addressed in Add a test for the default mirror encoder (Major). Accepted as written. Changing that default is the thing that makes production events carry elapsed, and the three existing mirror tests pin an unclocked encoder to keep their exact-event assertions deterministic, so nothing exercised it. Added a test that omits Remove private persistence details from comments (Minor). Acted on, though not for the cited reason. The guideline quoted covers sensitive values, and a table name is not one. The real problem is narrower and worth stating: this package is published, and the JSDoc for a public option explained itself by naming the API service's table and columns, so a consumer reading it was pointed at storage they cannot see and do not own. That is poor API documentation independent of any rule. Reworded to describe behaviour the caller can act on:
Same reasoning, no foreign schema names.
|
There was a problem hiding this comment.
🧹 Nitpick comments (1)
src/agent/conversation/run-chunk-mirror.test.ts (1)
81-103: 🩺 Stability & Availability | 🔵 Trivial | ⚡ Quick winMake mirror cleanup unconditional.
Because
flushDelayMsis set to10_000, the mirror can retain delayed flush work. IfhandleChunkor an assertion throws, execution skipsmirror.dispose(). Move the test body intotryand dispose the mirror infinally.Proposed fix
- await mirror.handleChunk({ type: "text-delta", id: "m1", delta: "hello" }); - - const elapsedMs = prepared[0]?.elapsedMs; - assertEquals(typeof elapsedMs, "number", "the default encoder must stamp elapsedMs"); - assertEquals( - typeof elapsedMs === "number" && Number.isFinite(elapsedMs) && elapsedMs >= 0, - true, - `elapsed must be a finite, nonnegative reading, got ${String(elapsedMs)}`, - ); - mirror.dispose(); + try { + await mirror.handleChunk({ type: "text-delta", id: "m1", delta: "hello" }); + + const elapsedMs = prepared[0]?.elapsedMs; + assertEquals(typeof elapsedMs, "number", "the default encoder must stamp elapsedMs"); + assertEquals( + typeof elapsedMs === "number" && Number.isFinite(elapsedMs) && elapsedMs >= 0, + true, + `elapsed must be a finite, nonnegative reading, got ${String(elapsedMs)}`, + ); + } finally { + mirror.dispose(); + }🤖 Prompt for AI Agents
Verify each finding against current code. Fix only still-valid issues, skip the rest with a brief reason, keep changes minimal, and validate. In `@src/agent/conversation/run-chunk-mirror.test.ts` around lines 81 - 103, Wrap the test body after creating the mirror in a try block and move mirror.dispose() into a finally block so cleanup always runs, including when handleChunk or an assertion throws. Keep the existing assertions and mirror configuration unchanged.
🤖 Prompt for all review comments with AI agents
Verify each finding against current code. Fix only still-valid issues, skip the
rest with a brief reason, keep changes minimal, and validate.
Nitpick comments:
In `@src/agent/conversation/run-chunk-mirror.test.ts`:
- Around line 81-103: Wrap the test body after creating the mirror in a try
block and move mirror.dispose() into a finally block so cleanup always runs,
including when handleChunk or an assertion throws. Keep the existing assertions
and mirror configuration unchanged.
ℹ️ Review info
⚙️ Run configuration
Configuration used: Repository UI
Review profile: CHILL
Plan: Pro Plus
Run ID: 852f84df-4665-4ffd-8a0f-72c0aaa3dec1
📒 Files selected for processing (3)
docs/api-reference/veryfront/agent.mdsrc/agent/conversation/run-chunk-mirror.test.tssrc/agent/conversation/run-events.ts
🚧 Files skipped from review as they are similar to previous changes (2)
- src/agent/conversation/run-events.ts
- docs/api-reference/veryfront/agent.md
Makes run traces measurable: every durable run event carries a run-relative
elapsedMstaken when it was emitted.The problem
agent_run_event.created_atisDEFAULT now()— the row's database insert time. No event carried an emission timestamp, so nothing downstream could say when an event actually happened.Not theoretical. A post-mortem of production run
2f7ae3d4built a phase waterfall oncreated_atand concluded the run spent 52% of its wall clock stalled mid-generation. It hadn't — the data described when rows were written. Three signatures in the same export are impossible under the runtime's own state machine, and are what exposed it:streaming_input → pending_input → streaming_inputinside 60ms, whenpendingrequires 5s of idleTOOL_CALL_ARGSrows beginning 200s after thestreaming_inputthat marks the first delta —tool-input-deltamaps straight toToolCallArgs, so those are the same eventWhy this encoder
It is the one whose output is persisted:
Stamping happens on the way out of
encode()rather than in eachcasearm, so every emitted record is treated alike — including ones the encoder synthesises itself, such as the terminal result for a provider-executed call the provider never resolved.Why run-relative, and why monotonic
Elapsed is measured from encoder creation. One encoder spans a whole run — it carries
stepCountand the active message across every step, which is why run 2f7ae3d4's five steps share one. SoelapsedMsneeds no per-attempt anchor, andagent_run.started_at + elapsed_msreconstructs wall clock for any event.Monotonic rather than wall clock:
Date.now()can step backwards under NTP, which across thousands of events yields negative durations. Injected rather than captured, so timing stays deterministic in tests the waypolicy.clockalready does for the stream-lifecycle runner.What makes it live
The chunk mirror owns one encoder per run, so installing the clock at
createConversationRunChunkMirroris what makes production events carry the stamp. Callers injecting their own encoder choose their own clock, or none — the three mirror tests that assert exact durable events pin an unclocked encoder, since their subject is the mirror rather than timing.Tests
Red-first:
elapsedMskey appears at all without a clock — the guard that keeps this invisible to consumers that don't want itsrc/agent+src/internal-agents+src/chat: 1,214 passed, 0 failed. Typecheck,deno fmt --check,deno lintclean.docs/api-referenceregenerated.Follow-up
veryfront-api:
ALTER TABLE agent_run_event ADD COLUMN elapsed_ms integer, lift it withpayload->>'elapsedMs'(it lands as a top-level field, since these records are flat), and expose it alongsidesequence— which exists on the table but is absent from both the API response and the CSV export.Related: veryfront-studio#6345 renames that export's
timestampcolumn tocreated_atso it stops implying it is event time.Summary by CodeRabbit
New Features
Documentation