scripts/oakbench/execution.py 274 lines · 9.8 KB · python
1
"""Timed command execution with admitted-output capture.
2
3
This is the measurement primitive every CLI lane shares: run a command under a
4
monotonic clock, capture full output bytes to disk, and admit only a capped
5
character window into token estimates (full byte counts are always recorded).
6
7
Memory: the child's peak RSS is captured at reap time via os.wait4 (rusage),
8
so no wrapper binary or sampling thread perturbs the timing. ru_maxrss units
9
differ by platform (bytes on macOS, KiB on Linux); peak_rss_bytes is always
10
bytes. None means unmeasured (ADR-0002), never zero — e.g. on platforms
11
without wait4.
12
"""
13
14
from __future__ import annotations
15
16
import os
17
import signal
18
import subprocess
19
import sys
20
import tempfile
21
import threading
22
import time
23
from dataclasses import dataclass
24
from pathlib import Path
25
from typing import Any, Optional
26
27
_HAS_WAIT4 = hasattr(os, "wait4")
28
PEAK_RSS_SOURCE = "os_wait4_ru_maxrss" if _HAS_WAIT4 else None
29
# CPU and block I/O come from the same wait4 rusage as peak RSS: the direct
30
# child's own usage (on macOS and Linux, including descendants it reaped
31
# before exiting; daemons it leaves running are not included).
32
RUSAGE_SOURCE = "os_wait4_child_rusage" if _HAS_WAIT4 else None
33
34
35
@dataclass(frozen=True)
36
class TimedCapture:
37
    elapsed_ms: float
38
    returncode: int
39
    stdout_text: str
40
    stdout_bytes: int
41
    stdout_truncated: bool
42
    stderr_text: str
43
    stderr_bytes: int
44
    stderr_truncated: bool
45
    peak_rss_bytes: Optional[int] = None
46
    stdout_full_text: Optional[str] = None
47
    stdout_full_text_truncated: Optional[bool] = None
48
    stderr_full_text: Optional[str] = None
49
    stderr_full_text_truncated: Optional[bool] = None
50
    timed_out: bool = False
51
    stdout_raw: bytes | None = None
52
    cpu_user_ms: Optional[float] = None
53
    cpu_sys_ms: Optional[float] = None
54
    io_read_blocks: Optional[int] = None
55
    io_write_blocks: Optional[int] = None
56
    major_page_faults: Optional[int] = None
57
58
59
def stop_owned_process(proc: subprocess.Popen[Any]) -> None:
60
    """Stop the timed child and its owned process group, then always reap it."""
61
    try:
62
        if os.name == "posix":
63
            os.killpg(proc.pid, signal.SIGTERM)
64
        else:
65
            proc.terminate()
66
    except (OSError, ProcessLookupError):
67
        pass
68
    try:
69
        proc.wait(timeout=1.0)
70
    except subprocess.TimeoutExpired:
71
        pass
72
73
    # The process-group leader may exit on SIGTERM while a descendant ignores
74
    # it. Probe and kill the owned group even after the leader has been reaped.
75
    if os.name == "posix":
76
        try:
77
            os.killpg(proc.pid, 0)
78
        except (OSError, ProcessLookupError):
79
            pass
80
        else:
81
            try:
82
                os.killpg(proc.pid, signal.SIGKILL)
83
            except (OSError, ProcessLookupError):
84
                pass
85
    elif proc.poll() is None:
86
        try:
87
            proc.kill()
88
        except (OSError, ProcessLookupError):
89
            pass
90
91
    if proc.poll() is None:
92
        proc.wait()
93
94
95
class _RusagePopen(subprocess.Popen):
96
    """Popen that records the child's rusage when it is reaped.
97
98
    Overriding _try_wait keeps a single wait4 syscall as both the reap and the
99
    measurement; there is no race against the kernel discarding rusage and no
100
    extra process in the timed path.
101
    """
102
103
    rusage = None
104
105
    def _try_wait(self, wait_flags):  # type: ignore[override]
106
        try:
107
            pid, sts, rusage = os.wait4(self.pid, wait_flags)
108
        except ChildProcessError:
109
            pid = self.pid
110
            sts = 0
111
        else:
112
            if pid == self.pid:
113
                self.rusage = rusage
114
        return (pid, sts)
115
116
117
def _peak_rss_bytes(rusage: Any) -> Optional[int]:
118
    if rusage is None:
119
        return None
120
    maxrss = getattr(rusage, "ru_maxrss", None)
121
    if not maxrss or maxrss < 0:
122
        return None
123
    # macOS reports bytes; Linux (and most other Unixes) report KiB.
124
    return int(maxrss) if sys.platform == "darwin" else int(maxrss) * 1024
125
126
127
def rusage_fields(rusage: Any) -> dict[str, Any]:
128
    """CPU user/sys ms and block I/O counts; None when unmeasured (ADR-0002).
129
130
    ru_inblock/ru_oublock count real block I/O, so a warm page cache yields a
131
    measured 0, not an unmeasured value.
132
    """
133
    if rusage is None:
134
        return {"cpu_user_ms": None, "cpu_sys_ms": None, "io_read_blocks": None,
135
                "io_write_blocks": None, "major_page_faults": None}
136
    return {
137
        "cpu_user_ms": round(float(rusage.ru_utime) * 1000.0, 3),
138
        "cpu_sys_ms": round(float(rusage.ru_stime) * 1000.0, 3),
139
        "io_read_blocks": int(rusage.ru_inblock),
140
        "io_write_blocks": int(rusage.ru_oublock),
141
        "major_page_faults": int(rusage.ru_majflt),
142
    }
143
144
145
def read_admitted_text(handle: Any, char_limit: int) -> tuple[str, int, bool]:
146
    handle.flush()
147
    handle.seek(0, os.SEEK_END)
148
    byte_count = handle.tell()
149
    handle.seek(0)
150
    if char_limit <= 0:
151
        return "", byte_count, byte_count > 0
152
    raw = handle.read(char_limit * 4 + 16)
153
    text = raw.decode("utf-8", "replace")[:char_limit]
154
    return text, byte_count, byte_count > len(text.encode("utf-8", "replace"))
155
156
157
def read_full_text_with_byte_limit(handle: Any, byte_limit: int) -> tuple[str | None, bool]:
158
    handle.flush()
159
    handle.seek(0, os.SEEK_END)
160
    byte_count = handle.tell()
161
    if byte_limit < 0:
162
        return None, byte_count > 0
163
    if byte_count > byte_limit:
164
        return None, True
165
    handle.seek(0)
166
    return handle.read().decode("utf-8", "replace"), False
167
168
169
def run_timed(
170
    command: list[str],
171
    cwd: Path,
172
    env: dict[str, str],
173
    admitted_output_chars: int,
174
    full_output_bytes: int | None = None,
175
    timeout_seconds: float | None = None,
176
    raw_output_bytes: int | None = None,
177
    watchdog_seconds: float | None = None,
178
) -> TimedCapture:
179
    """Run ``command`` under a monotonic clock.
180
181
    ``timeout_seconds`` uses ``Popen.wait(timeout)``, which on Python < 3.11
182
    polls with a doubling sleep (up to 50 ms), quantizing short timings.
183
    ``watchdog_seconds`` bounds the command instead with a timer thread that
184
    kills the owned process group while the caller blocks in a single
185
    ``wait4``, so the measured time does not depend on the bound. Pass one or
186
    the other; existing callers keep their behaviour.
187
    """
188
    if timeout_seconds is not None and timeout_seconds <= 0:
189
        raise ValueError("timeout_seconds must be positive")
190
    if watchdog_seconds is not None and watchdog_seconds <= 0:
191
        raise ValueError("watchdog_seconds must be positive")
192
    if timeout_seconds is not None and watchdog_seconds is not None:
193
        raise ValueError("pass timeout_seconds or watchdog_seconds, not both")
194
    if raw_output_bytes is not None and raw_output_bytes < 0:
195
        raise ValueError("raw_output_bytes must be nonnegative")
196
    popen_cls = _RusagePopen if _HAS_WAIT4 else subprocess.Popen
197
    start = time.perf_counter()
198
    with tempfile.TemporaryFile() as stdout_fh, tempfile.TemporaryFile() as stderr_fh:
199
        proc = popen_cls(
200
            command,
201
            cwd=cwd,
202
            env=env,
203
            stdout=stdout_fh,
204
            stderr=stderr_fh,
205
            start_new_session=(timeout_seconds is not None or watchdog_seconds is not None) and os.name == "posix",
206
        )
207
        timed_out = False
208
        if watchdog_seconds is not None:
209
            fired = threading.Event()
210
            done = threading.Lock()
211
212
            def _expire() -> None:
213
                with done:
214
                    if proc.returncode is None:
215
                        fired.set()
216
                        try:
217
                            os.killpg(proc.pid, signal.SIGKILL) if os.name == "posix" else proc.kill()
218
                        except (OSError, ProcessLookupError):
219
                            pass
220
221
            timer = threading.Timer(watchdog_seconds, _expire)
222
            timer.daemon = True
223
            timer.start()
224
            try:
225
                returncode = proc.wait()
226
            finally:
227
                with done:
228
                    timer.cancel()
229
            if fired.is_set():
230
                timed_out = True
231
                returncode = 124
232
        else:
233
            try:
234
                returncode = proc.wait(timeout=timeout_seconds)
235
            except subprocess.TimeoutExpired:
236
                timed_out = True
237
                stop_owned_process(proc)
238
                returncode = 124
239
        elapsed_ms = (time.perf_counter() - start) * 1000
240
        stdout_text, stdout_bytes, stdout_truncated = read_admitted_text(stdout_fh, admitted_output_chars)
241
        stderr_text, stderr_bytes, stderr_truncated = read_admitted_text(stderr_fh, admitted_output_chars)
242
        stdout_raw = None
243
        if raw_output_bytes is not None and stdout_bytes <= raw_output_bytes:
244
            stdout_fh.seek(0)
245
            stdout_raw = stdout_fh.read()
246
        stdout_full_text = None
247
        stdout_full_text_truncated = None
248
        stderr_full_text = None
249
        stderr_full_text_truncated = None
250
        if full_output_bytes is not None:
251
            stdout_full_text, stdout_full_text_truncated = read_full_text_with_byte_limit(
252
                stdout_fh, full_output_bytes
253
            )
254
            stderr_full_text, stderr_full_text_truncated = read_full_text_with_byte_limit(
255
                stderr_fh, full_output_bytes
256
            )
257
    return TimedCapture(
258
        elapsed_ms=elapsed_ms,
259
        returncode=returncode,
260
        stdout_text=stdout_text,
261
        stdout_bytes=stdout_bytes,
262
        stdout_truncated=stdout_truncated,
263
        stderr_text=stderr_text,
264
        stderr_bytes=stderr_bytes,
265
        stderr_truncated=stderr_truncated,
266
        peak_rss_bytes=_peak_rss_bytes(getattr(proc, "rusage", None)),
267
        stdout_full_text=stdout_full_text,
268
        stdout_full_text_truncated=stdout_full_text_truncated,
269
        stderr_full_text=stderr_full_text,
270
        stderr_full_text_truncated=stderr_full_text_truncated,
271
        timed_out=timed_out,
272
        stdout_raw=stdout_raw,
273
        **rusage_fields(getattr(proc, "rusage", None)),
274
    )