mirror of
https://github.com/headroomlabs-ai/headroom.git
synced 2026-08-27 14:17:10 -04:00
## Description
Four independent latency fixes on the request hot path, found by
profiling and each measured in isolation. No behaviour changes: every
commit is either a memo of a pure function, work moved to startup, or
work that was computed and discarded.
**End to end: 287ms → 210ms (−27%) on a 68k-token mixed payload, with
byte-identical output** (68,514 → 48,725 tokens both before and after).
Plus one-off costs removed that don't show in steady-state numbers:
~4.9s of lazy imports that were firing *inside* user requests, and
~750ms of HuggingFace round-trips per process start.
Closes #
## Type of Change
- [ ] Bug fix (non-breaking change that fixes an issue)
- [ ] New feature (non-breaking change that adds functionality)
- [ ] Breaking change (fix or feature that would cause existing
functionality to change)
- [ ] Documentation update
- [x] Performance improvement
- [ ] Code refactoring (no functional changes)
## Changes Made
**1. Memoise `count_text` (`ac369277`)** — tiktoken's `CoreBPE.encode`
was 0.243s of a 0.30s profiled request. It dominates because the same
string is counted repeatedly: a 103KB payload drove 600KB of encoding,
~6x the content, across six call sites (`tokenizers/base.py:196`,
`content_router.py:4704` and `:5474`, `parser.py:185/192/298`). 35% of
encode calls and 22% of encoded characters were an exact repeat *within
one request*.
`count_text` is a pure function of its text, so replaying a stored count
returns the same integer. That is the whole safety argument, and it is
what makes this safe at the sites whose count feeds a routing decision
(`context_pressure` → `min_ratio`) rather than a log line — an
*estimate* there would change which blocks compress; a memo cannot.
Keyed on the text itself, not a hash: a collision would hand back a
wrong count for real content and silently change compression. The cost
is holding the strings, so entries and total characters are both capped.
Clear-on-full rather than LRU eviction — the pipeline runs on a thread
pool, `dict` get/set/clear are atomic under the GIL but
`OrderedDict.move_to_end` is not.
**2. Preload what was importing mid-request (`2921a15b`)** — `litellm`
(2.9–3.8s) was imported lazily *on the event loop* during the first
request: `emit_request_outcome` → `record_request` →
`_estimate_compression_savings_usd` calls the loader before its own
`tokens_saved <= 0` early return, so even a request that saved nothing
paid it. `trafilatura` (978ms, pulling `htmldate` → `dateparser` and its
timezone tables) is the most expensive lazy import in the transform tree
— every other compressor module is 1–20ms — and fires on the first
request carrying an HTML-ish or mixed-content block. The TOIN singleton
reads ~5MB of learned patterns on construction (~150ms); a stale comment
claimed the SmartCrusher preload covered it, and it does not.
All three now load in `_eager_preload_transforms`, which already runs
under `asyncio.to_thread` and so cannot delay the port bind.
Same commit, two Kompress cold-path fixes: `_load_modernbert_tokenizer`
always used `local_files_only=False`, which makes transformers
re-validate against the Hub on every load — a tree listing plus a HEAD
per file — even when fully cached (~900ms warm-cache vs ~150ms
local-only). And `ensure_background_download` re-spawned a
finished-or-failed thread on the next call, so an unreachable Hub meant
one fresh download thread *per request* for the life of the process,
each importing transformers and holding the GIL against the event loop.
Consecutive failures now back off; success clears it, so the happy path
and the transient-failure path are unchanged.
**3. Memoise the JSON-block scan (`039c9735`)** —
`_has_valid_json_block_with_text` tries every `{`/`[`-leading line as a
possible block start. When a candidate never balances,
`_extract_json_block` scans character-by-character to the end of the
content and returns nothing — then the next candidate does it again.
Quadratic, on the request path, growing exactly 4x per doubling.
**4. `CostTracker.totals()` (`286b97e4`)** —
`_current_savings_tracker_totals` called `stats()` once per request and
read two of its fields. Building the rest includes
`period_cost_breakdown()`, which walks up to 100k cost records over 31
days, on the event loop, holding the metrics lock. It degrades with
proxy **uptime**, not load, which is why no short benchmark would
surface it.
## 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
### Test Output
```text
$ ruff check headroom/ tests/ --exclude headroom/dashboard/templates
All checks passed!
$ mypy --python-version 3.12 headroom/
Found 1 error in 1 file (checked 515 source files)
headroom/release_version.py:235: error: Name "tomllib" already defined (by an import)
# pre-existing on main, in a file this PR does not touch — verified by
# running the same command on a clean main checkout.
$ python -m pytest tests/test_token_count_cache.py tests/test_mixed_content_scan_cache.py \
tests/test_kompress_download_backoff.py tests/test_cost_tracker_totals.py -q
306 passed
$ python -m pytest tests/ -q -k "token or tokenizer or count or estimator or provider"
1303 passed, 105 skipped in 423.42s
$ python -m pytest tests/ -q -k "cost or budget or metrics or savings or stats"
683 passed, 127 skipped, 1 failed
# tests/test_proxy_memory_integration.py::TestMemoryStats::test_health_endpoint_works_with_memory
# Order-dependent and pre-existing: it SKIPS in isolation, and fails identically
# on a clean main checkout under the same -k selection (681 passed, 1 failed).
```
## Real Behavior Proof
- **Environment:** macOS, Python 3.12.6, local CPU, remote Kompress
disabled. Profiled with `cProfile` on `anthropic_pipeline.apply`.
- **Exact command / steps:** a 68k-token payload of four `tool_result`
blocks (900-item pretty JSON, 60KB of Python source, 500 lines of
JS-style object logs, 500 plain log lines), six reps, **content unique
per rep so every run is router-cache-cold**, run on this branch and on
main in alternation.
- **Observed result:**
| | median | min | tokens |
|---|---|---|---|
| main | 287ms | 286ms | 68,514 → 48,725 |
| this branch | 210ms | 208ms | 68,514 → 48,725 |
Per-change, measured in isolation:
| change | before | after |
|---|---|---|
| `count_text` memo | — | −25% pipeline wall; 44% of counted chars from
cache on new content, 100% when history repeats |
| litellm / trafilatura / TOIN | 3829 / 978 / 150ms mid-request | at
startup, off the event loop |
| Kompress tokenizer | ~900ms | ~150ms |
| JS-style object logs (1200 lines) | 4643ms | 183ms |
| truncated JSONL (1200 lines) | 3737ms | 116ms |
| `cost_tracker` per request | 2.8ms @20k records, 13.6ms @100k | loop
over models, not records |
Output equality: 18/18 payloads byte-identical on `tokens_before`,
`tokens_after` and a sha256 of the resulting messages, with the memo
forced on vs off.
- **Not tested:** Windows and Linux (the ORT dylib and CPU-arena paths
differ); multi-worker deployments; a proxy with a genuinely large live
cost ledger (the 100k figure is from a synthetic ledger); real
HTML-heavy traffic through the preloaded trafilatura path.
## 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
- [x] I have performed a self-review of my code
- [x] I have commented my code, particularly in hard-to-understand areas
- [ ] I have made corresponding changes to the documentation
- [x] My changes generate no new warnings
- [x] I have added tests that prove my fix is effective or that my
feature works
- [x] New and existing unit tests pass locally with my changes
- [x] I did **not** edit `CHANGELOG.md`
## Additional Notes
**Docs:** N/A — no user-facing surface changes. The reasoning lives in
the code, at the sites where someone debugging would look.
**A regression I introduced and caught.** The scan memo initially made
pretty-printed JSON ~2x **slower**: content that balances on the first
scan has nothing to reuse and just pays the per-line dict traffic. The
cache is now built only *after* a scan has run to the end without
balancing, which is the actual signal that later candidates will re-walk
the same tail. Every shape now improves and none regress:
```
before after
js object logs 4642.9ms 182.7ms 25x
JSONL truncated 3736.8ms 115.9ms 32x
pretty JSON 5.6ms 3.5ms
JSONL valid 5.6ms 3.2ms
plain logs 1.0ms 0.6ms
python source 1.0ms 0.5ms
markdown prose 0.9ms 0.5ms
```
Worth stating plainly: had I only benchmarked the shape I was fixing,
I'd have shipped a win on rare content and a loss on the common case.
**The scan fix is constant-factor, not asymptotic.** The walk over
remaining lines is still O(candidates × lines), so 3200 lines of the
pathological shape is still ~1.4s. The tests assert scan-call counts
rather than implying linearity. True linearity needs a prefix-sum
rewrite with a string-state fallback; that seemed like the wrong risk
for this PR.
**How the parser change is proven safe.** `_extract_json_block` is a
parser, so golden values would only encode whatever the new code does.
Instead the pre-memo implementation is kept verbatim in the test file as
an oracle, and every candidate index of a 139-document corpus — escapes,
unterminated strings, delimiters inside strings, code fences, truncated
JSON, randomised mixtures — is asserted equal, with a cold cache, with
the shared cache the real callers use, and replayed.
**Measurement trap, for anyone re-running these numbers.** Give each arm
its own content. Reusing one payload across arms lets the second arm hit
the router's result cache, which reads as a speedup having nothing to do
with the change under test. I hit this twice while working on it: it
manufactured a fake "INFO logging costs 21.8%" finding (real answer:
0.3%) and it *understated* the memo win.
**Deliberately not in this PR:**
- **ONNX thread tuning** — measured zero gain, and
`intra_op_num_threads` is not bitwise-safe (1.6e-05 score drift from
float reduction order), so it would trade an output risk for nothing.
- **`str(content)` on block lists** counts a base64 image at 210,775
tokens instead of 1,604 (131x), pinning `context_pressure` to 1.0 and
forcing the most aggressive `min_ratio` on any conversation containing
an image. Real bug, but fixing it changes compression output — needs its
own reviewed behaviour-change PR.
- **`chunk_words=350` against the tokenizer's 512-token limit** silently
drops roughly a third of every full chunk (measured: 240/240 words kept
in the first 240, 15/110 in the tail). That is data loss rather than
latency, it changes every output, and correcting it costs ~1.3x latency.
Filing separately.
- **Telemetry off the request thread** — the TOIN auto-save is a 236ms
inline stall every 600s and the waste-signal re-parse is ~50ms/request
that is invisible in `pipeline_total` (computed before it). Both want
deferral rather than removal, which is a larger change than belongs
here.
157 lines
5.5 KiB
Python
157 lines
5.5 KiB
Python
"""Startup must bind its port even when eager preload hangs (#790).
|
|
|
|
``HeadroomProxy.startup()`` runs inside the ASGI lifespan, which completes
|
|
*before* uvicorn binds the socket. The eager compressor/parser preload used to
|
|
run synchronously there, so a hang or an uncatchable native stall during a model
|
|
load (observed on Windows) left the proxy "never opening its port". The preload
|
|
now runs off the event loop under ``asyncio.wait_for`` with
|
|
``EAGER_PRELOAD_TIMEOUT_SECONDS``; on timeout startup logs and continues so the
|
|
bind still happens and transforms fall back to lazy loading.
|
|
"""
|
|
|
|
from __future__ import annotations
|
|
|
|
import logging
|
|
import threading
|
|
import time
|
|
|
|
import pytest
|
|
|
|
pytest.importorskip("fastapi")
|
|
|
|
import headroom.proxy.server as server_mod
|
|
from headroom.proxy.server import ProxyConfig, create_app
|
|
|
|
|
|
def _make_proxy(*, optimize: bool):
|
|
config = ProxyConfig(
|
|
optimize=optimize,
|
|
cache_enabled=False,
|
|
rate_limit_enabled=False,
|
|
cost_tracking_enabled=False,
|
|
log_requests=False,
|
|
ccr_inject_tool=False,
|
|
ccr_handle_responses=False,
|
|
ccr_context_tracking=False,
|
|
image_optimize=False,
|
|
subscription_tracking_enabled=False,
|
|
)
|
|
proxy = create_app(config).state.proxy
|
|
# Every test here substitutes fake pipelines to control exactly what the
|
|
# preload walks. The proxy also eagerly builds the default /v1/compress
|
|
# pipeline (a derived ContentRouter, warmed alongside the request
|
|
# pipelines), which would inject real transform statuses into those
|
|
# assertions — drop it so the fakes remain the only input.
|
|
proxy._compress_pipeline_cache = {}
|
|
return proxy
|
|
|
|
|
|
class _FastTransform:
|
|
def __init__(self, status):
|
|
self._status = status
|
|
|
|
def eager_load_compressors(self):
|
|
return self._status
|
|
|
|
|
|
class _RaisingTransform:
|
|
def eager_load_compressors(self):
|
|
raise RuntimeError("boom")
|
|
|
|
|
|
class _NonDictTransform:
|
|
def eager_load_compressors(self):
|
|
return "not-a-dict"
|
|
|
|
|
|
class _HangingTransform:
|
|
"""Simulates a model load that hangs forever (released via the event)."""
|
|
|
|
def __init__(self, release: threading.Event):
|
|
self._release = release
|
|
|
|
def eager_load_compressors(self):
|
|
# Safety cap so a misbehaving test can never wedge the suite.
|
|
self._release.wait(timeout=30)
|
|
return {"hang": "done"}
|
|
|
|
|
|
class _FakePipeline:
|
|
def __init__(self, transforms):
|
|
self.transforms = transforms
|
|
|
|
|
|
def test_eager_preload_dedupes_and_swallows_failures():
|
|
proxy = _make_proxy(optimize=False)
|
|
shared = _FastTransform({"shared": "enabled"})
|
|
proxy.anthropic_pipeline = _FakePipeline([shared, _FastTransform({"kompress": "enabled"})])
|
|
# ``shared`` appears in both pipelines and must load exactly once; the
|
|
# raising and non-dict transforms must be skipped without aborting.
|
|
proxy.openai_pipeline = _FakePipeline([shared, _RaisingTransform(), _NonDictTransform()])
|
|
|
|
eager_status, statuses = proxy._eager_preload_transforms()
|
|
|
|
# Keys the preload contributes itself rather than collecting from a
|
|
# transform, so this assertion stays about dedupe/swallowing.
|
|
non_transform_keys = {"litellm"}
|
|
assert {k: v for k, v in eager_status.items() if k not in non_transform_keys} == {
|
|
"shared": "enabled",
|
|
"kompress": "enabled",
|
|
}
|
|
assert statuses == [{"shared": "enabled"}, {"kompress": "enabled"}]
|
|
assert eager_status["litellm"] in {"ready", "not installed", "skipped"}
|
|
|
|
|
|
async def test_startup_binds_despite_hung_preload(monkeypatch):
|
|
monkeypatch.setattr(server_mod, "EAGER_PRELOAD_TIMEOUT_SECONDS", 0.3)
|
|
proxy = _make_proxy(optimize=True)
|
|
release = threading.Event()
|
|
proxy.anthropic_pipeline = _FakePipeline([_HangingTransform(release)])
|
|
proxy.openai_pipeline = _FakePipeline([])
|
|
|
|
try:
|
|
start = time.monotonic()
|
|
await proxy.startup() # must NOT wait on the hung load
|
|
elapsed = time.monotonic() - start
|
|
# Returns shortly after the 0.3s preload timeout, far below the 30s hang.
|
|
assert elapsed < 10
|
|
finally:
|
|
release.set()
|
|
await proxy.shutdown()
|
|
|
|
|
|
async def test_startup_merges_warmup_for_normal_transforms(monkeypatch):
|
|
proxy = _make_proxy(optimize=True)
|
|
captured: list[dict] = []
|
|
monkeypatch.setattr(proxy.warmup, "merge_transform_status", captured.append)
|
|
proxy.anthropic_pipeline = _FakePipeline([_FastTransform({"kompress": "enabled"})])
|
|
proxy.openai_pipeline = _FakePipeline([])
|
|
|
|
try:
|
|
await proxy.startup()
|
|
assert {"kompress": "enabled"} in captured
|
|
assert proxy._kompress_status == "enabled"
|
|
finally:
|
|
await proxy.shutdown()
|
|
|
|
|
|
async def test_startup_reports_deferred_kompress(caplog):
|
|
proxy = _make_proxy(optimize=True)
|
|
proxy.anthropic_pipeline = _FakePipeline([_FastTransform({"kompress": "deferred"})])
|
|
proxy.openai_pipeline = _FakePipeline([])
|
|
|
|
try:
|
|
# Proxy setup disables propagation on the ``headroom`` logger, so
|
|
# attach caplog's handler directly to the logger that emits this line.
|
|
server_mod.logger.addHandler(caplog.handler)
|
|
try:
|
|
with caplog.at_level(logging.INFO, logger=server_mod.logger.name):
|
|
await proxy.startup()
|
|
finally:
|
|
server_mod.logger.removeHandler(caplog.handler)
|
|
|
|
assert proxy._kompress_status == "deferred"
|
|
assert "Kompress: DEFERRED (model loads on first request)" in caplog.messages
|
|
assert not any("Kompress: not installed" in message for message in caplog.messages)
|
|
finally:
|
|
await proxy.shutdown()
|