headroom/tests/test_token_count_cache.py

Ignoring revisions in .git-blame-ignore-revs. Click here to bypass and see the normal blame view.

109 lines
4.1 KiB
Python
Raw Permalink Normal View History

perf: cut hot-path latency 27% (token-count memo, startup preloads, JSON scan memo) (#2838) ## 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.
2026-08-06 17:47:40 -07:00
"""The token-count memo must be invisible: same integers, or it is a bug.
These counts feed context_pressure -> min_ratio -> which blocks get compressed,
so "the cache returned a different number" is a compression regression, not a
cache miss. Every test here is an equality test for that reason.
"""
from __future__ import annotations
import json
import pytest
from headroom.providers.anthropic import AnthropicProvider
from headroom.tokenizers.base import TokenCountCache
from headroom.tokenizers.estimator import EstimatingTokenCounter
from headroom.tokenizers.tiktoken_counter import TiktokenCounter
BODIES = [
"word " * 500,
json.dumps([{"id": i, "name": f"item-{i}", "ok": i % 2 == 0} for i in range(300)]),
"def f(x):\n return x + 1\n" * 200,
"2026-08-06 13:00:00 INFO worker did a thing\n" * 400,
"日本語のテキストをここに置きます。" * 200,
"<|endoftext|> literal special token marker " * 100, # forces the ValueError path
"x" * 300,
]
def _counters():
return [
("anthropic", AnthropicProvider().get_token_counter("claude-sonnet-5")),
("tiktoken", TiktokenCounter(model="gpt-4o")),
("estimator-auto", EstimatingTokenCounter()),
("estimator-fixed", EstimatingTokenCounter(chars_per_token=3.5)),
]
@pytest.mark.filterwarnings("ignore::UserWarning")
@pytest.mark.parametrize("body", BODIES)
def test_cached_count_equals_uncached(body: str) -> None:
for name, counter in _counters():
counter._count_cache.clear()
first = counter.count_text(body) # miss, populates
second = counter.count_text(body) # hit
counter._count_cache.clear()
third = counter.count_text(body) # miss again
assert first == second == third, f"{name}: {first} != {second} != {third}"
@pytest.mark.filterwarnings("ignore::UserWarning")
def test_empty_and_tiny_text_still_correct() -> None:
for _name, counter in _counters():
assert counter.count_text("") == 0
assert counter.count_text("hi") == counter.count_text("hi")
def test_cache_clears_when_full_rather_than_growing() -> None:
cache = TokenCountCache(min_chars=1, max_entries=4, max_chars=10**9)
for i in range(10):
cache.put(f"text-number-{i}", i)
assert len(cache._counts) <= 4
def test_cache_respects_the_character_budget() -> None:
cache = TokenCountCache(min_chars=1, max_entries=10**6, max_chars=1000)
for i in range(50):
cache.put("x" * 100 + str(i), i)
assert cache._chars <= 1000 + 200 # one entry may straddle the cap
def test_small_strings_are_not_cached() -> None:
"""They encode in microseconds; caching them would evict the entries that matter."""
cache = TokenCountCache(min_chars=256)
cache.put("short", 1)
assert cache.get("short") is None
def test_distinct_texts_do_not_collide() -> None:
cache = TokenCountCache(min_chars=1)
cache.put("alpha", 1)
cache.put("beta", 2)
assert (cache.get("alpha"), cache.get("beta"), cache.get("gamma")) == (1, 2, None)
@pytest.mark.filterwarnings("ignore::UserWarning")
def test_counters_do_not_share_a_cache_across_encodings() -> None:
"""cl100k and o200k are both live in one process; a shared memo would mix them."""
a = TiktokenCounter(encoding="cl100k_base")
b = TiktokenCounter(encoding="o200k_base")
body = "tokenization differs between these two encodings. " * 100
assert a.count_text(body) == a.count_text(body)
assert b.count_text(body) == b.count_text(body)
assert a._count_cache is not b._count_cache
@pytest.mark.filterwarnings("ignore::UserWarning")
def test_concurrent_counting_is_consistent() -> None:
"""The pipeline runs on a thread pool and shares one counter."""
from concurrent.futures import ThreadPoolExecutor
counter = AnthropicProvider().get_token_counter("claude-sonnet-5")
bodies = [f"{b}\n{i}" for i, b in enumerate(BODIES * 3)]
expected = {b: counter.count_text(b) for b in bodies}
counter._count_cache.clear()
with ThreadPoolExecutor(max_workers=8) as pool:
got = list(pool.map(counter.count_text, bodies))
assert got == [expected[b] for b in bodies]