Skip to content

feat(logs): expose request timing breakdown - #6755

Open
StanleySun233 wants to merge 6 commits into
QuantumNous:mainfrom
StanleySun233:feat/request-timing-breakdown
Open

feat(logs): expose request timing breakdown#6755
StanleySun233 wants to merge 6 commits into
QuantumNous:mainfrom
StanleySun233:feat/request-timing-breakdown

Conversation

@StanleySun233

@StanleySun233 StanleySun233 commented Aug 10, 2026

Copy link
Copy Markdown

⚠️ 提交说明 / PR Notice

Important

  • 本 PR 描述经过整理,仅保留实现范围、边界和可复核证据。
  • 本 PR 由 OpenAI Codex 辅助实现并执行差异检查与本地验证,仍欢迎维护者独立审查阶段语义。

📝 变更描述 / Description

为选定的主流 LLM 请求入口记录端到端阶段耗时,并写入现有日志字段 other.request_timing。本次不新增数据库字段、迁移、配置项或日志接口。

  • 仅覆盖 POST /v1/chat/completions/v1/completions/v1/responses/v1/messages 以及 Gemini generateContent / streamGenerateContent
  • 从请求进入网关开始计时,在目标处理器统一记录上游尝试,并从现有 FRT 与客户端实际写入边界取得可用阶段;SDK、WebSocket、轮询来源不需要单独写死适配器。
  • 成功和错误日志均保存可用字段;普通用户查询日志时保留 request_timing,敏感的 admin_info 过滤逻辑不变。
  • 日志列表和详情页展示相同的阶段明细。新日志优先使用 total_ms 及端到端首数据耗时,旧日志继续回退到 use_time / frt
  • 保留现有 use_timefrt、性能指标和计费逻辑,不扩大到 embeddings、图片、音频、realtime、任务等接口。

脱敏后的流式日志结构示例:

{
  "request_timing": {
    "total_ms": 1320,
    "gateway_ms": 24,
    "upstream_first_data_ms": 411,
    "first_data_to_client_ms": 2,
    "client_stream_ms": 862,
    "finalize_ms": 21
  }
}

无法可靠取得的里程碑会省略,合法的 0ms 阶段会保留。

🚀 变更类型 / Type of change

  • 🐛 Bug 修复 (Bug fix) - 请关联对应 Issue,避免将设计取舍、理解偏差或预期不一致直接归类为 bug
  • ✨ 新功能 (New feature) - 重大特性建议先通过 Issue 沟通
  • ⚡ 性能优化 / 重构 (Refactor)
  • 📝 文档更新 (Documentation)

🔗 关联任务 / Related Issue

✅ 提交前检查项 / Checklist

  • 人工确认: 我已亲自整理并撰写此描述,没有直接粘贴未经处理的 AI 输出。
  • 非重复提交: 我已搜索现有的 IssuesPRs,确认不是重复提交。
  • Bug fix 说明: 若此 PR 标记为 Bug fix,我已提交或关联对应 Issue,且不会将设计取舍、预期不一致或理解偏差直接归类为 bug。
  • 变更理解: 我已理解这些更改的工作原理及可能影响。
  • 范围聚焦: 本 PR 未包含任何与当前任务无关的代码改动。
  • 本地验证: 已在本地运行并通过测试或手动验证,维护者可以据此复核结果。
  • 安全合规: 代码中无敏感凭据,且符合项目代码规范。

📸 运行证明 / Proof of Work

核心测试矩阵:

场景 覆盖结果
流式成功 gateway、首数据、写回、客户端流、收尾阶段;忽略首数据前 keepalive
非流式成功 gateway、上游响应、实际写回、收尾阶段
上游错误 / 网关前错误 仅记录实际可用阶段,不伪造缺失里程碑
渠道重试 保留累计上游等待,清除失败尝试的首数据状态
动态 SSE 升级 响应头升级后同步 stream 状态,首数据前写入不污染阶段
日志权限 普通用户可见 request_timing,仍不可见 admin_info
历史日志 无新字段时回退到 use_time / frt
前端 列表 tooltip、键盘焦点、详情页、非管理员视图及 0ms 阶段

本地结果:

go vet ./...                                  PASS
go test ./... -count=1                       PASS
go build ./...                               PASS
go test -race <timing packages>              PASS
cd relaykit && GOWORK=off go vet/test/build  PASS
web: oxlint (changed files)                   PASS
web: bun run typecheck                        PASS
web: targeted timing tests                    8 pass, 0 fail
web: bun run build:check                      PASS
web: full bun test                            160 pass, 3 baseline failures

完整前端测试剩余 3 个失败均位于既有 api-key-group-cell.test.tsx Auto ring 断言;在未修改的 origin/main 基线上可复现。本 PR 新增和涉及的前端测试全部通过。

