diff --git a/backend/scripts/benchmark/sandbox/bench_prewarm.py b/backend/scripts/benchmark/sandbox/bench_prewarm.py index 70cec7b513..7f40f31abb 100644 --- a/backend/scripts/benchmark/sandbox/bench_prewarm.py +++ b/backend/scripts/benchmark/sandbox/bench_prewarm.py @@ -94,7 +94,10 @@ def observe_provider(provider): if trace is None: return await acquire(*args, **kwargs) trace.mark("acquire_started") - entry = {"started": time.monotonic(), "sandbox_id": None} + # Record tool-request precedence as event state: coarse monotonic clocks + # (Windows) can timestamp a genuine prewarm acquire inside the same tick + # as the tool request, which a strict `<` comparison misclassifies. + entry = {"started": time.monotonic(), "sandbox_id": None, "precedes_tool_request": not trace.tool_requested.is_set()} trace.acquisitions.append(entry) try: sid = await acquire(*args, **kwargs) @@ -220,8 +223,7 @@ async def run_case(provider, app_config, *, case: str, prewarm: bool, model_dela tool_valid = len(tool_messages) == 1 and str(tool_messages[0].content).strip() == COMMAND_MARKER owner = sandbox_lease_owner(context) lease_remaining = owner is not None and get_sandbox_lease_manager(provider).binding_for(owner) is not None - requested = trace.timestamps.get("tool_requested", float("inf")) - speculative = [entry for entry in trace.acquisitions if entry["started"] < requested and entry["sandbox_id"] is not None] + speculative = [entry for entry in trace.acquisitions if entry["precedes_tool_request"] and entry["sandbox_id"] is not None] def duration(start: str, end: str) -> float | None: stamps = trace.timestamps diff --git a/backend/tests/test_bench_sandbox_prewarm.py b/backend/tests/test_bench_sandbox_prewarm.py index efbf9b8a2a..7258bb907e 100644 --- a/backend/tests/test_bench_sandbox_prewarm.py +++ b/backend/tests/test_bench_sandbox_prewarm.py @@ -4,7 +4,9 @@ from __future__ import annotations import asyncio import json +import math import threading +import time from types import SimpleNamespace import pytest @@ -138,6 +140,49 @@ async def test_real_graph_prewarm_starts_during_model_and_is_claimed_once(observ assert not provider.active +@pytest.mark.anyio +async def test_prewarm_reused_survives_a_coarse_clock_tie(observed, monkeypatch): + """Pin #7044: a same-tick acquire/tool timestamp must not unclassify a reused lease. + + Coarse monotonic clocks (Windows, ~15.6 ms granularity) can quantize the + prewarm acquire and the tool request into the same tick; the former strict + `<` classification then dropped the genuine prewarm from the speculative + set. Event-state capture must keep it classified as speculative. + """ + provider, config = observed + coarse_s = 0.015 + real_monotonic = time.monotonic + + def coarse_monotonic(): + return math.floor(real_monotonic() / coarse_s) * coarse_s + + monkeypatch.setattr(bench.time, "monotonic", coarse_monotonic) + # Spin until a fresh quantized bucket starts, so the whole overlap scenario + # lands inside the same tick deterministically. + current_bucket = coarse_monotonic() + while coarse_monotonic() == current_bucket: + await asyncio.sleep(0.001) + + model_gate = asyncio.Event() + trace = bench.Trace() + task = asyncio.create_task(bench.run_case(provider, config, case="tool", prewarm=True, model_delay=0, thread_id="coarse-tick", user_id="alice", trace=trace, model_gate=model_gate)) + try: + await asyncio.wait_for(trace.model_started.wait(), 2) + await asyncio.wait_for(provider.started.wait(), 2) + provider.finish.set() + await asyncio.wait_for(trace.acquire_ready.wait(), 2) + model_gate.set() + row = await asyncio.wait_for(task, 3) + finally: + provider.finish.set() + model_gate.set() + await asyncio.gather(task, return_exceptions=True) + assert trace.acquisitions[0]["started"] == trace.timestamps["tool_requested"], "precondition: the acquire and the tool request must share one quantized tick" + assert row["success"], json.dumps(row) + assert row["acquire_calls"] == 1 + assert row["prewarm_reused"] is True + + @pytest.mark.anyio async def test_real_graph_baseline_waits_until_tool_to_start(observed): provider, config = observed