fix(stella-tools): decline a blind wait before the spawn, and give the re-measurement an instrument

bench/trace_triage/banned.py

@@ -275,6 +275,19 @@ class ReportOnly:
             "worth reading, not worth killing."
         )
     ),
+    "blind-wait": ReportOnly(
+        reason=(
+            "a build carrying the rung in `crates/stella-tools/src/bash/wait.rs` "
+            "declines these before the spawn, so on a current binary this is close "
+            "to the `FIXED_REGRESSION` shape. It stays report-only for two reasons. "
+            "The before/after this detector exists to measure (`#3753`) runs the "
+            "pre-rung build as its control arm, and a first-trial trip would abort "
+            "the control. And a finding is not proof the fix is absent: the rung "
+            "covers `bash`, and the predicate cannot see a duration reached through "
+            "a variable, so both a false positive and a false negative are "
+            "reachable. It describes an agent waiting badly, which is a result."
+        )
+    ),
     "repeated-file-read": ReportOnly(
         reason=(
             "same shape as the band metrics above — 2 of 20 trials on s5b2. It "

bench/trace_triage/detectors.py

@@ -53,6 +53,7 @@ def _my_shape(run: Run) -> list[Finding]:
 import bands
 from fingerprint import Fingerprint, fingerprint_of
 from run_trace import Run, Trial
+from waits import REFUSAL_BOUND_SECS, waits_in
 
 # A `bash` error envelope whose message is at least this long, and this many
 # lines, before its `[exit code: N]` trailer is carrying real output that the
@@ -1278,3 +1279,74 @@ def _graded_void_trial(run: Run) -> list[Finding]:
             ],
         )
     ]
+
+
+
+@detector(
+    code="blind-wait",
+    title="a bash call sat in `sleep` for longer than a whole command's default limit",
+    site="crates/stella-tools/src/bash/wait.rs",
+    search_terms=("blind sleep tool time", "sleep instead of polling"),
+)
+def _blind_wait(run: Run) -> list[Finding]:
+    """`bash` calls that wait on a fixed number past the rung.
+
+    The measurement behind `#3753`. A blind `sleep N` costs N. A poll loop
+    costs one pass. Both look like a wait. Elapsed time tells them apart. So
+    each row carries the seconds asked for and the seconds spent.
+    """
+    occurrences = []
+    total_declared = 0
+    total_elapsed = 0.0
+    for trial in run.trials:
+        for wait in waits_in(trial):
+            if not wait.declined_by_the_shipped_rung:
+                continue
+            total_declared += wait.declared_sleep_secs
+            total_elapsed += wait.elapsed_secs or 0.0
+            spent = (
+                f"{wait.elapsed_secs:.1f}s spent"
+                if wait.elapsed_secs is not None
+                else "no result recorded"
+            )
+            occurrences.append(
+                Occurrence(
+                    trial_uuid=trial.trial_uuid,
+                    task_id=trial.task_id,
+                    s3_key=trial.s3_key(),
+                    location=(
+                        f"bash call `{wait.call_id}` — {wait.declared_sleep_secs}s of "
+                        f"`sleep` asked for, {spent}"
+                    ),
+                    excerpt=wait.command[:800],
+                )
+            )
+    if not occurrences:
+        return []
+    return [
+        Finding(
+            detector="blind-wait",
+            site="crates/stella-tools/src/bash/wait.rs",
+            variant_source=f"foreground sleep over {REFUSAL_BOUND_SECS}s",
+            title="a bash call waited on a number of seconds instead of on the thing",
+            summary=(
+                f"These calls asked for {total_declared}s of `sleep`. They spent "
+                f"{total_elapsed:.0f}s. The turn pays the whole wait. It pays it even "
+                "when the thing arrives early. A poll loop returns when it is ready. "
+                "A build with the rung in `bash/wait.rs` declines these before the "
+                "spawn. So on a new build the count is the finding, not the seconds."
+            ),
+            occurrences=occurrences,
+            denominator=len(run.trials),
+            search_terms=("blind sleep tool time", "sleep instead of polling"),
+            caveats=[
+                "This reads the command text, never a measured wait. A `sleep` "
+                "reached through a variable is invisible. So it is a floor on the "
+                "blind waiting in a run, not a census.",
+                f"The {REFUSAL_BOUND_SECS}s bound is the shipped one. An old trace is "
+                "scored against a rule its binary never ran. That is what makes a "
+                "before and an after line up. It is not a claim about what the old "
+                "build refused.",
+            ],
+        )
+    ]

bench/trace_triage/tests/test_postmortem.py

@@ -21,7 +21,7 @@
 
 from bands import arm_metrics, trial_metrics
 from fixtures import event, ok, tool_pair, write_run
-from postmortem import build_report, cohort_of, render_markdown, write_report
+from postmortem import build_report, render_markdown, write_report
 from run_trace import load_run
 
 # --------------------------------------------------------------------------

bench/trace_triage/tests/test_waits.py

@@ -0,0 +1,126 @@
+"""The wait parser and the `blind-wait` detector, against real command text.
+
+Every command string below was sent by a trial in arenabench match
+`13f7f2bb533d`. They are kept verbatim because the discrimination this code
+has to make is between two shapes that look alike and cost 13x differently:
+a blind `sleep N`, which always costs N, and a poll loop, which costs one pass
+when the check passes early. That match measured the loop at 20.9s and the
+blind wait beside it at 280.4s.
+"""
+
+from __future__ import annotations
+
+from detectors import run_all
+from fixtures import ok, write_run
+from run_trace import load_run
+from waits import ADVISORY_BOUND_SECS, REFUSAL_BOUND_SECS, blocking_sleep_seconds
+
+# The two calls that dominated the panel's tool time.
+BACKGROUNDED_INSTALL = (
+    "timeout 500 pip install --quiet torch --index-url "
+    "https://download.pytorch.org/whl/cpu 2>&1 | tail -30 &\n"
+    "BGPID=$!\nsleep 490\nwait $BGPID 2>/dev/null\necho done"
+)
+BLIND_POLL = "sleep 280; tail -30 /tmp/apt_install.log; echo ---; ps aux|grep apt"
+
+# The same agent, in the same trial, getting it right.
+POLL_LOOP = (
+    'for i in $(seq 1 25); do sleep 20; if ! ps aux | grep -q "[a]pt-get install"; '
+    "then echo DONE; break; fi; echo waiting $i; done; which g++ gcc"
+)
+NOHUP_START = (
+    "nohup apt-get install -y g++ > /tmp/apt_install.log 2>&1 & sleep 2; echo started"
+)
+# The shape the advisory's own remedy text recommends.
+CHECK_FIRST_LOOP = "for i in $(seq 30); do curl -sf http://localhost:8080 && break; sleep 1; done"
+
+
+def test_a_backgrounded_install_is_not_part_of_the_wait():
+    """The install runs beside the wait; only the `sleep` is the wait."""
+    assert blocking_sleep_seconds(BACKGROUNDED_INSTALL) == 490
+    assert blocking_sleep_seconds(BLIND_POLL) == 280
+
+
+def test_a_poll_loop_is_read_as_a_pass_or_not_at_all():
+    """Neither reading of a poll loop reaches the bound.
+
+    A segment counts only when it is exactly `sleep N`. `do sleep 20;` keeps
+    the loop keyword in the segment, so it reads as no sleep; the same loop
+    written `…; sleep 1; done` reads as one second, which is one pass rather
+    than the worst case. Both are far under the bound, so the cheap pattern is
+    never declined. The seconds this predicate cannot see are checked against
+    the Rust it mirrors in `crates/stella-core/src/shell_text.rs`.
+    """
+    assert blocking_sleep_seconds(POLL_LOOP) is None
+    assert blocking_sleep_seconds(CHECK_FIRST_LOOP) == 1
+    assert blocking_sleep_seconds(NOHUP_START) == 2
+
+
+def test_the_bounds_separate_the_two_shapes():
+    assert ADVISORY_BOUND_SECS < REFUSAL_BOUND_SECS
+    for command in (BACKGROUNDED_INSTALL, BLIND_POLL):
+        assert blocking_sleep_seconds(command) >= REFUSAL_BOUND_SECS, command
+    for command in (POLL_LOOP, CHECK_FIRST_LOOP, NOHUP_START):
+        assert (blocking_sleep_seconds(command) or 0) < REFUSAL_BOUND_SECS, command
+
+
+def test_a_command_that_never_sleeps_reports_nothing():
+    assert blocking_sleep_seconds("grep sleep /app/main.c") is None
+    assert blocking_sleep_seconds("cargo build --release") is None
+    # A duration this parser cannot read is not a wait it may invent.
+    assert blocking_sleep_seconds("sleep $DELAY") is None
+
+
+def _bash_call(call_id: str, command: str, *, started_ms: int, ended_ms: int):
+    return [
+        {
+            "ts": started_ms,
+            "type": "tool_start",
+            "call": {"call_id": call_id, "name": "bash", "input": {"command": command}},
+        },
+        {"ts": ended_ms, "type": "tool_result", "call_id": call_id, "output": ok("done")},
+    ]
+
+
+def test_the_detector_fires_on_the_blind_wait_and_leaves_the_poll_loop_alone(tmp_path):
+    write_run(
+        tmp_path,
+        [
+            {
+                "task": "rstan-to-pystan__AAA",
+                "reward": 0,
+                "events": [
+                    *_bash_call("blind", BLIND_POLL, started_ms=0, ended_ms=280_400),
+                    *_bash_call("loop", POLL_LOOP, started_ms=300_000, ended_ms=320_900),
+                    {"ts": 1, "type": "step_usage", "role": "worker", "model": "m"},
+                ],
+            }
+        ],
+    )
+    findings = [f for f in run_all(load_run(tmp_path, "testrun")) if f.detector == "blind-wait"]
+    assert len(findings) == 1
+    finding = findings[0]
+    assert finding.count == 1, "the poll loop is not a blind wait"
+    only = finding.occurrences[0]
+    assert "280s of `sleep` asked for" in only.location
+    assert "280.4s spent" in only.location
+    assert "sleep 280" in only.excerpt
+
+
+def test_the_detector_is_silent_when_nothing_waits(tmp_path):
+    write_run(
+        tmp_path,
+        [
+            {
+                "task": "alpha__AAA",
+                "reward": 1,
+                "events": [
+                    *_bash_call("build", "cargo build", started_ms=0, ended_ms=4_000),
+                    {"ts": 1, "type": "step_usage", "role": "worker", "model": "m"},
+                ],
+            }
+        ],
+    )
+    assert not [
+        f for f in run_all(load_run(tmp_path, "testrun")) if f.detector == "blind-wait"
+    ]

bench/trace_triage/waits.py

@@ -0,0 +1,141 @@
+"""What a trial spent waiting: the `sleep` seconds a command committed to.
+
+This mirrors `blocking_sleep_seconds` in `crates/stella-core/src/shell_text.rs`,
+which is the predicate the shipped `bash` rungs ask. A trace read with a
+different predicate than the binary used would report a share the binary never
+acted on.
+
+The mirror is close, not exact. Rust uses a quote-aware `shell_words`. Here
+the split is on whitespace, once the operators are cut out. So a `sleep` in a
+quoted string is a sleep here and data there. No trace this has run against
+has that shape. If one turns up, fix the parser rather than explain the
+number.
+
+Both sides share the segment rule, and it is strict. A segment counts only
+when it is exactly `sleep N`. So `…; sleep 1; done` reads as one second.
+`do sleep 20;` reads as no sleep, because the loop keyword is in the segment.
+The predicate under-reads a poll loop. That is why a poll loop is never
+declined.
+"""
+
+from __future__ import annotations
+
+import re
+from dataclasses import dataclass
+
+#: The `sleep` seconds past which `bash` declines a call before it spawns.
+#: This is `SLEEP_REFUSAL_THRESHOLD_SECS` in
+#: `crates/stella-tools/src/bash/wait.rs`, which is that tool's
+#: `DEFAULT_TIMEOUT_SECS`. It lives here so an old trace and a new one are
+#: scored against one bound.
+REFUSAL_BOUND_SECS = 120
+
+#: The seconds past which the call still runs and the result names the wait —
+#: `SLEEP_ADVISORY_THRESHOLD_SECS` in the same file.
+ADVISORY_BOUND_SECS = 30
+
+_OPERATORS = frozenset({";", "&&", "||", "|", "&", "\n"})
+_UNITS = {"s": 1.0, "m": 60.0, "h": 3600.0, "d": 86400.0}
+
+#: Longest first, so `&&` is one token and not two. The separator is captured
+#: and kept. `shell_words` does the same: an operator is its own word, even
+#: glued to one.
+_SPLIT = re.compile(r"(&&|\|\||;|\||&|\n)")
+
+
+def _words(command: str) -> list[str]:
+    out: list[str] = []
+    for piece in _SPLIT.split(command):
+        if piece in _OPERATORS:
+            out.append(piece)
+        else:
+            out.extend(piece.split())
+    return out
+
+
+def _arg_seconds(arg: str) -> float | None:
+    digits, per_unit = arg, 1.0
+    if arg and arg[-1] in _UNITS:
+        digits, per_unit = arg[:-1], _UNITS[arg[-1]]
+    try:
+        return float(digits) * per_unit
+    except ValueError:
+        return None
+
+
+def blocking_sleep_seconds(command: str) -> int | None:
+    """Seconds this command waits in a foreground `sleep`, or `None` for none.
+
+    A segment the shell backgrounds is skipped, as the Rust walk skips it.
+    `pip install … & sleep 490` waits 490 seconds. The install is not part of
+    the wait.
+    """
+    words = _words(command)
+    total = 0.0
+    saw_sleep = False
+    start = 0
+    for end in range(len(words) + 1):
+        separator = words[end] if end < len(words) and words[end] in _OPERATORS else None
+        if end < len(words) and separator is None:
+            continue
+        segment = words[start:end]
+        start = end + 1
+        if separator == "&":
+            continue
+        if len(segment) == 2 and segment[0] == "sleep":
+            secs = _arg_seconds(segment[1])
+            if secs is not None:
+                total += secs
+                saw_sleep = True
+    return round(total) if saw_sleep else None
+
+
+@dataclass(frozen=True)
+class Wait:
+    """One `bash` call that committed to a wait, with what it actually cost."""
+
+    call_id: str
+    command: str
+    declared_sleep_secs: int
+    elapsed_secs: float | None
+
+    @property
+    def declined_by_the_shipped_rung(self) -> bool:
+        return self.declared_sleep_secs >= REFUSAL_BOUND_SECS
+
+
+def waits_in(trial) -> list[Wait]:  # noqa: ANN001 — `run_trace.Trial`, imported by its user
+    """Every `bash` call in `trial` whose text commits to a foreground sleep.
+
+    `elapsed_secs` joins `tool_start` to `tool_result` by `call_id`. It is the
+    wall clock the call took, not the seconds it asked for. The two agree on a
+    blind wait and part on anything that exits early, so both are carried.
+    """
+    # `start_index` is a line number, not an index into `events`. So the start
+    # stamp comes from the `tool_start` event itself.
+    starts = {
+        str(e.get("call", {}).get("call_id") or ""): e.get("ts")
+        for e in trial.of_type("tool_start")
+    }
+    found: list[Wait] = []
+    for call in trial.tool_calls:
+        command = call.input.get("command")
+        if call.name != "bash" or not isinstance(command, str):
+            continue
+        secs = blocking_sleep_seconds(command)
+        if secs is None:
+            continue
+        elapsed = None
+        started = starts.get(call.call_id)
+        ended = call.result.get("ts") if call.result else None
+        if isinstance(started, int | float) and isinstance(ended, int | float):
+            elapsed = (ended - started) / 1000.0
+        found.append(
+            Wait(
+                call_id=call.call_id,
+                command=command,
+                declared_sleep_secs=secs,
+                elapsed_secs=elapsed,
+            )
+        )
+    return found