Merge pull request 'Record rate-limit waits in benchmark runs, and leave them out of time' (#50) from record-rate-limit-retries into main

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:
@@ -107,6 +111,13 @@ def render(rows: list[Row]) -> str:
             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.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("")

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
+        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,
     )

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

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")
 
 

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)

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: