headroomlabs-ai
diff --git a/‎headroom/perf/analyzer.py‎
Lines changed: 30 additions & 1 deletion b/‎headroom/perf/analyzer.py‎
Lines changed: 30 additions & 1 deletion
diff --git a/‎tests/test_cli_perf_format.py‎
Lines changed: 66 additions & 0 deletions b/‎tests/test_cli_perf_format.py‎
Lines changed: 66 additions & 0 deletions
@@ -15,6 +15,7 @@
 import re
 from dataclasses import asdict, dataclass, field
 from datetime import datetime, timedelta
+from pathlib import Path
 
 from headroom import paths as _paths
 from headroom.pricing.litellm_pricing import resolve_litellm_model
@@ -218,6 +219,10 @@ class PerfReport:
     transform_records: list[TransformRecord] = field(default_factory=list)
     toin_records: list[ToinRecord] = field(default_factory=list)
     log_files_read: int = 0
+    # Rotated files skipped unopened because they were last written before the
+    # requested window. Reported so coverage stays honest: `log_files_read` on
+    # its own would silently understate how much log exists on disk.
+    log_files_skipped: int = 0
     total_lines_parsed: int = 0
     # Window covered by the report. `requested_hours` is what the caller
     # asked for; `oldest_kept_ts` / `newest_kept_ts` are the actual
@@ -302,7 +307,31 @@ def _track_window(ts_str: str | None) -> None:
             report.newest_kept_ts = ts_str
 
     # Collect log files: proxy.log, proxy.log.1, proxy.log.2, ...
-    log_files = sorted(log_dir.glob("proxy.log*"), key=lambda p: p.stat().st_mtime)
+    #
+    # A rotated file last written before the cutoff cannot contain a record
+    # inside the window, so skip it without opening it. Without this the cost
+    # of a windowed query is O(total log history) rather than O(window):
+    # `/stats` recomputes throughput over the last hour on a 10s cache TTL, so
+    # a dashboard polling it re-read and re-regexed every byte of every
+    # rotated log, forever, for an answer that lives in the tail of the newest
+    # file. Measured on a developer machine with six rotations (54 MB).
+    #
+    # mtime is the safe discriminator: the logs are append-only, so a file
+    # untouched since before the cutoff has no line written after it. Files
+    # are stat'd once and the value reused for the sort.
+    cutoff_epoch = cutoff.timestamp() if cutoff is not None else None
+    dated_files: list[tuple[float, Path]] = []
+    for path in log_dir.glob("proxy.log*"):
+        try:
+            mtime = path.stat().st_mtime
+        except OSError:
+            # Rotated away between glob and stat — nothing to read.
+            continue
+        if cutoff_epoch is not None and mtime < cutoff_epoch:
+            report.log_files_skipped += 1
+            continue
+        dated_files.append((mtime, path))
+    log_files = [path for _, path in sorted(dated_files, key=lambda pair: pair[0])]
 
     for log_file in log_files:
         report.log_files_read += 1
 
@@ -5,6 +5,8 @@
 import csv
 import io
 import json
+import os
+from datetime import datetime, timedelta
 
 import pytest
 from click.testing import CliRunner
@@ -230,6 +232,70 @@ def test_parse_perf_line_preserves_client_field(monkeypatch, tmp_path):
     assert report.perf_records[0].client == "codex"
 
 
+def _perf_line(ts: datetime, client: str) -> str:
+    return (
+        f"{ts.strftime('%Y-%m-%d %H:%M:%S')},000 - headroom.proxy - INFO - "
+        f"[hr_x] PERF model=gpt-5 msgs=3 tok_before=1000 "
+        f"tok_after=90 tok_saved=910 cache_read=0 cache_write=0 "
+        f"cache_hit_pct=0 opt_ms=12 transforms=content_router client={client}\n"
+    )
+
+
+def _write_log(path, text: str, mtime: datetime) -> None:
+    path.write_text(text)
+    stamp = mtime.timestamp()
+    os.utime(path, (stamp, stamp))
+
+
+def test_windowed_parse_skips_rotated_logs_older_than_the_cutoff(monkeypatch, tmp_path):
+    """A windowed query must cost O(window), not O(total log history).
+
+    `/stats` recomputes throughput over the last hour on a 10s cache TTL, so
+    reading every rotated log each time made the endpoint slower the longer
+    the proxy had been running.
+    """
+    log_dir = tmp_path / "logs"
+    log_dir.mkdir()
+    now = datetime.now()
+    _write_log(
+        log_dir / "proxy.log.1",
+        _perf_line(now - timedelta(days=3), "stale"),
+        now - timedelta(days=3),
+    )
+    _write_log(log_dir / "proxy.log", _perf_line(now - timedelta(minutes=5), "live"), now)
+    monkeypatch.setattr(analyzer, "LOG_DIR", log_dir)
+
+    report = analyzer.parse_log_files(last_n_hours=1.0)
+
+    assert [r.client for r in report.perf_records] == ["live"]
+    # The stale file was never opened, so its lines were never even counted.
+    # Asserted before the counters below because a read-then-filter
+    # implementation also yields the right records -- only the work differs.
+    assert report.total_lines_parsed == 1
+    assert report.log_files_read == 1
+    assert report.log_files_skipped == 1
+
+
+def test_unwindowed_parse_still_reads_every_rotated_log(monkeypatch, tmp_path):
+    """`--hours 0` means "all data" and must not prune anything."""
+    log_dir = tmp_path / "logs"
+    log_dir.mkdir()
+    now = datetime.now()
+    _write_log(
+        log_dir / "proxy.log.1",
+        _perf_line(now - timedelta(days=3), "stale"),
+        now - timedelta(days=3),
+    )
+    _write_log(log_dir / "proxy.log", _perf_line(now - timedelta(minutes=5), "live"), now)
+    monkeypatch.setattr(analyzer, "LOG_DIR", log_dir)
+
+    report = analyzer.parse_log_files(last_n_hours=0)
+
+    assert {r.client for r in report.perf_records} == {"stale", "live"}
+    assert report.log_files_skipped == 0
+    assert report.log_files_read == 2
+
+
 def test_perf_csv_by_model(runner, monkeypatch):
     _patch_report(monkeypatch, _sample_report())
     result = runner.invoke(main, ["perf", "--format", "csv"])