Summary by CodeRabbit

  • New Features

    • Added detailed request timing metrics for supported requests, including gateway, upstream, streaming, response-writing, and error phases.
    • Preserved request timing in usage and error logs.
    • Added timing breakdowns to usage-log tables, mobile views, and detail dialogs.
    • Added localized timing labels across supported languages.
  • Bug Fixes

    • Improved first-response timing accuracy for streaming responses and retries.
    • Preserved valid zero-millisecond timing phases while excluding invalid values.
    • Ensured timing is recorded only for eligible request routes and methods.

@coderabbitai

coderabbitai Bot commented Aug 10, 2026

Copy link
Copy Markdown
Contributor

Review Change Stack

Important

Review skipped

No new commits to review since the last review.

⚙️ Run configuration

Configuration used: Organization UI

Review profile: CHILL

Plan: Pro Plus

Run ID: 29e1ec00-50ae-406f-a2b9-15babfc147e4

You can disable this status message by setting the reviews.review_status to false in the CodeRabbit configuration file.

Use the checkbox below for a quick retry:

  • 🔍 Trigger review

Walkthrough

The PR adds request-timing capture for supported relay requests. It records lifecycle phases, persists snapshots in logs, and displays normalized timing breakdowns in usage-log interfaces.

Changes

Request timing observability

