Skip to content

fix(logs): measure the decode rate over the generation window - #6416

Closed
xyjk0511 wants to merge 3 commits into
lidge-jun:devfrom
xyjk0511:feat/generation-window-decode-rate
Closed

xyjk0511 wants to merge 3 commits into
lidge-jun:devfrom
xyjk0511:feat/generation-window-decode-rate

Conversation

@xyjk0511

@xyjk0511 xyjk0511 commented Oct 1, 2026 •

Copy link
Copy Markdown
Contributor

Summary

The Logs decode rate (#4038, #4166) is outputTokens / (durationMs - firstOutputMs). On a reasoning model firstOutputMs is the first visible delta, i.e. the end of the reasoning phase, while outputTokens still includes the reasoning tokens. The numerator counts work the denominator leaves out, so the estimate is inflated by however long the model thought. It also runs to stream close rather than the last token.

This PR records the generation window in the proxy and prefers it when present:

  • genStartMs: the first output item of any kind (Anthropic content_block_start, Responses response.output_item.added), reasoning included.
  • lastOutputMs: the last output delta (content_block_delta, response.*.delta).

Both values are request-relative. They are recorded from the two existing SSE taps (inspectResponseLogSsePayloadParsed for Responses/WebSocket, tapAnthropicSseForLog for Anthropic passthrough and native) by a small new module, src/server/request-log-generation-window.ts, and persisted to usage.jsonl as a validated pair. decodeTokPerSecondResult uses lastOutputMs - genStartMs when the pair exists and keeps MIN_DECODE_WINDOW_MS and estimated: true. Rows without the pair fall back to the existing post-TTFT window, so the change is additive and older rows keep the behavior they have today.

Persisting the window is also the server-side groundwork that #6309 needs: average tokens/sec in Usage from usage history rather than the Logs buffer. The Usage aggregation and UI are deliberately left out of this PR.

Measured effect. These are medians from ~3,000 of my own usage.jsonl rows (output ≥ 200 tokens, window ≥ 2 s), recorded with the same instrumentation applied to 2.63:

model generation window (this PR) current post-TTFT estimate visible-text-only rate
gpt-6-luna 55.7 139.6 57.4
gpt-6.1-sol 30.9 42.6 35.9
gpt-5.6-luna 56.0 96.9 57.4

The visible-text-only rate (non-reasoning tokens ÷ lastOutputMs - firstOutputMs) is an independent cross-check. The generation-window number agrees with it; the current estimate is up to ~2.5× high.

Not covered: translated Claude-inbound paths that do not go through tapAnthropicSseForLog, and per-attempt windows on combo attempts. Both keep the existing post-TTFT estimate.

Refs #4038, #6309

Verification

  • bun run typecheck: passed.
  • bun test tests/usage/request-log-generation-window.test.ts tests/server/management-api-logs-metrics.test.ts tests/test-layout.test.ts tests/test-layout-tooling.test.ts tests/ci-workflows/file-size-ratchet.test.ts: 60 pass, 0 fail.
  • Regression check: with src/server/management/shared.ts reverted to dev, the new decode-rate test fails (expected 100 tok/s, got the post-TTFT 200).
  • bun run privacy:scan: passed. bun run structure:check: passed.
  • bun run test: did not complete locally. The parallel runner hit its 900 s limit on this Windows machine, with failures in 38 files (quota probes, Fake-IP/proxy, gateway profiles, Kiro, account pools). I ran each of those 38 files serially on this branch and on an untouched dev worktree (f86ad0a). Results were identical in 35. Two failed less on this branch. codex-catalog-sync-hardening alternated between 3 and 4 failures on both sides across reruns, and every one was a 5 s timeout. None of these files exercise the changed code paths. The full suite is left to CI.
  • Platform: Windows 11, Bun 1.4.0.
  • Review follow-up (ab2c357, after merging dev at b4616be): docs and wording only. bun run typecheck, structure:check and privacy:scan passed; the focused tests above 60 pass / 0 fail; gui/tests/i18n-locales.test.ts and gui/tests/compatibility-lab-i18n.test.ts 12 pass / 0 fail.
  • GUI: the only change is the logs.detail.reason.decode_window_too_short wording in all ten locales ("window after the first token" became "the measured output window", true for both windows). Rendered from this branch's GUI against a live proxy:

Logs detail showing the reworded decode-window reason

Checklist

  • Scope stays focused and avoids unrelated cleanup.
  • Docs or release notes were updated when needed. (structure/dashboard-and-usage.md, the Logs section of docs-site/.../guides/web-dashboard.md, and the decodeTokPerSecondResult doc comment.)
  • Security-sensitive changes were reviewed for secrets, auth, and unsafe defaults. (Timing integers only; no request content is persisted.)

🤖 Generated with Claude Code

Review readiness checklist

This PR stays in draft until every box below is ticked. Tick all four boxes once the requirements are met:

  • Required local validation passed; commands, results, and any full-suite exception are documented.

  • I pushed my PR to a recent dev commit (at most 10 behind; a maintainer may still ask for the exact tip before merge).

  • I resolved all correct Codex and CodeRabbit findings.

  • My PR is ready for review.

Summary by CodeRabbit

  • New Features
    • Request usage records capture the generation interval for both Anthropic and Responses API streams, supporting more representative decode-rate estimates.
    • Request details show an estimated decode rate based on output during the measured generation window when available. Older records use the time after the first visible token instead.
  • Bug Fixes
    • Decode-rate estimates are unavailable for measured windows shorter than one second or invalid intervals. Incomplete or inconsistent timing data is excluded from usage records.

The post-TTFT decode estimate divides all output tokens, reasoning
included, by the time after the first VISIBLE delta, so reasoning models
read up to ~2.5x high. Record when generation starts (first output item
of any kind) and when the last output delta arrives, persist both to
usage.jsonl as a validated pair, and prefer that window in
decodeTokPerSecondResult. Rows without the pair keep the old estimate.

Refs lidge-jun#4038, lidge-jun#6309

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
@chatgpt-codex-connector

Copy link
Copy Markdown

You have reached your Codex usage limits for code reviews. You can see your limits in the Codex usage dashboard.
To continue using code reviews, add credits to your account and enable them for code reviews in your settings.

@github-actions

github-actions Bot commented Oct 1, 2026

Copy link
Copy Markdown
Contributor

✅ Deterministic PR hygiene checks passed.

@github-actions github-actions Bot added the bug Something isn't working label Oct 1, 2026
@coderabbitai

coderabbitai Bot commented Oct 1, 2026 •

Copy link
Copy Markdown
Contributor

Review in Change Stack →

Navigate logical layers of code changes, visualize relationships, and explore their blast radius.

No actionable comments were generated in the recent review. 🎉

ℹ️ Recent review info
⚙️ Run configuration

Configuration used: Repository: lidge-jun/opencodex/.coderabbit.yaml

Review profile: ASSERTIVE

Plan: Advanced

Run ID: fb5c1cb2-2edb-4346-bfda-8e75000971a3

📥 Commits

Reviewing files that changed from the base of the PR and between 895d2e9 and ab2c357.

📒 Files selected for processing (16)
  • docs-site/src/content/docs/guides/web-dashboard.md
  • gui/src/i18n/de.ts
  • gui/src/i18n/en.ts
  • gui/src/i18n/fr.ts
  • gui/src/i18n/ja.ts
  • gui/src/i18n/ko.ts
  • gui/src/i18n/ru.ts
  • gui/src/i18n/tr.ts
  • gui/src/i18n/vi.ts
  • gui/src/i18n/zh-TW.ts
  • gui/src/i18n/zh.ts
  • scripts/test-layout/layout.json
  • src/server/claude-messages.ts
  • src/server/management/shared.ts
  • structure/dashboard-and-usage.md
  • tests/fixtures/test-layout-expected.json

Included review availability: This review used your included allowance. Your plan provides up to 10 included reviews per hour; 9 remain after this review.


📝 Walkthrough

Walkthrough

The change records generation start and last-output times from Anthropic and Responses events. Request logs expose these times relative to request start, and usage entries persist valid pairs. Decode-rate calculations use the generation window when available.

Changes

Generation Window Tracking

Layer / File(s) Summary
Capture and project generation timestamps
src/server/request-log-generation-window.ts, src/server/request-log.ts, src/server/claude-messages.ts
SSE inspectors record generation events. Request logs store the first generation timestamp and latest output timestamp, then project them as request-relative offsets.
Persist and normalize generation windows
src/usage/log.ts, src/server/request-log.ts
Usage entries include both window fields. Request-log persistence and restoration carry the fields. Normalization drops both unless they form a valid pair.
Calculate and validate decode rates
src/server/management/shared.ts, tests/usage/request-log-generation-window.test.ts, scripts/test-layout/layout.json, tests/fixtures/test-layout-expected.json, docs-site/src/content/docs/guides/web-dashboard.md, gui/src/i18n/*, structure/dashboard-and-usage.md
Decode-rate calculations use a valid generation window. The existing first-output-based calculation remains the fallback when timestamps are unavailable or non-finite. Tests cover timing, rate outcomes, persistence, and SSE taps. Documentation and translations describe the measured output window.

Priority: ⬇️ Low

Estimated code review effort: 3 (Moderate) | ~20 minutes

Change: Bug fix

Sequence Diagram(s)

sequenceDiagram
  participant SSE as SSE inspector
  participant Recorder as recordGenerationEvent
  participant RequestLog
  participant UsageLog
  participant DecodeRate as decodeTokPerSecondResult
  SSE->>Recorder: parsed event type and timestamp
  Recorder->>RequestLog: update generation timestamps
  RequestLog->>UsageLog: persist request-relative timestamp pair
  UsageLog-->>DecodeRate: normalized usage entry
  DecodeRate->>DecodeRate: calculate rate from generation window when valid
Loading

Merge Risk: ⚪ Minimal · up to ab2c3

The change adds optional generation-window decode-rate estimates while retaining the older-record fallback. The PR reports passing focused checks; no actionable risk is established, with the full suite left to CI.

Architecture Summary

Architecture risk: 🔵 Low · up to ab2c3

The change affects 6 systems.

Changed systems: gui, src, tests, docs-site, scripts, structure

Architecture concerns
No architecture-level concerns identified.

Review details

Systems and components

  • observed — gui (service) was modified; 10 changed files map to changed impact.
  • observed — src (service) was modified; 5 changed files map to changed impact.
  • observed — tests (service) was modified; 2 changed files map to changed impact.
  • observed — docs-site (service) was modified; 1 changed file maps to changed impact.

Before / after behavior

  • observed — Modified behavior in src/server/request-log-generation-window.ts: Adds event handling that ignores non-string types and non-finite timestamps, records the first start time for the specified Anthropic and Responses start events, and records both a start time if absent and the latest output time for the specified delta events. Other event types leave the window unchanged.
  • observed — Modified behavior in src/server/request-log-generation-window.ts: Adds a function that returns request-relative start and last-output offsets only when both timestamps are present and the request start is finite; returned offsets are clamped to zero or greater, otherwise the function returns an empty object.
  • observed — Modified behavior in src/server/request-log.ts: Imports generationWindowFields and recordGenerationEvent for generation-window tracking and log projection.
  • observed — Modified behavior in src/server/request-log.ts: Adds optional context timestamps for the first output item and last output delta.
🚥 Pre-merge checks | ✅ 4 | ❌ 1

❌ Failed checks (1 warning)

Check name Status Explanation Resolution
Docstring Coverage ⚠️ Warning Docstring coverage is 66.67% which is insufficient. The required threshold is 80.00%. Docstring coverage is scoped to functions touched by this diff. Analyzed 9 functions across 16 files. (4 skipped: … Write docstrings for the functions missing them to satisfy the coverage threshold.
✅ Passed checks (4 passed)
Check name Status Explanation
Linked Issues check ✅ Passed Check skipped because no linked issues were found for this pull request.
Out of Scope Changes check ✅ Passed Check skipped because no linked issues were found for this pull request.
Description Check ✅ Passed Check skipped - CodeRabbit’s high-level summary is enabled.
Title check ✅ Passed The title clearly and concisely describes the primary change: measuring decode rate over the generation window. This matches the implementation and PR objectives.
Full details: Docstring Coverage

Explanation

Docstring coverage is 66.67% which is insufficient. The required threshold is 80.00%. Docstring coverage is scoped to functions touched by this diff. Analyzed 9 functions across 16 files. (4 skipped: 4 unsupported.)

  • Fix all pre-merge checks with AI
✨ Finishing Touches 💡 1
🛠️ Fix failing CI checks 💡
  • Commit to this branch
  • Create a new PR
🧪 Generate unit tests (beta)
  • Create a new PR
  • Autopilot · Keep fixing CodeRabbit findings and required CI, and resolving merge conflicts

Autopilot is currently an internal CodeRabbit preview.


Thanks for using CodeRabbit! It's free for OSS, and your support helps us grow. If you like it, consider giving us a shout-out.

❤️ Share

Comment @coderabbitai help to get the list of available commands.

@github-actions

github-actions Bot commented Oct 1, 2026 •

Copy link
Copy Markdown
Contributor

✅ READY

  • all PR quality gates passed; the review readiness checklist is complete.

Review readiness checklist

  • ✅ Required local validation passed; commands, results, and any full-suite exception are documented.
  • ✅ I pushed my PR to a recent dev commit (at most 10 behind; a maintainer may still ask for the exact tip before merge).
  • ✅ I resolved all correct Codex and CodeRabbit findings.
  • ✅ My PR is ready for review.

✅ 4/4 boxes ticked.

This pull request has been marked Ready for Review.
The review-ready label marks this PR as ready; review automation runs independently.
Maintainers notified: @lidge-jun @Ingwannu

Hygiene

✅ Deterministic PR hygiene checks passed.

@github-actions
github-actions Bot marked this pull request as draft October 1, 2026 19:55
@github-actions
github-actions Bot marked this pull request as ready for review October 1, 2026 20:34

@Ingwannu Ingwannu left a comment

Copy link
Copy Markdown
Owner

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Review at 895d2e9. I read the complete eight-file patch and ran bun test tests/usage/request-log-generation-window.test.ts tests/server/management-api-logs-metrics.test.ts tests/test-layout.test.ts tests/test-layout-tooling.test.ts: 51 passed, 0 failed, 1015 assertions, exit 0, Bun 1.4.0. The actual Responses/Anthropic SSE taps, paired usage persistence, legacy fallback, short-window refusal and existing attempt/history behavior passed in isolated temporary homes under CPUQuota=75%, MemoryHigh=1280M, MemoryMax=1536M, zero swap and TasksMax=64. No live provider request or security scan. The approved current-head hosted CI run 36917793105 completed successfully; intentionally unselected platform jobs do not establish universal OS coverage.

One completion blocker remains: this changes user-visible decode-rate semantics and the persisted usage-row contract, but no owning structure or user documentation changes accompany it. Please update the mapped structure/dashboard-and-usage.md contract and the Logs documentation to explain:

  • Optional genStartMs/lastOutputMs are an observed request-relative pair, measured from the first output item/block (reasoning included) to the last delta, not provider-internal token timing.
  • The generation-window estimate is preferred only with a valid pair; legacy rows retain the post-TTFT fallback and minimum-window/unavailable behavior.
  • End-to-end tok/s remains unchanged; attempt-specific generation windows and request-history presentation are not added by this patch.

Also check the existing logs.detail.reason.decode_window_too_short wording (currently “window after the first token”) against the newly preferred event window, and keep any corrected visible wording consistent across registered locales. A short measured window is still an estimate, not a provider decode benchmark. The new source comment is useful rationale but does not replace the repository's owning-document/user-contract requirement.

Please revalidate and re-attest the resulting head. This request does not ask for a broad metrics redesign or a live benchmark; the focused production-path regressions are good evidence for the bounded implementation.

xyjk and others added 2 commits October 2, 2026 12:56
Review on lidge-jun#6416 asked for the owning structure doc and the Logs user docs to
state the new decode-rate semantics, and for the short-window reason wording
to match the window that is now preferred.

Constraint: structure/dashboard-and-usage.md sits at the 600-line budget, so two redundant blank lines were dropped to fit the new paragraph
Rejected: keep "window after the first token" wording | wrong for rows that carry the generation window
Confidence: high
Scope-risk: narrow
Directive: keep decode_window_too_short wording identical in meaning across all registered locales
Tested: bun run typecheck; structure:check; privacy:scan; focused usage/logs/layout/ratchet tests 60 pass; gui i18n tests 12 pass
Not-tested: docs-site build; full bun run test (left to CI)

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
@xyjk0511

xyjk0511 commented Oct 2, 2026

Copy link
Copy Markdown
Contributor Author

Thanks for the review. Addressed in ab2c357 (after merging current dev):

  • structure/dashboard-and-usage.md (Usage history section): documents genStartMs / lastOutputMs as an observed request-relative pair from the first output item or block (reasoning included) to the last delta, not provider-internal token timing; the pair is kept only when valid; the generation window is preferred only with a valid pair, and other rows keep the post-TTFT fallback with the same one-second minimum, unavailable reasons and estimated: true. It also states that end-to-end tok/s is unchanged and that attempts and the request-history view carry no generation window. Two redundant blank lines were dropped to stay within the 600-line budget.
  • docs-site/.../guides/web-dashboard.md: a short Logs paragraph on Decode rate (est.) covering the same points for users.
  • logs.detail.reason.decode_window_too_short: reworded from "window after the first token" to "the measured output window", which is true for both windows, consistently across all ten registered locales. The decodeTokPerSecondResult doc comment now says the same, and no longer claims RequestLogEntry / usage.jsonl are untouched.

Revalidated: bun run typecheck, structure:check, privacy:scan; focused tests (generation window, logs metrics, test layout, file-size ratchet) 60 pass / 0 fail; gui/tests/i18n-locales.test.ts and compatibility-lab-i18n.test.ts 12 pass / 0 fail. I'll re-tick the readiness checklist for this head.

@github-actions
github-actions Bot marked this pull request as draft October 2, 2026 20:01
xyjk0511 pushed a commit to xyjk0511/opencodex that referenced this pull request Oct 2, 2026
@github-actions
github-actions Bot marked this pull request as ready for review October 2, 2026 20:17
robin-bially pushed a commit to robin-bially/opencodex that referenced this pull request Oct 3, 2026
…jun#6416)

Persist the first output-item and last output-delta timing pair, including reasoning.
Prefer that window for estimated decode throughput and retain the legacy TTFT fallback.
Keep end-to-end speed unchanged and synchronize unavailable-window locale copy.

Carries lidge-jun#6416 by @xyjk0511.

Co-authored-by: xyjk0511 <127614382+xyjk0511@users.noreply.github.com>
@lidge-jun

Copy link
Copy Markdown
Owner

Superseded by the integration in #6487, with reviewed follow-up fixes in #6490 and Windows validation repairs in #6494/#6495, all merged into dev.

Generation-window decode-rate telemetry, legacy fallback, documentation and locale wording were carried and reconciled. End-to-end throughput remains a distinct metric.

Original carry commit: 2abd7341a3c761bba14f54c91128ce656ab99ed6. Attribution to @xyjk0511 is preserved in the integration history and merge trailers. The final integrated candidate passed the complete cross-platform CI run.

Closing this PR as superseded, not claiming that its original head was merged. Thank you for the contribution.

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

Labels

bug Something isn't working review-ready superseded

Projects

None yet

Development

Successfully merging this pull request may close these issues.

3 participants