fix(perf): stamp each batched metric with its own timestamp - #1400
Conversation
`record_metrics` docstring promises "The observable behaviour is identical to calling `record_metric` once per entry". It was not: the batch hoisted a single `now = datetime.now(timezone.utc)` out of the comprehension and gave every record in the batch that same timestamp, while the serial `record_metric` stamps each metric at the moment it is recorded. Nothing tested the timestamp in either direction, so the divergence was free to persist. It was raised on #1341 (Copilot) and again on #1356, and has now survived two reviews unfixed. Consult the clock per record so the batch is a true drop-in. The `entry["timestamp"]` escape hatch is unchanged: an explicitly supplied timestamp is still honoured and the clock is only read for entries that omit it. Cost is one extra clock read per metric — the background monitor records 7 per 30s cycle, so it is not measurable against the SQLite commit the batch exists to collapse. Three tests pin it. Rather than assert timestamps merely differ — wall-clock resolution is coarse enough that several `now()` calls in a tight loop can legitimately return the same value — they patch the module clock to walk a known sequence, so the Nth record must carry the Nth instant. That holds only if the clock is consulted once per record, in order. Two of the three fail against the shared-`now` code and pass with this change; the third guards the explicit-timestamp path, which was never broken. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_019baCDT5aP5Z66pLGBCE2Y6
|
The latest updates on your projects. Learn more about Vercel for GitHub.
|
|
Important Review skippedAuto reviews are limited based on label configuration. 🏷️ Required labels (at least one) (1)
Please check the settings in the CodeRabbit UI or the ⚙️ Run configurationConfiguration used: Repository YAML (base), Repository UI (inherited), Organization UI (inherited) Review profile: ASSERTIVE Plan: Pro Plus Run ID: You can disable this status message by setting the Use the checkbox below for a quick retry:
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 |
Dependency Review✅ No vulnerabilities or license issues or OpenSSF Scorecard issues found.Snapshot WarningsEnsure that dependencies are being submitted on PR branches and consider enabling retry-on-snapshot-warnings. See the documentation for more information and troubleshooting advice. Scanned FilesNone |
|
@coderabbitai review Auto-review skipped on the label gate again. The required-label list is satisfied by this PR's content ( Generated by Claude Code |
Agent Completion Truth Gate: BLOCKEDReasons: Machine-readable verdict{
"details": {
"collection_errors": [
"incomplete_linked_issue_contract",
"linked_issue_not_agent_task",
"missing_intent_snapshot",
"missing_agent_run_id",
"missing_agent_login"
],
"invalid_fields": [
"policy.agent_login",
"policy.run_id"
]
},
"reasons": [
"invalid_payload"
],
"verdict": "blocked"
} |
|
|
CI status on
|
| Check | Result |
|---|---|
lint-python, guards, validate, gitleaks (working tree), dependency-review |
✅ pass |
Canonical issue and evidence, Agent completion enforcement |
✅ pass |
| Vercel preview | ✅ Ready |
agent-completion/truth-gate |
❌ false positive → #1401 |
Local: 8105 passed, 5 xpassed, 0 failed on tests/unit; ruff clean.
CodeRabbit has not reviewed this PR. The label gate skipped it (labels are applied by the auto-labeler after open, so the gate sees an unlabelled PR); the explicit @coderabbitai review retry was accepted but then hit the account's review rate limit — next slot in ~51 minutes. Worth noting this skip-on-open pattern is hitting every PR in this repo, #1381 included.
Generated by Claude Code
|
Tip For best results, initiate chat on the files or code changes.
The reported The reported passing checks and focused test results support keeping this PR limited to the timestamp fix. CodeRabbit review remains pending until the review rate limit permits a retry. 🐇 ✏️ Learnings added
You are interacting with an AI system. |
2 participants
Canonical issue
Closes #1399
Outcome
PerformanceMonitor.record_metricsbecomes the drop-in for serialrecord_metricthat its docstring already claims to be. Each record in a batch is stamped at the moment it is built, instead of all records sharing one timestamp hoisted out of the comprehension.The
entry["timestamp"]escape hatch is unchanged: an explicitly supplied timestamp is still honoured, and the clock is read only for entries that omit it.Scope
src/youtube_extension/backend/services/performance_monitor.py— per-record clock read inrecord_metrics, plus a comment recording why the hoist is not a valid optimization here.tests/unit/test_performance_monitor.py— three tests pinning the timestamp contract (+90 lines).record_metric(serial path) — already correct, untouched._store_metrics/ the batching itself — the one-connection-one-commit win from perf: batch performance-metric writes into one SQLite round-trip #1341 is preserved exactly; this changes only which instant each row carries.metrics_recordedcount and the SQLite-handle-on-error fix in fix(perf): correct metrics_recorded count and close SQLite handle on error in _store_metric #1360 — a separate concern on a separate branch.Risk
datetime.now()per metric. The background monitor records 7 per 30-second cycle, so this is not measurable against the SQLite commit thatrecord_metricsexists to collapse. No schema, query, or API surface changes.WHERE timestamp < ?for retention pruning,WHERE timestamp >= ?for windowed reads); rows written under either implementation remain readable by both.Verification
Current head
f531eeb.tests/unit/test_performance_monitor.py: 131 passed (128 before, +3).now,test_batch_stamps_each_record_with_its_own_nowandtest_batch_persists_the_per_record_timestampsboth FAIL; both pass with the change. The third (test_batch_honours_an_explicitly_supplied_timestamp) passes either way by design — it guards the explicit-timestamp path, which was never broken.tests/unit: 8105 passed, 5 xpassed, 89 subtests, 0 failed (175s).tests/unit/test_v1_router_extended.pyincluded above;record_metricsis the call the report endpoint makes.ruff checkclean on both changed files.On how the tests assert
Asserting that timestamps merely differ would be flaky: wall-clock resolution is coarse enough that several
now()calls in a tight loop can legitimately return the same value. The tests instead patch the module clock to walk a known sequence, so the Nth record must carry the Nth instant — true only if the clock is consulted once per record, in order. Running out of instants raisesIndexError, whichrecord_metricsswallows, leaving the batch unwritten and failing the buffer assertion; an extra clock read cannot pass silently.Production evidence
Not applicable — no runtime surface, HTTP contract, or deployed artifact changes. The edit is one expression inside an internal service method; there is no user-visible behaviour to observe in a preview deployment. Evidence is the fail-test above, which demonstrates the tests detect the exact regression being fixed.
Relationship to #1356
#1356 carries this same fix and nothing else that is not already on
main. Its other three files landed via #1341, so GitHub's "+428" is measured against a pre-#1341 merge base. #1356 is additionally conflicted (mergeable_state: dirty, two hunks, both these timestamp lines) and blocked on a redagent-completion/truth-gate(invalid_payload— its body is still the unfilled template).This PR takes the fix cleanly off current
mainand adds the test coverage #1356 lacks — its serial-vs-batched parity test asserts buffer and deque contents but never timestamps, so the fix it carries is itself unguarded. #1356 can be closed as superseded once this lands.Agent handoff
mainGenerated by Claude Code