Layer / File(s) Summary
Timing session and snapshots
common/request_timing.go, common/request_timing_test.go
RequestTimingSession records lifecycle timestamps and creates snapshots for streaming, non-streaming, retry, failure, and zero-duration cases.
Middleware capture and routing
middleware/request_timing.go, middleware/request_timing_test.go, router/relay-router.go
The middleware filters supported POST routes, tracks successful writes, excludes keepalives and embeddings, and is registered globally.
Relay timing instrumentation
relay/common/relay_info.go, relay/*handler.go, relay/channel/*
Relay handlers mark upstream attempts, synchronize stream state, and record first upstream data.
Log snapshot persistence
model/log.go, model/log_format_test.go, model/log_request_timing_test.go
Consume and error logs store request-timing snapshots under request_timing while preserving log formatting behavior.
Usage-log timing presentation
web/src/features/usage-logs/types.ts, web/src/features/usage-logs/lib/*, web/src/features/usage-logs/components/*, web/src/i18n/locales/*
The frontend validates timing data, derives display values, renders phase breakdowns, and adds translations.
Development build wiring
Dockerfile.dev
The development builder copies relaykit/go.mod before downloading Go modules.

Estimated code review effort: 4 (Complex) | ~60 minutes

Sequence Diagram(s)

sequenceDiagram
  participant Client
  participant RequestTimingMiddleware
  participant RelayInfo
  participant Upstream
  participant LogStore
  participant UsageLogUI

  Client->>RequestTimingMiddleware: Send supported POST request
  RequestTimingMiddleware->>RelayInfo: Attach RequestTimingSession
  RelayInfo->>Upstream: Mark attempt and send request
  Upstream-->>RelayInfo: Return response or first data
  RelayInfo->>RequestTimingMiddleware: Record client writes
  RequestTimingMiddleware->>LogStore: Persist request_timing snapshot
  LogStore-->>UsageLogUI: Provide request_timing metadata
  UsageLogUI-->>Client: Render timing phases
Loading

Poem

A rabbit tracks each hop and stream,
With millisecond paws precise.
Upstream, client, writes align,
Logs keep each timing sign.
Usage views reveal the trail.

🚥 Pre-merge checks | ✅ 4 | ❌ 1

❌ Failed checks (1 warning)

Check name Status Explanation Resolution
Docstring Coverage ⚠️ Warning Docstring coverage is 7.14% which is insufficient. The required threshold is 80.00%. 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 main change: exposing request timing breakdowns in logs.
✨ Finishing Touches
🧪 Generate unit tests (beta)
  • Create PR with unit tests

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.

@coderabbitai coderabbitai Bot left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

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

Actionable comments posted: 4

🤖 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 `@middleware/request_timing_test.go`:
- Around line 46-70: In TestRequestTimingMiddlewareIgnoresKeepaliveWrites,
remove the exact equality assertion on the dereferenced FirstDataToClientMs
value while retaining the existing non-nil assertion. Keep the test focused on
verifying that the keepalive PING is not treated as the first client write.

In `@relay/channel/cloudflare/relay_cloudflare.go`:
- Around line 64-68: In the response loop, keep the first-data marker before
helper.ObjectData while moving info.SetFirstResponseTime() to after
helper.ObjectData completes, preserving the existing FirstResponseTime boundary
that includes rendering and write time. Split the isFirst handling as needed
without changing the existing error flow.

In
`@web/src/features/usage-logs/components/__tests__/request-timing-display.test.tsx`:
- Around line 1-195: Rewrite the request timing display suite to use Vitest and
React Testing Library: replace node:test, happy-dom global setup, createRoot,
act, and manual cleanup with RTL render and screen queries. Update assertions to
use user-facing queries such as screen.getByRole or getByLabelText, and use
userEvent to exercise the timing breakdown trigger interaction rather than
inspecting querySelector results or tagName. Preserve coverage for stream
phases, timing headlines, and non-admin details rendering.

In `@web/src/features/usage-logs/components/timing-metrics-cell.tsx`:
- Around line 161-175: Update the TooltipTrigger accessibility in the timing
metrics component so its accessible name retains the visible duration labels and
values rendered by content. Replace the aria-label usage with an
aria-describedby hint for “Timing breakdown,” or otherwise include the visible
text in the accessible name, and update the associated test assertion to match
the chosen ARIA behavior.
🪄 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: Organization UI

Review profile: CHILL

Plan: Pro Plus

Run ID: d5f2b4bc-6f9d-4743-abe0-21bdac5701c8

📥 Commits

Reviewing files that changed from the base of the PR and between 9c97e78 and 7cf44ea.

📒 Files selected for processing (33)
  • common/request_timing.go
  • common/request_timing_test.go
  • middleware/request_timing.go
  • middleware/request_timing_test.go
  • model/log.go
  • model/log_format_test.go
  • model/log_request_timing_test.go
  • relay/channel/cloudflare/relay_cloudflare.go
  • relay/channel/cohere/relay-cohere.go
  • relay/chat_completions_via_responses.go
  • relay/claude_handler.go
  • relay/common/relay_info.go
  • relay/common/relay_info_test.go
  • relay/compatible_handler.go
  • relay/gemini_handler.go
  • relay/responses_handler.go
  • router/relay-router.go
  • web/src/features/usage-logs/components/__tests__/request-timing-display.test.tsx
  • web/src/features/usage-logs/components/columns/common-logs-columns.tsx
  • web/src/features/usage-logs/components/dialogs/details-dialog.tsx
  • web/src/features/usage-logs/components/request-timing-breakdown.tsx
  • web/src/features/usage-logs/components/timing-metrics-cell.tsx
  • web/src/features/usage-logs/components/usage-logs-mobile-card.tsx
  • web/src/features/usage-logs/lib/__tests__/request-timing.test.ts
  • web/src/features/usage-logs/lib/request-timing.ts
  • web/src/features/usage-logs/types.ts
  • web/src/i18n/locales/en.json
  • web/src/i18n/locales/fr.json
  • web/src/i18n/locales/ja.json
  • web/src/i18n/locales/ru.json
  • web/src/i18n/locales/vi.json
  • web/src/i18n/locales/zh-TW.json
  • web/src/i18n/locales/zh.json

Comment thread middleware/request_timing_test.go Outdated
Comment thread relay/channel/cloudflare/relay_cloudflare.go
Comment thread web/src/features/usage-logs/components/timing-metrics-cell.tsx
@StanleySun233
StanleySun233 force-pushed the feat/request-timing-breakdown branch from 7cf44ea to a7f2455 Compare August 10, 2026 11:18
@StanleySun233

Copy link
Copy Markdown
Author

@coderabbitai review

@coderabbitai

coderabbitai Bot commented Aug 10, 2026

Copy link
Copy Markdown
Contributor
⚠️ Action not completed

Already reviewed.

Note: CodeRabbit is an incremental review system and does not re-review already reviewed commits. This command is applicable only when automatic reviews are paused.

@StanleySun233

Copy link
Copy Markdown
Author

@coderabbitai review

@coderabbitai

coderabbitai Bot commented Aug 10, 2026

Copy link
Copy Markdown
Contributor
⚠️ Action not completed

Already reviewed.

Note: CodeRabbit is an incremental review system and does not re-review already reviewed commits. This command is applicable only when automatic reviews are paused.

@coderabbitai coderabbitai Bot left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

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

Actionable comments posted: 1

🤖 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 `@Dockerfile.dev`:
- Line 15: Replace the ADD instruction for relaykit/go.mod with COPY, preserving
the existing source and destination paths.
🪄 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: Organization UI

Review profile: CHILL

Plan: Pro Plus

Run ID: 96ef4b11-7f5d-46dc-bca1-4fcb8584f53d

📥 Commits

Reviewing files that changed from the base of the PR and between 04139a2 and 94445f3.

📒 Files selected for processing (1)
  • Dockerfile.dev

Comment thread Dockerfile.dev Outdated
@StanleySun233

Copy link
Copy Markdown
Author

@coderabbitai review

@coderabbitai

coderabbitai Bot commented Aug 10, 2026

Copy link
Copy Markdown
Contributor
⚠️ Action not completed

Already reviewed.

Note: CodeRabbit is an incremental review system and does not re-review already reviewed commits. This command is applicable only when automatic reviews are paused.

@Calcium-Ion
Calcium-Ion force-pushed the main branch 2 times, most recently from 51fdfc5 to 2b6f1df Compare August 30, 2026 15:03
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant