feat: fs_slow_request diagnostic log for slow list operations#747
feat: fs_slow_request diagnostic log for slow list operations#747qiffang wants to merge 2 commits into
Conversation
When handleList takes ≥500ms (handler-internal, excluding auth), emit a production-visible fs_slow_request log with op, path, entries, status, total_ms, read_dir_ms, tenant_id, and api_key_id. This helps diagnose latency spikes like the 1993ms list observed in production without enabling bench timing globally. Known limitation: auth/middleware overhead is not included in this log — that gap requires injecting auth start time via context (follow-up PR). Co-Authored-By: Claude Opus 4.6 <noreply@anthropic.com>
|
No actionable comments were generated in the recent review. 🎉 ℹ️ Recent review info⚙️ Run configurationConfiguration used: defaults Review profile: CHILL Plan: Pro Run ID: 📒 Files selected for processing (2)
🚧 Files skipped from review as they are similar to previous changes (1)
📝 WalkthroughWalkthrough
ChangesFilesystem slow-request logging
Estimated code review effort: 2 (Simple) | ~10 minutes Sequence Diagram(s)sequenceDiagram
participant handleList
participant ReadDirCtx
participant logSlowFSList
participant Logger
handleList->>ReadDirCtx: Read directory entries
handleList->>logSlowFSList: Pass path, count, status, and timing data
logSlowFSList->>Logger: Emit fs_slow_request at threshold
🚥 Pre-merge checks | ✅ 4 | ❌ 1❌ Failed checks (1 warning)
✅ Passed checks (4 passed)
✨ Finishing Touches📝 Generate docstrings
🧪 Generate unit tests (beta)
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. Comment |
qiffang
left a comment
qiffang
left a comment
There was a problem hiding this comment.
adversary-2 R1 — GREEN at HEAD
Minimal, correct, well-tested.
logSlowFSListonly fires at ≥500ms handler duration, zero noise on normal requests.- Named constant
slowFSRequestThreshold— good, not a magic number. - Reuses existing
serverDurationMs,requestMetricScope— no new abstractions. - Fields match what was agreed:
op,path,entries,status,total_ms,read_dir_ms,tenant_id,api_key_id. No sensitive payload. - Tests cover below/at/above threshold + field assertions + integration test proving fast list produces no log.
- Known gap (auth/middleware phase) explicitly documented in both code comment and PR description.
No issues found.
![coderabbitai[bot]](https://avatars.githubusercontent.com/in/347564?s=60&v=4){kind=small}
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 `@pkg/server/server_test.go`:
- Around line 463-465: Update pkg/server/server_test.go lines 463-465 and
474-504 to use t.Errorf for assertion failures, including the fs_slow_request
absence, log presence, and field validations; retain t.Fatalf at line 482 for
the len(entries) != 1 guard because subsequent access depends on it.
- Around line 453-455: Update the request setup in the test around
http.NewRequest and http.DefaultClient.Do to check both returned errors and fail
the test immediately with the underlying error before accessing the response.
Only close resp.Body after the request succeeds and resp is confirmed non-nil.
🪄 Autofix (Beta)
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: defaults
Review profile: CHILL
Plan: Pro
Run ID: 757813aa-bd43-4078-a38c-af6bfeab7fab
📒 Files selected for processing (2)
pkg/server/server.gopkg/server/server_test.go
![chatgpt-codex-connector[bot]](https://avatars.githubusercontent.com/in/1144995?s=60&v=4){kind=small}
There was a problem hiding this comment.
💡 Codex Review
Here are some automated review suggestions for this pull request.
Reviewed commit: d8dd8e1833
ℹ️ 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".
| w.Header().Set("Content-Type", "application/json") | ||
| _ = json.NewEncoder(w).Encode(map[string]any{"entries": out}) | ||
|
|
||
| logSlowFSList(r.Context(), path, len(entries), time.Since(start), readDirDuration) |
There was a problem hiding this comment.
Because this call is only reached on the successful path, any slow ReadDirCtx that eventually returns an error (for example a DB timeout/deadlock or a slow not-found lookup) exits above without the new production-visible fs_slow_request log, leaving only the bench-gated server_list_timing. Since the diagnostic is meant to catch slow list handlers and already includes a status field, consider recording the status and logging from a deferred path or each error return as well.
Useful? React with 👍 / 👎.
There was a problem hiding this comment.
Fixed in 3cde92d. logSlowFSList now takes a status int param, and handleList calls it on both error returns (404 not-found and 500 internal error) before returning — not just the success path. The real HTTP status is threaded through instead of hardcoding StatusOK, so a slow ReadDirCtx that eventually errors (DB timeout/deadlock, slow not-found) now emits fs_slow_request with the correct status. Added a regression assertion covering the 500 error-path status.
|
GREEN from adversary-1 on exact head No blockers found. The diff is scoped to Validation:
Local focused |
srstack
left a comment
srstack
left a comment
There was a problem hiding this comment.
Reviewed (read-only diff — did not compile locally). Clean, focused, well-tested observability addition. Approving.
Logic is correct and follows the established pattern. logSlowFSList early-returns below slowFSRequestThreshold (500ms) and otherwise emits a production-visible logger.Info (not bench-gated), mirroring the existing slowWriteBodyReadThreshold/logSlowWriteBodyRead idiom. Fast lists stay silent.
Verified the wiring against the actual code (not just the diff):
start(handler entry, line 5) andreadDirDuration(readDirStart/time.Since, lines 13-15) are both defined inhandleList, sotime.Since(start)(full handler span) andreadDirDuration(ReadDir-only) are the right two durations.requestMetricScope(ctx)exists ininstrumentation.gowith signature(tenantID, apiKeyID, provider); discardingproviderhere matches its 5 existing call sites.serverDurationMsexists.statusis hardcodedhttp.StatusOK, which is correct because the log fires only after the response is successfully encoded (error paths return earlier and are logged elsewhere).
Tests are solid: TestListDirFastNoSlowLog (end-to-end fast list → zero fs_slow_request), and TestLogSlowFSListThreshold pinning the 499→no-log / 500→log / 2s→log boundary plus asserting op/path/entries/status/total_ms/read_dir_ms fields. The < (strict) comparison means exactly-500ms logs, which matches the "at threshold → log" assertion.
One thing worth emphasizing (you already flagged it, not blocking): this covers only handler-internal time (ReadDir + serialization), not auth/middleware. That matters for the motivating case — a 1993ms list where the time may well be in pool.Acquire() cold-open. If so, this log will show a small total_ms and could read as "handler was fast" while the real latency is upstream and invisible here. The known-limitation note and the follow-up plan to inject auth start time via context are the right call; I'd prioritize that follow-up since cold-open is the likeliest culprit for the exact symptom this PR is chasing. As-is, this is still a strict improvement (it catches genuinely slow ReadDir/serialization, which the bench-gated logs couldn't surface in prod).
LGTM.
|
Follow-up to my review: the cold-open blind spot I flagged is now covered by #748 (merged), so What #748 does (now on main):
How this pairs with #747:
Together they split the request lifecycle, so for a slow request you can now tell in production whether the time went to cold-open ( |
- server_test.go: check http.NewRequest/Do errors to prevent nil-pointer panic on resp.Body.Close() (coderabbit r3593155751) - server_test.go: use t.Errorf for assertion failures, keep t.Fatalf only for the len(entries)!=1 guard that would otherwise panic (coderabbit r3593155768) - server.go: log fs_slow_request on slow list error paths (not-found / internal error), threading the real HTTP status through logSlowFSList instead of hardcoding StatusOK (codex r3593156384) - add regression assertion for the error-path status field Co-Authored-By: Claude Opus 4.8 <noreply@anthropic.com>
2 participants
Summary
fs_slow_requestlog whenhandleListhandler takes ≥500msslowFSRequestThreshold(500ms), follows existingslowWriteBodyReadThresholdpatternop,path,entries,status,total_ms,read_dir_ms,tenant_id,api_key_idlogger.Info(notInfoBenchTiming), so it fires in production without bench flagMotivation
A production GET
/v1/fs/.../upload?listtook 1993ms for 11 entries. Existing timing logs (server_list_timing,tenant_auth_timing) are behindBenchTimingLogEnabled()and invisible in production. This adds a single slow-path log to diagnose where time is spent.Known limitation
This PR only covers handler-internal time (ReadDir + serialization). Auth/middleware overhead is not included — if the 2s is in
pool.Acquire()cold-open, this log won't capture it. A follow-up PR should inject auth start time via context to cover the full request lifecycle.Test plan
TestListDirFastNoSlowLog: fast list produces nofs_slow_requestlogTestLogSlowFSListThreshold: below threshold → no log; at threshold → log with correct fields; above threshold → log emittedgo build ./pkg/server/cleango vet ./pkg/server/clean🤖 Generated with Claude Code
Summary by CodeRabbit