akadmin/headroom
1
0
Fork 0
mirror of https://github.com/headroomlabs-ai/headroom.git synced 2026-08-27 14:17:10 -04:00
Code Issues Projects Releases Packages Wiki Activity Actions
headroom/tests/test_cli_perf_format.py
gglucass 6c9f41e08c
perf(perf): skip rotated logs outside the requested window (#3081) 
## Description

`parse_log_files(last_n_hours=N)` reads every `proxy.log*` file in full
— line by line, applying the PERF / STAGE_TIMINGS / ROUTER regexes to
each — and only then filters records against the cutoff. The cost of a
windowed query is O(retained log history), not O(window).

`/stats` is the hot caller. `_build_stats_payload` recomputes throughput
over `last_n_hours=1.0` behind a 10s cache TTL, so anything polling the
endpoint re-reads and re-regexes the entire rotated set every 10 seconds
for an answer that lives in the tail of the newest file or two.

Rotation caps the log directory at 10 MB × 5 backups
(`proxy/helpers.py`), so this is a bounded ~60 MB rather than an
unbounded leak. But it is a fixed tax that ramps up as a user's logs
fill toward that ceiling and then stays there — on a machine that has
reached the cap it is ~0.43s of pure waste on every stats rebuild.

The fix: skip any file whose mtime predates the cutoff. The logs are
append-only, so a file untouched since before the window cannot contain
a record inside it. `--hours 0` ("all data") still reads everything.

## Type of Change

- [x] Performance improvement

## Changes Made

- `parse_log_files` prunes rotated files by mtime before opening them;
files are `stat`'d once and the value reused for the ordering
(previously `stat`'d once per file anyway, as the sort key).
- A file that rotates away between `glob` and `stat` is skipped instead
of raising `OSError`.
- New `PerfReport.log_files_skipped` so coverage reporting stays honest
— `log_files_read` on its own would silently understate how much log
exists on disk. Defaulted, so existing callers are unaffected.

## Testing

- [x] Unit tests pass (`pytest`)
- [x] Linting passes (`ruff check .`)
- [x] Type checking passes (`mypy headroom`)
- [x] New tests added for new functionality
- [x] Manual testing performed

Both new tests were confirmed to fail against unpatched `main`. The
windowed one fails on behavior (`total_lines_parsed`: `assert 2 == 1`),
not merely on the new field — the assertion order is deliberate, since a
read-then-filter implementation produces the same records and only
differs in work done.

### Test Output

```text
$ uv run --frozen --extra dev pytest tests/test_cli_perf_format.py \
    tests/test_proxy_dashboard_stats_cache.py tests/test_agent_savings.py -q
59 passed, 1 skipped, 1 warning in 3.36s

$ uvx ruff check headroom/perf/analyzer.py tests/test_cli_perf_format.py
All checks passed!

$ uvx ruff format --check headroom/perf/analyzer.py tests/test_cli_perf_format.py
2 files already formatted

$ uv run --frozen --extra dev mypy headroom/perf/analyzer.py
Success: no issues found in 1 source file
```

## Real Behavior Proof

- Environment: macOS 15 (arm64), Python 3.10.18, headroom-ai at
6d2254df, against a real `~/.headroom/logs` holding 54 MB across six
rotations (`proxy.log` + `.1`–`.5`) from a proxy that had been running
for weeks.
- Exact command / steps: pointed `analyzer.LOG_DIR` at the live log
directory and timed `parse_log_files(last_n_hours=1.0)` three times,
taking the median; ran it once on this branch and once with
`headroom/perf/analyzer.py` stashed back to `main`.
- Observed result: main = 0.426s median, 6 files read, 246,819 lines
parsed. This branch = 0.141s median, 2 files read, 4 skipped, 48,147
lines parsed. 3.0x faster, 80% fewer lines parsed, identical throughput
figure. The two files still read are the live log and one rotation that
had been written inside the last hour, which is correct.
- Not tested: Windows and Linux (the mtime semantics used here are
POSIX-standard and `pathlib` handles both, but I ran only macOS). No
benchmark on a log directory below the rotation ceiling — the win there
is proportionally smaller by construction, since there is less stale
history to skip.

## Runtime Rollout Safety

- Rollout-managed feature(s): none — this is a pure read-path
optimization inside the perf log parser.
- Minimum rollout channel: n/a.
- Stable/default behavior changed: no. Windowed queries return the same
records; only the work to produce them changes. `--hours 0` is
untouched.
- Kill switch / disable path: n/a — revert the commit. There is no flag
because there is no behavior to toggle.
- Unsafe override required: no.
- Qualification impact: none.
- Rollback path: single-commit revert; `PerfReport.log_files_skipped` is
a defaulted field, so no persisted or serialized data depends on it.

## Review Readiness

- [x] I have performed a self-review
- [x] This PR is ready for human review

## Checklist

- [x] My code follows the project's style guidelines
2026-08-17 20:20:56 -07:00

426 lines
16 KiB
Python
Raw Blame History

"""Tests for `headroom perf --format {text,json,csv}` (issue #595)."""
from __future__ import annotations
import csv
import io
import json
import os
from datetime import datetime, timedelta
import pytest
from click.testing import CliRunner
from headroom.cli.main import main
from headroom.perf import analyzer
from headroom.perf.analyzer import (
PerfRecord,
PerfReport,
TransformRecord,
build_overhead_summary,
build_perf_summary,
perf_records_as_dicts,
)
@pytest.fixture
def runner() -> CliRunner:
return CliRunner()
def _sample_report() -> PerfReport:
"""A small report with two models, cache numbers, and a transform."""
return PerfReport(
perf_records=[
PerfRecord(
timestamp="2026-06-05 10:00:00,000",
request_id="hr_1",
model="claude-sonnet-4.5",
num_messages=10,
tokens_before=1000,
tokens_after=400,
tokens_saved=600,
cache_read=800,
cache_write=200,
cache_hit_pct=80,
optimization_ms=12.0,
transforms=["content_router"],
),
PerfRecord(
timestamp="2026-06-05 11:00:00,000",
request_id="hr_2",
model="claude-opus-4-8",
num_messages=4,
tokens_before=1000,
tokens_after=600,
tokens_saved=400,
cache_read=200,
cache_write=0,
cache_hit_pct=100,
optimization_ms=8.0,
transforms=["content_router"],
),
],
transform_records=[
TransformRecord(
timestamp="2026-06-05 10:00:00,000",
name="content_router",
tokens_before=2000,
tokens_after=1000,
tokens_saved=1000,
),
],
log_files_read=1,
total_lines_parsed=42,
requested_hours=24.0,
oldest_kept_ts="2026-06-05 10:00:00,000",
newest_kept_ts="2026-06-05 11:00:00,000",
)
# ---------------------------------------------------------------------------
# Pure builders
# ---------------------------------------------------------------------------
def test_build_perf_summary_totals_and_pct():
summary = build_perf_summary(_sample_report())
assert summary["total_requests"] == 2
assert summary["total_tokens_before"] == 2000
assert summary["total_tokens_after"] == 1000
assert summary["tokens_saved"] == 1000
# 1000 / 2000 == 50.0%
assert summary["savings_pct"] == 50.0
# cache: read 1000, write 200 -> 1000 / 1200 == 83.3%
assert summary["cache_read_tokens"] == 1000
assert summary["cache_write_tokens"] == 200
assert summary["cache_hit_pct"] == 83.3
assert summary["window_hours"] == 24.0
def test_build_perf_summary_by_model_and_transform():
summary = build_perf_summary(_sample_report())
models = {m["model"]: m for m in summary["by_model"]}
assert set(models) == {"claude-sonnet-4.5", "claude-opus-4-8"}
assert models["claude-sonnet-4.5"]["tokens_saved"] == 600
assert models["claude-sonnet-4.5"]["savings_pct"] == 60.0
assert models["claude-opus-4-8"]["savings_pct"] == 40.0
assert summary["by_transform"][0]["transform"] == "content_router"
assert summary["by_transform"][0]["tokens_saved"] == 1000
assert summary["by_transform"][0]["uses"] == 1
def test_build_perf_summary_empty_report_no_zero_division():
summary = build_perf_summary(PerfReport(requested_hours=168.0))
assert summary["total_requests"] == 0
assert summary["savings_pct"] == 0.0
assert summary["cache_hit_pct"] == 0.0
assert summary["by_model"] == []
assert summary["overhead"]["optimization_ms"]["count"] == 0
def test_build_overhead_summary_attributes_slow_stages():
report = PerfReport(
perf_records=[
PerfRecord(
timestamp="2026-06-05 10:00:00,000",
request_id="fast",
model="gpt-5",
tokens_before=1000,
tokens_after=500,
tokens_saved=500,
optimization_ms=100.0,
total_ms=300.0,
stages={"cache_align": 10.0, "content_router": 90.0},
),
PerfRecord(
timestamp="2026-06-05 10:01:00,000",
request_id="slow",
model="gpt-5",
tokens_before=1000,
tokens_after=500,
tokens_saved=500,
optimization_ms=700.0,
total_ms=900.0,
stages={"kompress": 650.0, "content_router": 40.0},
),
]
)
overhead = build_overhead_summary(report, slow_threshold_ms=500.0)
assert overhead["optimization_ms"]["count"] == 2
assert overhead["optimization_ms"]["average_ms"] == 400.0
assert overhead["optimization_ms"]["p50_ms"] == 400.0
assert overhead["optimization_ms"]["p95_ms"] == 670.0
assert overhead["optimization_ms"]["p99_ms"] == 694.0
assert overhead["optimization_ms"]["slow_request_count"] == 1
assert overhead["stage_breakdown"][0]["stage"] == "kompress"
assert overhead["stage_breakdown"][0]["total_ms"] == 650.0
assert overhead["top_slow_requests"][0]["request_id"] == "slow"
assert overhead["top_slow_requests"][0]["slowest_stage"] == "kompress"
def test_perf_records_as_dicts_roundtrips_fields():
dicts = perf_records_as_dicts(_sample_report())
assert len(dicts) == 2
assert dicts[0]["request_id"] == "hr_1"
assert dicts[0]["tokens_saved"] == 600
# transforms stays a list for JSON consumers
assert dicts[0]["transforms"] == ["content_router"]
# ---------------------------------------------------------------------------
# CLI integration
# ---------------------------------------------------------------------------
def _patch_report(monkeypatch, report: PerfReport) -> None:
monkeypatch.setattr(analyzer, "parse_log_files", lambda last_n_hours=168.0: report)
def test_perf_json_format(runner, monkeypatch):
_patch_report(monkeypatch, _sample_report())
result = runner.invoke(main, ["perf", "--format", "json"])
assert result.exit_code == 0, result.output
data = json.loads(result.output)
assert data["savings_pct"] == 50.0
assert "by_model" in data
assert data["total_requests"] == 2
assert data["overhead"]["optimization_ms"]["p95_ms"] == 11.8
def test_perf_json_raw_is_array(runner, monkeypatch):
_patch_report(monkeypatch, _sample_report())
result = runner.invoke(main, ["perf", "--format", "json", "--raw"])
assert result.exit_code == 0, result.output
data = json.loads(result.output)
assert isinstance(data, list)
assert len(data) == 2
assert data[0]["request_id"] == "hr_1"
def test_perf_json_raw_preserves_client_field(runner, monkeypatch):
report = _sample_report()
report.perf_records[0].client = "codex"
_patch_report(monkeypatch, report)
result = runner.invoke(main, ["perf", "--format", "json", "--raw"])
assert result.exit_code == 0, result.output
data = json.loads(result.output)
assert data[0]["client"] == "codex"
def test_parse_perf_line_preserves_client_field(monkeypatch, tmp_path):
log_dir = tmp_path / "logs"
log_dir.mkdir()
(log_dir / "proxy.log").write_text(
"2026-06-10 10:00:00,000 - headroom.proxy - INFO - "
"[hr_codex] PERF model=gpt-5 msgs=3 tok_before=1000 "
"tok_after=90 tok_saved=910 cache_read=0 cache_write=0 "
"cache_hit_pct=0 opt_ms=12 transforms=content_router client=codex\n"
)
monkeypatch.setattr(analyzer, "LOG_DIR", log_dir)
report = analyzer.parse_log_files(last_n_hours=0)
assert len(report.perf_records) == 1
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"])
assert result.exit_code == 0, result.output
rows = list(csv.DictReader(io.StringIO(result.output)))
assert {r["model"] for r in rows} == {"claude-sonnet-4.5", "claude-opus-4-8"}
sonnet = next(r for r in rows if r["model"] == "claude-sonnet-4.5")
assert sonnet["tokens_saved"] == "600"
def test_perf_csv_raw_per_record(runner, monkeypatch):
report = _sample_report()
report.perf_records[0].client = "codex"
_patch_report(monkeypatch, report)
result = runner.invoke(main, ["perf", "--format", "csv", "--raw"])
assert result.exit_code == 0, result.output
rows = list(csv.DictReader(io.StringIO(result.output)))
assert len(rows) == 2
assert rows[0]["request_id"] == "hr_1"
assert rows[0]["client"] == "codex"
# transforms flattened to a string cell
assert rows[0]["transforms"] == "content_router"
def test_perf_text_default_unchanged(runner, monkeypatch):
_patch_report(monkeypatch, _sample_report())
result = runner.invoke(main, ["perf"])
assert result.exit_code == 0, result.output
assert "Headroom Performance Report" in result.output
assert "p50/p95/p99" in result.output
def test_perf_rejects_unknown_format(runner, monkeypatch):
_patch_report(monkeypatch, _sample_report())
result = runner.invoke(main, ["perf", "--format", "xml"])
assert result.exit_code != 0
def test_parse_perf_line_preserves_blank_client_field(
tmp_path, monkeypatch: pytest.MonkeyPatch
) -> None:
logs_dir = tmp_path / "logs"
logs_dir.mkdir()
monkeypatch.setattr(analyzer, "LOG_DIR", logs_dir)
(logs_dir / "proxy.log").write_text(
"2026-06-10 10:00:00,000 - headroom.proxy - INFO - [req-blank] PERF "
"model=gpt-5 msgs=1 tok_before=100 tok_after=50 tok_saved=50 "
"cache_read=0 cache_write=0 cache_hit_pct=0 opt_ms=1 transforms=test client=\n",
encoding="utf-8",
)
report = analyzer.parse_log_files(last_n_hours=0)
assert len(report.perf_records) == 1
assert report.perf_records[0].client == ""
def test_throughput_parsing_and_calculations(monkeypatch, tmp_path):
logs_dir = tmp_path / "logs"
logs_dir.mkdir()
monkeypatch.setattr(analyzer, "LOG_DIR", logs_dir)
log_content = (
'2026-06-10 10:00:00,000 - headroom.proxy - INFO - [req1] STAGE_TIMINGS {"event": "stage_timings", "stages": {"compression_first_stage": 100.0, "upstream_connect": 50.0}}\n'
"2026-06-10 10:00:01,000 - headroom.proxy - INFO - [req1] PERF model=gpt-5 msgs=1 tok_before=1000 tok_after=400 tok_saved=600 opt_ms=10 total_ms=500 tok_out=500 ttfb_ms=100 transforms=test client=codex\n"
'2026-06-10 10:00:02,000 - headroom.proxy - INFO - [req2] STAGE_TIMINGS {"event": "stage_timings", "stages": {"compression": 200.0, "upstream_connect": 50.0}}\n'
"2026-06-10 10:00:03,000 - headroom.proxy - INFO - [req2] PERF model=gpt-5 msgs=1 tok_before=2000 tok_after=1000 tok_saved=1000 opt_ms=20 total_ms=1000 tok_out=1000 ttfb_ms=200 transforms=test client=codex\n"
"2026-06-10 10:00:05,000 - headroom.proxy - INFO - [req3] PERF model=gpt-5 msgs=1 tok_before=1500 tok_after=500 tok_saved=1000 opt_ms=15 total_ms=600 tok_out=600 ttfb_ms=150 transforms=test client=codex\n"
'2026-06-10 10:00:06,000 - headroom.proxy - INFO - [req4] STAGE_TIMINGS {"event": "stage_timings", "stages": {"compression_first_stage": 150.0, "upstream_connect": 50.0}}\n'
"2026-06-10 10:00:07,000 - headroom.proxy - INFO - [req4] PERF model=gpt-5 msgs=1 tok_before=1200 tok_after=300 tok_saved=900 opt_ms=12 total_ms=400 tok_out=400 ttfb_ms=80 transforms=test client=codex\n"
'2026-06-10 10:00:08,000 - headroom.proxy - INFO - [req5] STAGE_TIMINGS {"event": "stage_timings", "stages": {"compression_first_stage": 50.0, "upstream_connect": 50.0}}\n'
"2026-06-10 10:00:09,000 - headroom.proxy - INFO - [req5] PERF model=gpt-5 msgs=1 tok_before=800 tok_after=200 tok_saved=600 opt_ms=5 total_ms=300 tok_out=300 ttfb_ms=50 transforms=test client=codex\n"
)
(logs_dir / "proxy.log").write_text(log_content, encoding="utf-8")
report = analyzer.parse_log_files(last_n_hours=0)
assert len(report.perf_records) == 5
assert report.perf_records[0].request_id == "req1"
assert report.perf_records[0].total_ms == 500.0
assert report.perf_records[0].tokens_out == 500
assert report.perf_records[0].ttfb_ms == 100.0
assert report.perf_records[0].stages == {
"compression_first_stage": 100.0,
"upstream_connect": 50.0,
}
assert report.perf_records[2].request_id == "req3"
assert report.perf_records[2].stages == {}
summary = build_perf_summary(report)
assert "throughput" in summary
tp = summary["throughput"]
rolling = tp["rolling"]
assert rolling["input_wall_clock"] > 0
assert rolling["input_active_p50"] == 2500.0
assert rolling["compression_p50"] == 10000.0
def test_throughput_empty_and_percentiles():
from headroom.perf.analyzer import (
PerfReport,
_calculate_throughput_stats,
_percentile,
calculate_throughput,
)
# Empty percentiles
assert _percentile([], 0.5) == 0.0
# Percentiles boundary checks
assert _percentile([10.0], 0.5) == 10.0
assert _percentile([10.0, 20.0], 0.5) == 15.0
assert _percentile([10.0, 20.0], 0.0) == 10.0
assert _percentile([10.0, 20.0], 1.0) == 20.0
assert _percentile([10.0, 20.0], 1.5) == 20.0
# Empty calculate_throughput
empty_report = PerfReport()
tp = calculate_throughput(empty_report)
assert tp["rolling"]["input_wall_clock"] == 0.0
assert tp["current"]["input_wall_clock"] == 0.0
# _calculate_throughput_stats with empty records
stats = _calculate_throughput_stats([], 10.0)
assert stats["input_wall_clock"] == 0.0
Reference in a new issue View git blame Copy permalink