diff --git a/nisse-dev/src/nisse_dev/bench/results.py b/nisse-dev/src/nisse_dev/bench/results.py index 0e3fb43..3138217 100644 --- a/nisse-dev/src/nisse_dev/bench/results.py +++ b/nisse-dev/src/nisse_dev/bench/results.py @@ -60,9 +60,10 @@ class Row: runs: int successes: int median_turns: float - mean_wall_s: float + mean_wall_s: float # working time: rate-limit waits are left out cost_per_run: float stale: bool + rate_limited: int = 0 # runs that waited out the proxy's rate limit @property def interval(self) -> tuple[float, float]: @@ -86,9 +87,12 @@ def summarise( runs=len(runs), successes=sum(1 for r in runs if r["success"]), median_turns=statistics.median(r["turns"] for r in runs), - mean_wall_s=statistics.fmean(r["wall_s"] for r in runs), + mean_wall_s=statistics.fmean( + r["wall_s"] - r.get("rate_limit_wait_s", 0.0) for r in runs + ), cost_per_run=statistics.fmean(r["cost"] for r in runs), stale=current_hashes.get(task) != task_hash, + rate_limited=sum(1 for r in runs if r.get("rate_limit_wait_s")), ) ) return rows @@ -97,7 +101,7 @@ def summarise( def render(rows: list[Row]) -> str: header = ( f"{'model':<34} {'note':<22} {'task':<15} {'success':>8} {'95% CI':>11} " - f"{'turns':>6} {'time':>7} {'$/run':>8}" + f"{'turns':>6} {'time':>7} {'$/run':>8} {'429':>4}" ) lines = [header, "-" * len(header)] for row in rows: @@ -106,7 +110,14 @@ def render(rows: list[Row]) -> str: lines.append( f"{row.model[:34]:<34} {row.note[:22]:<22} {task[:15]:<15} " f"{row.successes:>3}/{row.runs:<4} {low:>4.0%}-{high:<5.0%} " - f"{row.median_turns:>6.0f} {row.mean_wall_s:>6.0f}s {row.cost_per_run:>8.4f}" + f"{row.median_turns:>6.0f} {row.mean_wall_s:>6.0f}s {row.cost_per_run:>8.4f} " + f"{row.rate_limited or '':>4}" + ) + if any(row.rate_limited for row in rows): + lines.append("") + lines.append( + "429 = runs that waited out the proxy's rate limit; time leaves the " + "waits out." ) if any(row.stale for row in rows): lines.append("") diff --git a/nisse-dev/src/nisse_dev/bench/runner.py b/nisse-dev/src/nisse_dev/bench/runner.py index ba4d02a..0ae3c13 100644 --- a/nisse-dev/src/nisse_dev/bench/runner.py +++ b/nisse-dev/src/nisse_dev/bench/runner.py @@ -40,6 +40,7 @@ class MeteringClient: self.tokens_out = 0 self.cost = 0.0 self.fallbacks: list[str] = [] + self.rate_limit_wait_s = 0.0 def complete( self, @@ -49,7 +50,14 @@ class MeteringClient: system: str | None = None, ) -> list[CanonicalEvent]: self.calls += 1 - produced = self._inner.complete(events, tools, model, system=system) + try: + produced = self._inner.complete(events, tools, model, system=system) + finally: + # Counted even when the call fails: a rate limit that never + # cleared still cost the run its wait. + self.rate_limit_wait_s += float( + getattr(self._inner, "last_rate_limit_wait_s", 0.0) or 0.0 + ) usage = getattr(self._inner, "last_usage", {}) or {} self.tokens_in += int(usage.get("input", 0)) self.tokens_out += int(usage.get("output", 0)) @@ -90,6 +98,8 @@ class RunRecord: cost: float wall_s: float fallbacks: list[str] = field(default_factory=list) + # Part of wall_s spent waiting out the proxy's rate limit, not working. + rate_limit_wait_s: float = 0.0 check_output: str = "" def to_json(self) -> dict[str, Any]: @@ -214,5 +224,6 @@ def run_task( cost=round(meter.cost, 6), wall_s=round(wall, 1), fallbacks=meter.fallbacks, + rate_limit_wait_s=meter.rate_limit_wait_s, check_output=check_output, ) diff --git a/nisse-dev/src/nisse_dev/context.py b/nisse-dev/src/nisse_dev/context.py index d77eb61..c0f4a07 100644 --- a/nisse-dev/src/nisse_dev/context.py +++ b/nisse-dev/src/nisse_dev/context.py @@ -244,6 +244,10 @@ class BudgetedClient: def last_cost(self) -> float: return float(getattr(self._inner, "last_cost", 0.0) or 0.0) + @property + def last_rate_limit_wait_s(self) -> float: + return float(getattr(self._inner, "last_rate_limit_wait_s", 0.0) or 0.0) + def budget_for(self, model: str) -> Budget: window, model_max_output = self._limits_for(model) ceiling = self._max_output_tokens diff --git a/nisse-dev/src/nisse_dev/llm.py b/nisse-dev/src/nisse_dev/llm.py index 1579a60..afbc1f1 100644 --- a/nisse-dev/src/nisse_dev/llm.py +++ b/nisse-dev/src/nisse_dev/llm.py @@ -144,6 +144,9 @@ class LiteLLMClient: self.last_usage: dict[str, int] = {} self.last_model: str | None = None self.last_cost: float = 0.0 + # Set even when the call then fails: time spent waiting out a rate + # limit is the proxy's, not the model's (the benchmark subtracts it). + self.last_rate_limit_wait_s: float = 0.0 def complete( self, @@ -164,7 +167,8 @@ class LiteLLMClient: # nothing to check against. A caller that knows the model's limits # (the context budget) passes a tighter one. body["max_tokens"] = max_tokens or self._max_tokens - response = _post_with_rate_limit_retry( + self.last_rate_limit_wait_s = 0.0 # not the last call's, if this one raises + response, self.last_rate_limit_wait_s = _post_with_rate_limit_retry( self._http, "/chat/completions", body, self._sleep ) if response.status_code != 200: @@ -267,6 +271,9 @@ class AnthropicPassthroughClient: self.last_usage: dict[str, int] = {} self.last_model: str | None = None self.last_cost: float = 0.0 + # Set even when the call then fails: time spent waiting out a rate + # limit is the proxy's, not the model's (the benchmark subtracts it). + self.last_rate_limit_wait_s: float = 0.0 def complete( self, @@ -287,7 +294,8 @@ class AnthropicPassthroughClient: ) if require_tool_call and tools: body["tool_choice"] = {"type": "any"} # Anthropic's name for it - response = _post_with_rate_limit_retry( + self.last_rate_limit_wait_s = 0.0 # not the last call's, if this one raises + response, self.last_rate_limit_wait_s = _post_with_rate_limit_retry( self._http, "/v1/messages", body, self._sleep ) if response.status_code != 200: @@ -347,7 +355,9 @@ class AnthropicPassthroughClient: def _post_with_rate_limit_retry( http: httpx.Client, path: str, body: dict[str, Any], sleep: Any -) -> httpx.Response: +) -> tuple[httpx.Response, float]: + """The response, and how long was spent waiting out a rate limit.""" + waited = 0.0 for attempt in (1, 2): try: response = http.post(path, json=body) @@ -356,8 +366,9 @@ def _post_with_rate_limit_retry( # wrong, so callers holding work in progress should keep it. raise UpstreamUnavailable(f"LLM request failed: {exc}") from exc if response.status_code != RATE_LIMIT_STATUS or attempt == 2: - return response + return response, waited sleep(RATE_LIMIT_RETRY_S) + waited += RATE_LIMIT_RETRY_S raise AssertionError("unreachable") diff --git a/nisse-dev/tests/test_bench.py b/nisse-dev/tests/test_bench.py index a48eff1..3c67b53 100644 --- a/nisse-dev/tests/test_bench.py +++ b/nisse-dev/tests/test_bench.py @@ -263,3 +263,57 @@ def test_metering_counts_prose_and_cost() -> None: meter.complete([], None, "local-fast") meter.complete([], None, "local-fast") assert (meter.calls, meter.prose_turns, meter.cost) == (2, 2, 1.0) + + +def test_metering_counts_rate_limit_waits_even_on_failure() -> None: + class Inner: + def __init__(self) -> None: + self.last_usage = {"input": 10, "output": 2} + self.last_cost = 0.0 + self.last_model = "local-fast" + self.last_rate_limit_wait_s = 0.0 + self.calls = 0 + + def complete(self, events, tools, model, system=None): + self.calls += 1 + self.last_rate_limit_wait_s = 20.0 + if self.calls == 2: + raise RuntimeError("upstream returned 429") + return [AssistantText(text="hi", model=model)] + + meter = MeteringClient(Inner(), FACTS) + meter.complete([], None, "local-fast") + with pytest.raises(RuntimeError): + meter.complete([], None, "local-fast") + assert meter.rate_limit_wait_s == 40.0 + + +def test_a_run_records_its_rate_limit_waits(tmp_path: Path) -> None: + [task] = load_tasks(["write-function"]) + client = Scripted(list(SOLVE_SLUGIFY)) + client.last_rate_limit_wait_s = 20.0 # every call waited once + record = run_task(task, FACTS, client, Tuning()) + assert record.rate_limit_wait_s == 60.0 + + +def test_the_report_leaves_rate_limit_waits_out_of_time() -> None: + current = {t.name: t.content_hash for t in TASKS} + rows = summarise( + [ + record_json(wall_s=50.0, rate_limit_wait_s=40.0), + record_json(wall_s=10.0, rate_limit_wait_s=0.0), + ], + current, + ) + [row] = rows + assert row.mean_wall_s == 10.0 + assert row.rate_limited == 1 + assert "429 = runs that waited" in render(rows) + + +def test_results_stored_before_waits_were_recorded_still_load() -> None: + current = {t.name: t.content_hash for t in TASKS} + old = record_json(wall_s=12.0) + del old["rate_limit_wait_s"] + [row] = summarise([old], current) + assert (row.mean_wall_s, row.rate_limited) == (12.0, 0) diff --git a/nisse-dev/tests/test_llm.py b/nisse-dev/tests/test_llm.py index fd930ff..ffc4580 100644 --- a/nisse-dev/tests/test_llm.py +++ b/nisse-dev/tests/test_llm.py @@ -142,6 +142,9 @@ def test_rate_limit_is_retried_once_then_surfaced() -> None: client.complete(EVENTS, tools=None, model="local/qwen") assert len(attempts) == 2 assert waited == [RATE_LIMIT_RETRY_S] + # Reported even though the call failed, so a caller can leave the wait + # out of how long the model took. + assert client.last_rate_limit_wait_s == RATE_LIMIT_RETRY_S def test_rate_limit_that_clears_succeeds() -> None: @@ -149,6 +152,19 @@ def test_rate_limit_that_clears_succeeds() -> None: client = make_client(lambda request: responses.pop(0), sleep=lambda _s: None) [event] = client.complete(EVENTS, tools=None, model="local/qwen") assert isinstance(event, AssistantText) + assert client.last_rate_limit_wait_s == RATE_LIMIT_RETRY_S + + +def test_the_rate_limit_wait_is_per_call() -> None: + responses = [ + httpx.Response(429, text="slow down"), + completion({"content": "one"}), + completion({"content": "two"}), + ] + client = make_client(lambda request: responses.pop(0), sleep=lambda _s: None) + client.complete(EVENTS, tools=None, model="local/qwen") + client.complete(EVENTS, tools=None, model="local/qwen") + assert client.last_rate_limit_wait_s == 0.0 def test_connection_failure_raises_llm_error() -> None: