headroom/tests/test_proxy_compression_executor.py

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

260 lines
9.2 KiB
Python
Raw Permalink Normal View History

fix(proxy): cache concurrency lock, multi-worker docs, bounded compression executor Three audit follow-ups from issue #327's deep-dive review. C1 — CompressionCache concurrency lock ====================================== `CompressionCache` instances are shared per `session_id` and accessed from async-dispatched threadpool workers. Pre-fix, concurrent requests for the same session raced on `_cache`, `_stable_hashes`, `_first_seen`, and `_total_tokens_saved` with no synchronization. Observable failures: * Lost-update on `_total_tokens_saved` (read-modify-write). * `RuntimeError: OrderedDict mutated during iteration` from `apply_cached` when a concurrent `store_compressed` evicts during the walk. * Lost stable-hash records — next-turn compute_frozen_count reads inconsistent state. May also explain part of SvenMeyer's `_cache: 0 entries / 1003 misses` observation: the cache was being clobbered concurrently. Added `threading.RLock` guarding all mutating methods. `RLock` (not `Lock`) so future code can call locked methods from inside another locked method without self-deadlock. Also locked `HeadroomProxy._compression_caches` dict-of-caches access via a separate `_compression_caches_lock` so two concurrent calls for the same session_id can't each create distinct CompressionCache objects (which would split the cache state between them). The `/stats` endpoint snapshots the cache list under the dict lock before iterating to avoid eviction-during-iteration. C2 — Multi-worker CCR fragmentation: documented + startup warning ================================================================= The in-memory `InMemoryCcrStore` (Rust), `_compression_caches` (Python), `session_tracker_store` (Python), and TOIN learner state are ALL per-process. Multi-worker uvicorn round-robins requests across workers, so a session whose turn-1 lands on worker A may have turn-2 land on worker B. Worker B has zero knowledge of A's CCR markers, replay cache, or prefix-cache state. Result: `Retrieve original: hash=X` markers stay in-context as opaque directives, every fresh tool_result is recompressed from scratch, and `frozen_message_count=0` causes Anthropic prefix-cache busts on every cross-worker turn. Added a "Multi-worker deployment — CCR fragmentation" section in `RUST_DEV.md` documenting the failure modes, the supported configuration (`--workers 1`), and the sticky-session workaround for horizontal scale. The proxy emits a `WARNING`-level log line on startup if `workers > 1` is detected, pointing at the doc section. C3 — Bounded compression executor with cancel-aware metrics =========================================================== `asyncio.wait_for(asyncio.to_thread(pipeline.apply), timeout=...)` cancellation does NOT propagate into the threadpool worker that's running Rust code. Once the worker has picked up the task, `concurrent.futures.Future.cancel()` returns False and the thread runs to completion. Stuck threads accumulated invisibly on asyncio's default executor, contending with unrelated `to_thread` callers (file IO, etc.). Replaced all 7 `asyncio.to_thread` call sites for `pipeline.apply()` across `proxy/handlers/anthropic.py` (3) and `proxy/handlers/openai.py` (4) with a new `HeadroomProxy._run_compression_in_executor(fn, *, timeout)` helper that: 1. Submits to a dedicated bounded `ThreadPoolExecutor` named `headroom-compress` (configurable via `ProxyConfig.compression_max_workers`; defaults to `min(32, (cpu_count or 1) * 4)`). 2. Increments `_compression_in_flight` (gauge) when work starts and decrements when work completes; tracks `_compression_in_flight_max` as a high-water mark. 3. Detects "leaked threads" by comparing wall-clock elapsed against the timeout in the worker's `finally` block. Increments `_compression_leaked_threads` when a worker finishes after its asyncio future was cancelled. Operators can see the leaked-thread rate climbing in `/stats runtime.compression_executor` BEFORE the pool fills up. Tests ===== * `TestCompressionCacheConcurrency` (3 tests) — many threads store_compressed / apply_cached / update_from_result on a single CompressionCache; assert no exceptions, no lost updates, no partial state. * `test_get_compression_cache_returns_same_instance_under_contention` — 32 concurrent `_get_compression_cache(same_id)` calls return the identical instance (would split pre-lock). * `test_proxy_compression_executor.py` (8 tests) — pool size respects config, in-flight gauge tracks running compressions, high-water mark is monotonic, timeout propagates to awaiter, leaked-thread counter increments on post-deadline completion, `/stats` surfaces all three gauges. Verification ============ * All 123 targeted regression tests pass. * `make ci-precheck` clean. * No `Co-Authored-By` trailer; conventional `fix:` prefix; no `--no-verify`.
2026-05-01 15:25:18 -07:00
"""Audit follow-up C3: bounded compression executor + cancel-aware metrics.
Replaces ``asyncio.to_thread`` for ``pipeline.apply()`` calls with a dedicated
``ThreadPoolExecutor`` that's bounded by ``ProxyConfig.compression_max_workers``.
Locks the following invariants:
1. The pool exists and respects ``compression_max_workers`` (auto and explicit).
2. ``compression_in_flight`` increments while a compression is running and
decrements after it completes under load, the high-water mark moves up
as expected.
3. When a compression call exceeds its timeout, the awaiter unblocks with
``TimeoutError`` but the worker thread keeps running (Python cannot
preempt running CPython bytecode or in-flight Rust calls), and when the
work eventually completes, ``compression_leaked_threads`` increments.
4. ``/stats runtime.compression_executor`` surfaces the gauge + counter so
operators can see leaked-thread rate.
These tests also serve as documentation: anyone reading them sees that
"timeout fired" does not mean "compression was cancelled" it means "we
stopped waiting; the worker is still going". A bounded pool plus the
leaked-thread counter is how we make that visible.
"""
from __future__ import annotations
import asyncio
import threading
import time
import pytest
pytest.importorskip("fastapi")
from headroom.proxy.helpers import COMPRESSION_TIMEOUT_SECONDS # noqa: F401
from headroom.proxy.server import ProxyConfig, create_app
def _make_proxy(compression_max_workers: int | None = None):
"""Construct a HeadroomProxy with a no-op pipeline. Returns the proxy."""
config = ProxyConfig(
optimize=False,
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,
compression_max_workers=compression_max_workers,
)
app = create_app(config)
return app.state.proxy
def test_compression_executor_default_size_matches_asyncio_default() -> None:
"""When ``compression_max_workers`` is None, the resolved size should
match asyncio's default executor sizing (``min(32, (cpu+1)*4)`` style).
"""
import os
proxy = _make_proxy(compression_max_workers=None)
expected = min(32, (os.cpu_count() or 1) * 4)
assert proxy.compression_max_workers == expected
assert proxy._compression_executor._max_workers == expected
def test_compression_executor_explicit_override() -> None:
"""``ProxyConfig.compression_max_workers=N`` is honored verbatim."""
proxy = _make_proxy(compression_max_workers=3)
assert proxy.compression_max_workers == 3
assert proxy._compression_executor._max_workers == 3
def test_compression_executor_minimum_one_worker() -> None:
"""A non-positive override clamps to 1 (zero workers would deadlock)."""
proxy = _make_proxy(compression_max_workers=0)
assert proxy.compression_max_workers == 1
def test_in_flight_gauge_tracks_running_compressions() -> None:
"""While a compression is running, ``_compression_in_flight`` reads ≥ 1.
After it completes, it returns to 0. The high-water mark records the
peak observed.
"""
proxy = _make_proxy(compression_max_workers=4)
enter_event = threading.Event()
release_event = threading.Event()
observed: dict[str, int] = {}
def _slow_compression():
enter_event.set()
# Block until the test thread reads in_flight from the gauge.
release_event.wait(timeout=5.0)
return "done"
async def _drive():
task = asyncio.create_task(
proxy._run_compression_in_executor(_slow_compression, timeout=10.0)
)
# Wait for the worker to actually start.
for _ in range(50):
if enter_event.is_set():
break
await asyncio.sleep(0.01)
with proxy._compression_metrics_lock:
observed["mid_flight"] = proxy._compression_in_flight
observed["mid_flight_max"] = proxy._compression_in_flight_max
release_event.set()
result = await task
return result
result = asyncio.run(_drive())
assert result == "done"
assert observed["mid_flight"] == 1, (
f"in_flight should be 1 mid-call, got {observed['mid_flight']}"
)
assert observed["mid_flight_max"] >= 1
# Decremented after task completes.
with proxy._compression_metrics_lock:
assert proxy._compression_in_flight == 0
def test_high_water_mark_persists_after_completion() -> None:
"""``_compression_in_flight_max`` is monotonic — never decreases."""
proxy = _make_proxy(compression_max_workers=8)
enter_events = [threading.Event() for _ in range(3)]
release_events = [threading.Event() for _ in range(3)]
def _make_slow(idx: int):
def _slow():
enter_events[idx].set()
release_events[idx].wait(timeout=5.0)
return idx
return _slow
async def _drive():
tasks = [
asyncio.create_task(proxy._run_compression_in_executor(_make_slow(i), timeout=10.0))
for i in range(3)
]
# Wait for all 3 to enter.
for ev in enter_events:
for _ in range(50):
if ev.is_set():
break
await asyncio.sleep(0.01)
peak = proxy._compression_in_flight
for ev in release_events:
ev.set()
for t in tasks:
await t
return peak
peak = asyncio.run(_drive())
assert peak == 3, f"Should have observed 3 concurrent compressions, got {peak}"
# After all complete, in_flight is back to 0 but max remains 3.
with proxy._compression_metrics_lock:
assert proxy._compression_in_flight == 0
assert proxy._compression_in_flight_max >= 3
def test_timeout_fires_and_leaked_thread_is_counted() -> None:
"""When the compression exceeds ``timeout``, the awaiter sees
``TimeoutError`` immediately. The worker keeps running; when it finishes,
``_compression_leaked_threads`` increments by 1.
"""
proxy = _make_proxy(compression_max_workers=2)
finished_event = threading.Event()
timeout_seconds = 0.10
def _slow_compression():
# Sleep well past the timeout so the asyncio side cancels first.
time.sleep(timeout_seconds * 5)
finished_event.set()
return "completed-after-deadline"
async def _drive():
with pytest.raises(asyncio.TimeoutError):
await proxy._run_compression_in_executor(_slow_compression, timeout=timeout_seconds)
asyncio.run(_drive())
# Wait for the worker to actually finish (it ran past the deadline).
finished_event.wait(timeout=2.0)
# Give the worker thread a moment to update the counter under the lock.
deadline = time.monotonic() + 1.0
while time.monotonic() < deadline:
with proxy._compression_metrics_lock:
if proxy._compression_leaked_threads >= 1:
break
time.sleep(0.01)
with proxy._compression_metrics_lock:
assert proxy._compression_leaked_threads >= 1, (
f"leaked_threads should be ≥ 1; got {proxy._compression_leaked_threads}. "
f"The worker either didn't finish past the deadline, or the wrapper "
f"didn't increment the counter."
)
# In-flight gauge restored.
assert proxy._compression_in_flight == 0
def test_compression_executor_metrics_appear_in_runtime_payload() -> None:
"""``/stats runtime.compression_executor`` surfaces the new gauges."""
from fastapi.testclient import TestClient
config = ProxyConfig(
optimize=False,
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,
compression_max_workers=5,
)
app = create_app(config)
with TestClient(app) as client:
# The compression_executor metrics are published from the runtime
# payload (also surfaced in /health). Hit /health and look there.
r = client.get("/health")
assert r.status_code == 200
runtime = r.json()["runtime"]
assert "compression_executor" in runtime
ce = runtime["compression_executor"]
assert ce["max_workers"] == 5
assert ce["in_flight"] == 0
assert ce["leaked_threads_total"] == 0
assert ce["source"] == "explicit"
def test_explicit_None_resolves_to_auto_source() -> None:
"""When max_workers is None (default), the runtime payload reports
``source: auto``."""
from fastapi.testclient import TestClient
config = ProxyConfig(
optimize=False,
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,
)
app = create_app(config)
with TestClient(app) as client:
r = client.get("/health")
assert r.json()["runtime"]["compression_executor"]["source"] == "auto"