From f531eeb2cf5e6ad6759dcb7dbac9d788b2ed602c Mon Sep 17 00:00:00 2001 From: Claude Date: Wed, 5 Aug 2026 09:43:44 +0000 Subject: [PATCH] fix(perf): stamp each batched metric with its own timestamp MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit `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 Claude-Session: https://claude.ai/code/session_019baCDT5aP5Z66pLGBCE2Y6 --- .../backend/services/performance_monitor.py | 9 +- tests/unit/test_performance_monitor.py | 90 +++++++++++++++++++ 2 files changed, 97 insertions(+), 2 deletions(-) diff --git a/src/youtube_extension/backend/services/performance_monitor.py b/src/youtube_extension/backend/services/performance_monitor.py index 6d3d1d28e..68d217298 100644 --- a/src/youtube_extension/backend/services/performance_monitor.py +++ b/src/youtube_extension/backend/services/performance_monitor.py @@ -293,13 +293,18 @@ async def record_metrics(self, metrics: Sequence[Mapping[str, Any]]) -> None: return try: - now = datetime.now(timezone.utc) + # Stamp each record with its own ``datetime.now`` exactly as the + # serial ``record_metric`` does. A single shared ``now`` for the + # whole batch gives every row an identical timestamp, which + # diverges from the parity this method's docstring promises and + # erases per-sample ordering for callers that submit genuinely + # distinct samples in one call. records = [ PerformanceMetric( component=entry["component"], metric_name=entry["metric_name"], value=float(entry["value"]), - timestamp=entry.get("timestamp") or now, + timestamp=entry.get("timestamp") or datetime.now(timezone.utc), unit=entry.get("unit", "ms"), tags=entry.get("tags") or {}, ) diff --git a/tests/unit/test_performance_monitor.py b/tests/unit/test_performance_monitor.py index 4ceed2c76..f5972c8ff 100644 --- a/tests/unit/test_performance_monitor.py +++ b/tests/unit/test_performance_monitor.py @@ -1306,6 +1306,96 @@ async def test_batch_matches_serial_buffer_and_collections(self, tmp_path): want.component, want.metric_name, want.value, want.unit ) + @staticmethod + def _walking_clock(instants): + """Stand-in for the module's ``datetime`` whose ``now`` walks a list. + + Wall-clock resolution is too coarse to assert on directly -- several + ``datetime.now()`` calls in a tight loop can legitimately return the + same value -- so distinctness alone would be a flaky proxy for "one + stamp per record". Handing out a known sequence instead makes the + assertion exact: the Nth record must carry the Nth instant, which is + true only if ``now`` was consulted once per record, in order. + + Running out of instants raises ``IndexError``. ``record_metrics`` + swallows it, so the batch lands nothing and the caller's assertion on + buffer contents fails -- an extra clock read cannot pass silently. + """ + remaining = list(instants) + + class _Clock: + @staticmethod + def now(tz=None): + return remaining.pop(0) + + return _Clock + + async def test_batch_stamps_each_record_with_its_own_now(self, monitor): + """Every record gets its own stamp, as serial ``record_metric`` does. + + A single shared ``now`` reused across the batch would give all three + records instant[0] and leave the last two unconsumed. That is the + regression this pins: the docstring promises behaviour identical to + calling ``record_metric`` once per entry, and the timestamp is the one + field where a batched implementation is tempted to diverge. + """ + instants = [ + datetime(2026, 1, 1, 0, 0, second, tzinfo=timezone.utc) + for second in range(3) + ] + + with patch.object( + self._impl_module(), "datetime", self._walking_clock(instants) + ): + await monitor.record_metrics(self._samples(3)) + + assert [m.timestamp for m in monitor.metrics_buffer] == instants + + async def test_batch_honours_an_explicitly_supplied_timestamp(self, monitor): + """An entry carrying its own ``timestamp`` must not be re-stamped. + + Callers replaying buffered samples depend on this: the clock is only + consulted for entries that omit the field. + """ + supplied = datetime(2020, 6, 1, 12, 30, 0, tzinfo=timezone.utc) + generated = datetime(2026, 1, 1, 0, 0, 0, tzinfo=timezone.utc) + + with patch.object( + self._impl_module(), "datetime", self._walking_clock([generated]) + ): + await monitor.record_metrics([ + {"component": "system", "metric_name": "replayed", + "value": 1.0, "unit": "ms", "timestamp": supplied}, + {"component": "system", "metric_name": "live", + "value": 2.0, "unit": "ms"}, + ]) + + stamped = {m.metric_name: m.timestamp for m in monitor.metrics_buffer} + assert stamped == {"replayed": supplied, "live": generated} + + async def test_batch_persists_the_per_record_timestamps(self, monitor): + """The distinct stamps must survive the write, not just the buffer.""" + instants = [ + datetime(2026, 1, 1, 0, 0, second, tzinfo=timezone.utc) + for second in range(3) + ] + + with patch.object( + self._impl_module(), "datetime", self._walking_clock(instants) + ): + await monitor.record_metrics(self._samples(3)) + + conn = sqlite3.connect(monitor.db_path) + try: + rows = conn.execute( + "SELECT metric_name, timestamp FROM performance_metrics " + "ORDER BY metric_name" + ).fetchall() + finally: + conn.close() + + assert [r[1] for r in rows] == [i.isoformat() for i in instants] + async def test_empty_batch_does_no_database_work(self, monitor): calls: list[int] = [] with patch.object(perf_mod.sqlite3, "connect", self._counting_connect(calls)):