diff --git a/TRACKER.md b/TRACKER.md new file mode 100644 index 0000000..7012602 --- /dev/null +++ b/TRACKER.md @@ -0,0 +1,112 @@ +# ExcelBench — Sprint Tracker + +> Single source of truth for the **7-Dimension Extension** initiative. Each row tracks one +> self-contained sprint (one branch, one PR, one row flip). Resume cold by reading this file +> and the most recent `[*INCOMPLETE*]` marker. + +**Last updated**: 2026-04-27 (S1 shipped) + +## Status Table + +| # | Dimension | Status | Sprint size | Branch | PR | Acceptance commit range | +|----|------------------------------------|-------------|-------------|--------------------------------|-----|-------------------------| +| S1 | Memory honesty + Tracker bootstrap | Shipped | S (3–5 d) | `feat/perf-mem-honesty` | #28 | `50dc104..HEAD@PR#28` | +| S2 | Data shape (int/str/date/formula) | Planned | M (1 wk) | `feat/perf-data-shape` | — | — | +| S3 | File shape (wide/tall/sparse) | Planned | M (1 wk) | `feat/perf-file-shape` | — | — | +| S4 | High-cost operations | Planned | M (1 wk) | `feat/perf-operations` | — | — | +| S5 | Workbook complexity perf | Planned | M (1 wk) | `feat/perf-complexity` | — | — | +| S6 | Cold-start / warm path | Planned | S (3–5 d) | `feat/perf-cold-start` | — | — | +| S7 | Round-trip fidelity (LibreOffice) | Planned | L (~2 wk) | `feat/fidelity-roundtrip` | — | — | + +**Status legend**: `Planned` → `In Progress` → `Shipped` (or `Blocked` with reason). + +## How to Flip a Row + +When a sprint lands: + +1. Update the row's **Status** to `Shipped`. +2. Fill in the **PR** column (`#NN`). +3. Fill in **Acceptance commit range** (`abc1234..def5678`). +4. Bump the **Last updated** line at the top of this file. +5. Append a sprint acceptance entry (template below) to the **Acceptance Notes** section. +6. Add the corresponding `DEC-NNN` entry to `decisions.md` if not already done. + +If a sprint stalls, switch its status to `Blocked` and add a one-line reason in the row. + +## Sprint Acceptance Template + +Use this template when appending to **Acceptance Notes** below. + +```markdown +### S — (YYYY-MM-DD) + +**Branch**: `feat/...` · **PR**: #NN · **Commit range**: `abc1234..def5678` + +**What shipped**: +- + +**Verification**: +- `uv run pytest tests/` ✓ +- `uv run ruff check src/ tests/` ✓ +- `uv run mypy src/` ✓ +- `excelbench ...` ✓ (16 adapters, no crashes) +- Dashboard regenerated, results.json + history.jsonl appended. + +**Decisions**: DEC-NNN logged in `decisions.md`. + +**Deferred / out-of-scope**: +- +``` + +## Acceptance Notes + + + +### S1 — Memory honesty + Tracker bootstrap (2026-04-27) + +**Branch**: `feat/perf-mem-honesty` · **PR**: [#28](https://github.com/SynthGL/ExcelBench/pull/28) · **Commit range**: `50dc104..HEAD` (final range fills in on merge) + +**What shipped**: +- `TRACKER.md` (this file) — 7-row sprint table, row-flip protocol, acceptance template. +- `src/excelbench/perf/memory.py` — three-mode memory harness (`getrusage` / `tracemalloc` / + `time` via `/usr/bin/time -l` subprocess + `all` composite). `MemoryProbe` context manager + for in-process modes; `parse_time_l_stderr` cross-platform parser (macOS BSD time + GNU + time `-l`). +- `PerfOpResult` extended with `rss_kb_via_time` and `python_heap_peak_kb` fields (existing + `rss_peak_mb` preserved — backwards-compatible). +- `src/excelbench/perf/_iter_subprocess.py` — internal subprocess entrypoint that runs one + iteration per invocation; wrapped by parent under `/usr/bin/time -l`. +- `excelbench perf --memory-mode={getrusage,tracemalloc,time,all}` CLI flag. +- HTML dashboard renders dual `RSS (MB) — getrusage / time -l` cells with a tooltip + explaining divergence whenever any entry has a `time -l` measurement. +- DEC-018 documents why three modes coexist and what each is honest about. + +**Verification** (run on macOS 25.2, Python 3.13): +- `uv run pytest tests/` ✓ 1140 passed, 32 skipped, 6 xfailed +- `uv run ruff check src/excelbench/perf/ src/excelbench/cli.py src/excelbench/results/html_dashboard.py` ✓ +- `uv run mypy src/excelbench/perf/` ✓ no issues +- `excelbench perf --memory-mode=all --feature cell_values --adapter wolfxl --adapter openpyxl --warmup 1 --iters 2`: + - All three fields populated as expected. + - Python-heap honesty signal landed: openpyxl uses 16× (read) and 227× (write) more + Python heap than wolfxl on the same workload, confirming wolfxl pushes allocations into Rust. + - `time -l/getrusage` ratio ~0.97x on small fixtures (subprocess startup dominates); + expected to diverge meaningfully once Sprint 2 lands ≥1M-cell fixtures. + +**Decisions**: DEC-018 logged in `decisions.md`. + +**Deferred / out-of-scope**: +- Tracemalloc reset semantics across nested probes — current code uses `reset_peak()` when a + probe re-enters an already-traced context. Should be revisited if any caller starts + tracemalloc outside the probe. +- `time -l` subprocess support on Windows — skipped silently (no `/usr/bin/time`). + Sprint 6 (cold-start) will set the precedent for cross-platform subprocess handling. +- Visualizing the time-l/getrusage divergence as a dedicated chart — single dual-cell + with tooltip is sufficient until S2 ships larger fixtures that make the gap visible. + +## Reference + +- Plan: see the wolfxl session that produced this tracker (multi-sprint roadmap). +- Architecture: [`architecture.md`](architecture.md) +- Decisions: [`decisions.md`](decisions.md) +- Key seams: `src/excelbench/perf/runner.py`, `src/excelbench/harness/adapters/base.py`, + `src/excelbench/results/html_dashboard.py`. diff --git a/decisions.md b/decisions.md index 39b19c1..39a0811 100644 --- a/decisions.md +++ b/decisions.md @@ -40,6 +40,54 @@ Skip logging for routine bug fixes, refactors, or incremental test additions. ## Decisions +### DEC-018 — Three coexisting memory-measurement modes (2026-04-27) + +**Context**: Until Sprint 1 of the 7-Dimension Extension, the perf runner reported a single +memory number — peak RSS via `resource.getrusage(RUSAGE_SELF).ru_maxrss`. Two problems with +that single number: (1) `getrusage` returns the **process-lifetime peak**, so once the first +heavy iteration has allocated, subsequent iterations report the same sticky max even if they +allocated less — making per-iteration comparisons misleading; (2) ad-hoc 100k → 1M cell +benchmarks against openpyxl from the wolfxl 1.0 work showed the `getrusage` peak diverges +from `/usr/bin/time -l` peaks by 30-300% on large workloads, depending on Rust allocator +release behavior. There is no single right number — different libraries pay memory cost in +different places (Python heap vs Rust heap vs OS pages) and the perf dashboard needs to be +honest about that asymmetry rather than pretending a single column tells the truth. + +**Decision**: Coexist three modes via a new `--memory-mode` flag, all populating the existing +`PerfOpResult` dataclass with separate fields: + +- `getrusage` (default, cheap): in-process `RUSAGE_SELF.ru_maxrss`. Preserved as the hot-path + default — fast, but documented as lifetime-peak-sticky. +- `tracemalloc`: in-process `tracemalloc.get_traced_memory()`. Adds the Python heap peak. + Misleading for Rust-backed adapters (wolfxl, python-calamine, rust_xlsxwriter) because it + cannot see native allocations; honest for pure-Python adapters. +- `time`: spawn each iteration under `/usr/bin/time -l` and parse peak RSS from stderr. + Honest about Rust allocations because the OS reports it. Slow (subprocess startup + + adapter import per iteration); quarterly deep-dive only. +- `all`: composite — every iteration runs in-process (capturing getrusage + tracemalloc) AND + in a fresh subprocess (capturing time-l RSS). Used for the memory-deep-dive bench, not CI. + +The dashboard renders `RSS (MB) — getrusage / time -l` as a dual cell with a tooltip +explaining the divergence whenever any entry has the time-l field populated. + +**Alternatives considered**: (1) Replace `getrusage` with `psutil.Process().memory_info().rss` +polling — rejected: still in-process, still subject to allocator-release lag, and adds a +mandatory third-party dependency to the runner. (2) Drop `getrusage` once `time -l` is +available — rejected: `time -l` is 50-500x slower per iteration, breaking the CI hot path. +(3) Single `multi_mode` field instead of three separate fields — rejected: makes the JSON +schema lossy (can't tell which number came from which mode in a composite run). + +**Consequences**: `PerfOpResult` JSON now carries `rss_kb_via_time` and `python_heap_peak_kb` +in addition to the existing `rss_peak_mb`. Downstream dashboards must accept these as +optional fields. The `time` and `all` modes spawn one subprocess per iteration via the new +private `excelbench.perf._iter_subprocess` module; on Windows where `/usr/bin/time` does not +exist, `rss_kb_via_time` is silently `None`. Comparisons across past results remain valid +because the existing `rss_peak_mb` field is unchanged. + +**Commit(s)**: Sprint 1, branch `feat/perf-mem-honesty`. + +--- + ### DEC-017 — Do not inject Excel alignment defaults in benchmark comparisons (2026-02-17) **Context**: Several value-focused adapters return an empty `CellFormat()` for alignment reads/writes. diff --git a/src/excelbench/cli.py b/src/excelbench/cli.py index 36be8ed..357d5a5 100644 --- a/src/excelbench/cli.py +++ b/src/excelbench/cli.py @@ -260,6 +260,19 @@ def perf( "--profile", help="Benchmark profile: xlsx (default) or xls.", ), + memory_mode: str = typer.Option( + "getrusage", + "--memory-mode", + help=( + "Memory measurement strategy. 'getrusage' (default) uses the cheap " + "in-process RUSAGE_SELF peak. 'tracemalloc' reports getrusage RSS " + "plus the Python heap peak (misses Rust allocations). 'time' spawns " + "each iteration under /usr/bin/time (-l on macOS, -v on Linux) for " + "an OS-honest peak RSS — runs only the subprocess, not double-" + "executed in-process. 'all' runs every iteration in all three modes " + "— quarterly deep-dive, not the CI hot path." + ), + ), ) -> None: """Run performance benchmarks (speed + best-effort memory). @@ -269,15 +282,26 @@ def perf( from excelbench.harness.adapters import get_all_adapters from excelbench.perf import render_perf_results, run_perf + from excelbench.perf.memory import VALID_MEMORY_MODES if not isinstance(iteration_policy, str): iteration_policy = "fixed" + if not isinstance(memory_mode, str): + memory_mode = "getrusage" profile = profile.strip().lower() if profile not in {"xlsx", "xls"}: console.print("[red]Error: profile must be one of: xlsx, xls[/red]") raise typer.Exit(1) + memory_mode_normalized = memory_mode.strip().lower() + if memory_mode_normalized not in VALID_MEMORY_MODES: + console.print( + f"[red]Error: --memory-mode must be one of {list(VALID_MEMORY_MODES)}; " + f"got {memory_mode!r}[/red]" + ) + raise typer.Exit(1) + if profile == "xls" and test_dir.resolve() == PERF_XLSX_PROFILE_DEFAULT_TEST_DIR.resolve(): test_dir = XLS_PROFILE_DEFAULT_TEST_DIR @@ -304,6 +328,7 @@ def perf( console.print(f" Iterations: {iters}") console.print(f" Iteration policy: {iteration_policy}") console.print(f" Breakdown: {breakdown}") + console.print(f" Memory mode: {memory_mode_normalized}") if adapters: console.print(f" Adapters: {', '.join([a.name for a in selected])}") console.print() @@ -318,6 +343,7 @@ def perf( iters=iters, iteration_policy=iteration_policy, breakdown=breakdown, + memory_mode=memory_mode_normalized, # type: ignore[arg-type] ) render_perf_results(perf_results, output_dir) diff --git a/src/excelbench/perf/_iter_subprocess.py b/src/excelbench/perf/_iter_subprocess.py new file mode 100644 index 0000000..20da911 --- /dev/null +++ b/src/excelbench/perf/_iter_subprocess.py @@ -0,0 +1,71 @@ +"""Internal subprocess entrypoint for ``time -l`` memory measurement. + +Invoked by :func:`excelbench.perf.runner._measure_iteration_under_time_l`. Runs +exactly one iteration of (adapter, kind, feature) and prints metrics JSON to +stdout; the parent harness wraps the invocation in ``/usr/bin/time -l`` and +parses peak RSS from stderr. + +Not part of the public CLI surface — only the perf runner calls this. +""" + +from __future__ import annotations + +import argparse +import json +import sys +from pathlib import Path + + +def main(argv: list[str] | None = None) -> int: + parser = argparse.ArgumentParser(prog="excelbench-perf-iter") + parser.add_argument("--library", required=True) + parser.add_argument("--kind", choices=["read", "write"], required=True) + parser.add_argument("--manifest", required=True, type=Path) + parser.add_argument("--feature", required=True) + parser.add_argument( + "--memory-mode", + default="getrusage", + choices=["getrusage", "tracemalloc", "all"], + help="In-process memory mode for the iteration. The 'time' mode is " + "implicit — that's why the parent process is calling us under " + "/usr/bin/time -l.", + ) + args = parser.parse_args(argv) + + from excelbench.generator.generate import load_manifest + from excelbench.harness.adapters import get_all_adapters + from excelbench.perf.runner import run_one_iteration + + manifest = load_manifest(args.manifest) + matching = [f for f in manifest.files if f.feature == args.feature] + if not matching: + sys.stderr.write(f"feature {args.feature!r} not in manifest\n") + return 2 + test_file = matching[0] + + adapters_by_name = {a.name: a for a in get_all_adapters()} + adapter = adapters_by_name.get(args.library) + if adapter is None: + sys.stderr.write(f"adapter {args.library!r} not registered\n") + return 2 + + test_dir = args.manifest.parent + metrics = run_one_iteration( + adapter=adapter, + kind=args.kind, + test_file=test_file, + test_dir=test_dir, + memory_mode=args.memory_mode, + ) + serializable = { + k: v + for k, v in metrics.items() + if k in ("wall_ms", "cpu_ms", "rss_peak_mb", "python_heap_peak_kb") + and isinstance(v, int | float) + } + sys.stdout.write(json.dumps(serializable) + "\n") + return 0 + + +if __name__ == "__main__": + sys.exit(main()) diff --git a/src/excelbench/perf/memory.py b/src/excelbench/perf/memory.py new file mode 100644 index 0000000..31fe5d9 --- /dev/null +++ b/src/excelbench/perf/memory.py @@ -0,0 +1,229 @@ +"""Memory measurement harness with three coexisting modes. + +The perf runner can measure memory three different ways. None of them is *the* +right answer in isolation — each is honest about a different slice of reality: + +- ``getrusage`` (default, cheap): peak RSS via ``resource.getrusage(RUSAGE_SELF)``. + Returns the **process-lifetime peak**, so once the first heavy iteration has + allocated, subsequent iterations report the sticky max regardless of whether + they actually allocated less. Iteration-noisy in practice. + +- ``tracemalloc``: peak Python heap via ``tracemalloc.get_traced_memory()``. + Misses Rust / PyO3 / native-extension allocations entirely. Misleading for + Rust-backed adapters (wolfxl, python-calamine, rust_xlsxwriter); fine for + pure-Python adapters (openpyxl, xlsxwriter). + +- ``time``: spawn ``/usr/bin/time`` in a fresh subprocess (with ``-l`` on + macOS BSD time, ``-v`` on GNU/Linux time) and parse the peak RSS from + stderr. Honest about Rust allocations because the measurement is from the + OS. Slow because each iteration pays Python startup + adapter import cost; + that overhead is included in the reported peak (a feature, not a bug — it + answers "what does running this library actually cost in a fresh process"). + +The composite ``all`` mode runs all three sequentially per iteration so the +quarterly memory deep-dive can compare them directly. +""" + +from __future__ import annotations + +import json +import re +import subprocess +import sys +from dataclasses import dataclass +from pathlib import Path +from typing import Literal + +MemoryMode = Literal["getrusage", "time", "tracemalloc", "all"] +VALID_MEMORY_MODES: tuple[MemoryMode, ...] = ("getrusage", "time", "tracemalloc", "all") + + +@dataclass(frozen=True) +class MemorySample: + """One memory measurement of an iteration. Any field may be ``None``. + + All RSS fields are reported in **kilobytes** for direct comparability with + ``/usr/bin/time -l`` stderr output. The runner converts to MB for display. + """ + + rss_via_getrusage_kb: float | None = None + rss_via_time_kb: float | None = None + python_heap_peak_kb: float | None = None + + +def includes_getrusage(mode: MemoryMode) -> bool: + # getrusage is essentially free (one syscall), so we always populate + # rss_peak_mb in any in-process mode. This keeps the help text honest: + # tracemalloc-only runs still report RSS alongside the Python heap peak. + return mode in ("getrusage", "tracemalloc", "all") + + +def includes_tracemalloc(mode: MemoryMode) -> bool: + return mode in ("tracemalloc", "all") + + +def includes_time(mode: MemoryMode) -> bool: + return mode in ("time", "all") + + +class MemoryProbe: + """Context manager that captures the in-process memory modes. + + Use ``with MemoryProbe(mode) as probe: ...`` and read ``probe.sample`` after + exit. The ``time`` mode is **not** captured here — it requires a subprocess + and is invoked separately by the runner via :func:`run_iteration_under_time_l`. + """ + + def __init__(self, mode: MemoryMode) -> None: + self.mode: MemoryMode = mode + self.sample: MemorySample = MemorySample() + self._tm_started = False + + def __enter__(self) -> MemoryProbe: + if includes_tracemalloc(self.mode): + import tracemalloc + + # Avoid double-start in case a parent context already started it. + if not tracemalloc.is_tracing(): + tracemalloc.start() + self._tm_started = True + else: + # Reset peak so we measure only this scope. + tracemalloc.reset_peak() + return self + + def __exit__(self, *_exc_info: object) -> None: + rss_via_getrusage_kb: float | None = None + python_heap_peak_kb: float | None = None + + if includes_getrusage(self.mode): + import resource + + ru = resource.getrusage(resource.RUSAGE_SELF).ru_maxrss + rss_via_getrusage_kb = _ru_maxrss_to_kb(ru) + + if includes_tracemalloc(self.mode): + import tracemalloc + + _, peak = tracemalloc.get_traced_memory() + python_heap_peak_kb = float(peak) / 1024.0 + if self._tm_started: + tracemalloc.stop() + + self.sample = MemorySample( + rss_via_getrusage_kb=rss_via_getrusage_kb, + rss_via_time_kb=None, # always populated separately by subprocess path + python_heap_peak_kb=python_heap_peak_kb, + ) + + +def run_iteration_under_time_l( + cli_args: list[str], + *, + cwd: Path | None = None, + timeout_s: float = 300.0, +) -> tuple[dict[str, float] | None, float | None]: + """Run ``/usr/bin/time`` and return (subprocess stdout JSON, peak RSS KB). + + The flag varies by platform: ``-l`` on macOS BSD time, ``-v`` on GNU/Linux + time. The subprocess is expected to print one JSON object to stdout + containing iteration metrics (wall_ms, cpu_ms). Stderr captures the time + output, from which we extract the peak RSS. + + Returns ``(metrics, rss_kb)``. Either may be ``None`` if parsing failed — + callers should treat ``None`` as "measurement unavailable" (e.g., on + Windows, where ``/usr/bin/time`` doesn't exist). + """ + time_bin = _resolve_time_l_path() + if time_bin is None: + return None, None + + cmd = [time_bin, _time_flag(), *cli_args] + try: + completed = subprocess.run( + cmd, + cwd=str(cwd) if cwd else None, + capture_output=True, + text=True, + timeout=timeout_s, + check=False, + ) + except subprocess.TimeoutExpired: + return None, None + except (FileNotFoundError, OSError): + return None, None + + metrics: dict[str, float] | None = None + if completed.returncode == 0 and completed.stdout.strip(): + try: + parsed = json.loads(completed.stdout.strip().splitlines()[-1]) + if isinstance(parsed, dict): + metrics = {k: float(v) for k, v in parsed.items() if isinstance(v, int | float)} + except (json.JSONDecodeError, ValueError): + metrics = None + + rss_kb = parse_time_l_stderr(completed.stderr) + return metrics, rss_kb + + +def parse_time_l_stderr(text: str) -> float | None: + """Extract peak RSS in KB from ``/usr/bin/time`` stderr output. + + Cross-platform: macOS BSD time emits bytes (``maximum resident set size``), + GNU/Linux time -v emits kilobytes (``Maximum resident set size (kbytes)``). + """ + if not text: + return None + + # macOS: " 12345678 maximum resident set size" (value in bytes) + macos_pattern = re.compile(r"^\s*(\d+)\s+maximum resident set size", re.MULTILINE) + m = macos_pattern.search(text) + if m: + return float(m.group(1)) / 1024.0 # bytes → KB + + # GNU time -v (Linux): "Maximum resident set size (kbytes): 12345" + gnu_kb_pattern = re.compile( + r"^\s*Maximum resident set size \(kbytes\):\s*(\d+)", re.MULTILINE + ) + m = gnu_kb_pattern.search(text) + if m: + return float(m.group(1)) # already KB + + return None + + +def _time_flag() -> str: + """Return the verbose-output flag accepted by the local ``/usr/bin/time``. + + macOS ships BSD time which uses ``-l``; GNU coreutils time on Linux uses + ``-v`` (it does not accept ``-l`` and would error out). Both stderr formats + are handled by :func:`parse_time_l_stderr`. + """ + if sys.platform == "darwin": + return "-l" + return "-v" + + +def _resolve_time_l_path() -> str | None: + """Return the absolute path to ``/usr/bin/time`` if available, else ``None``. + + On macOS this is the BSD time supporting ``-l``; on Linux it is GNU time + which uses ``-v`` for the verbose output we need. On Windows there is no + equivalent and we return ``None`` so callers can fall back gracefully. + """ + if sys.platform == "win32": + return None + candidate = "/usr/bin/time" + if Path(candidate).exists(): + return candidate + return None + + +def _ru_maxrss_to_kb(ru_maxrss: float) -> float: + """Convert ``ru_maxrss`` to kilobytes, accounting for platform differences. + + macOS reports bytes, Linux reports kilobytes (per ``getrusage(2)``). + """ + if sys.platform == "darwin": + return float(ru_maxrss) / 1024.0 + return float(ru_maxrss) diff --git a/src/excelbench/perf/runner.py b/src/excelbench/perf/runner.py index e205e55..d11404c 100644 --- a/src/excelbench/perf/runner.py +++ b/src/excelbench/perf/runner.py @@ -8,11 +8,20 @@ from __future__ import annotations +from collections.abc import Callable from dataclasses import asdict, dataclass from datetime import UTC, datetime from pathlib import Path from typing import Any +from excelbench.perf.memory import ( + VALID_MEMORY_MODES, + MemoryMode, + MemoryProbe, + includes_time, + run_iteration_under_time_l, +) + @dataclass(frozen=True) class PerfConfig: @@ -38,6 +47,15 @@ class PerfOpResult: phase_attribution_ms: dict[str, float] | None = None op_count: int | None = None op_unit: str | None = None + # Honest peak RSS measured via `/usr/bin/time -l` in a fresh subprocess. + # ``None`` when memory_mode does not include ``time`` or the platform lacks + # ``/usr/bin/time``. Includes Python startup + adapter import cost (a feature, + # not a bug — see decisions.md DEC-018). + rss_kb_via_time: float | None = None + # Peak Python heap via tracemalloc. ``None`` when memory_mode does not + # include ``tracemalloc``. Misses Rust / PyO3 / native allocations — useful + # only for pure-Python adapters. + python_heap_peak_kb: float | None = None @dataclass(frozen=True) @@ -81,6 +99,7 @@ def run_perf( iters: int = 25, iteration_policy: str = "fixed", breakdown: bool = False, + memory_mode: MemoryMode = "getrusage", ) -> PerfResults: import platform as _platform @@ -97,6 +116,10 @@ def run_perf( iteration_policy_normalized = iteration_policy.strip().lower() if iteration_policy_normalized != "fixed": raise ValueError("iteration_policy must be 'fixed'") + if memory_mode not in VALID_MEMORY_MODES: + raise ValueError( + f"memory_mode must be one of {VALID_MEMORY_MODES}; got {memory_mode!r}" + ) manifest = load_manifest(manifest_path) @@ -165,6 +188,8 @@ def run_perf( warmup=warmup, iters=iters, breakdown=breakdown, + memory_mode=memory_mode, + manifest_path=manifest_path, ) except Exception as e: notes_parts.append(f"Read failed: {type(e).__name__}: {e}") @@ -181,6 +206,8 @@ def run_perf( warmup=warmup, iters=iters, breakdown=breakdown, + memory_mode=memory_mode, + manifest_path=manifest_path, ) except Exception as e: notes_parts.append(f"Write failed: {type(e).__name__}: {e}") @@ -241,6 +268,8 @@ def _op_result_to_dict(op: PerfOpResult | None) -> dict[str, Any] | None: "phase_attribution_ms": op.phase_attribution_ms, "op_count": op.op_count, "op_unit": op.op_unit, + "rss_kb_via_time": op.rss_kb_via_time, + "python_heap_peak_kb": op.python_heap_peak_kb, } @@ -278,6 +307,8 @@ def _bench_read( warmup: int, iters: int, breakdown: bool, + memory_mode: MemoryMode = "getrusage", + manifest_path: Path | None = None, ) -> PerfOpResult: workload = _extract_single_workload(test_file) if workload is not None: @@ -288,21 +319,33 @@ def _bench_read( iters=iters, breakdown=breakdown, workload=workload, + memory_mode=memory_mode, + manifest_path=manifest_path, ) wall_samples: list[float] = [] cpu_samples: list[float] = [] rss_samples: list[float] = [] + heap_samples: list[float] = [] + time_rss_samples: list[float] = [] phase_samples: dict[str, list[float]] = {"open": [], "sheets": [], "exercise": [], "close": []} attribution_samples: dict[str, list[float]] = {"parse": [], "write": [], "verify": []} for i in range(warmup + iters): - m = _measure_read_iteration( - adapter=adapter, - test_file=test_file, - file_path=file_path, - breakdown=breakdown, + m, rss_kb = _measure_one_sample( + memory_mode=memory_mode, + manifest_path=manifest_path, + adapter_name=adapter.name, + kind="read", + feature=test_file.feature, + in_process=lambda: _measure_read_iteration( + adapter=adapter, + test_file=test_file, + file_path=file_path, + breakdown=breakdown, + memory_mode=memory_mode, + ), ) if i < warmup: continue @@ -310,6 +353,8 @@ def _bench_read( cpu_samples.append(m["cpu_ms"]) if m.get("rss_peak_mb") is not None: rss_samples.append(float(m["rss_peak_mb"])) + if m.get("python_heap_peak_kb") is not None: + heap_samples.append(float(m["python_heap_peak_kb"])) if breakdown and m.get("breakdown_ms"): for k, v in m["breakdown_ms"].items(): phase_samples.setdefault(k, []).append(float(v)) @@ -317,6 +362,9 @@ def _bench_read( for k, v in coarse.items(): attribution_samples.setdefault(k, []).append(float(v)) + if rss_kb is not None: + time_rss_samples.append(rss_kb) + breakdown_out: dict[str, float] | None = None if breakdown: breakdown_out = {k: _stats(v).p50 for k, v in phase_samples.items() if v} @@ -327,6 +375,8 @@ def _bench_read( rss_peak_mb=max(rss_samples) if rss_samples else None, breakdown_ms=breakdown_out, phase_attribution_ms={k: _stats(v).p50 for k, v in attribution_samples.items() if v}, + rss_kb_via_time=max(time_rss_samples) if time_rss_samples else None, + python_heap_peak_kb=max(heap_samples) if heap_samples else None, ) @@ -338,6 +388,8 @@ def _bench_read_workload( iters: int, breakdown: bool, workload: dict[str, Any], + memory_mode: MemoryMode = "getrusage", + manifest_path: Path | None = None, ) -> PerfOpResult: cells = _cells_from_range(workload["range"]) op_count = len(cells) @@ -345,16 +397,28 @@ def _bench_read_workload( wall_samples: list[float] = [] cpu_samples: list[float] = [] rss_samples: list[float] = [] + heap_samples: list[float] = [] + time_rss_samples: list[float] = [] phase_samples: dict[str, list[float]] = {"open": [], "sheets": [], "exercise": [], "close": []} attribution_samples: dict[str, list[float]] = {"parse": [], "write": [], "verify": []} + feature_name = str(workload.get("scenario") or workload.get("feature") or "") + for i in range(warmup + iters): - m = _measure_read_workload_iteration( - adapter=adapter, - file_path=file_path, - workload=workload, - cells=cells, - breakdown=breakdown, + m, rss_kb = _measure_one_sample( + memory_mode=memory_mode, + manifest_path=manifest_path, + adapter_name=adapter.name, + kind="read", + feature=feature_name, + in_process=lambda: _measure_read_workload_iteration( + adapter=adapter, + file_path=file_path, + workload=workload, + cells=cells, + breakdown=breakdown, + memory_mode=memory_mode, + ), ) if i < warmup: continue @@ -362,6 +426,8 @@ def _bench_read_workload( cpu_samples.append(m["cpu_ms"]) if m.get("rss_peak_mb") is not None: rss_samples.append(float(m["rss_peak_mb"])) + if m.get("python_heap_peak_kb") is not None: + heap_samples.append(float(m["python_heap_peak_kb"])) if breakdown and m.get("breakdown_ms"): for k, v in m["breakdown_ms"].items(): phase_samples.setdefault(k, []).append(float(v)) @@ -369,6 +435,9 @@ def _bench_read_workload( for k, v in coarse.items(): attribution_samples.setdefault(k, []).append(float(v)) + if rss_kb is not None: + time_rss_samples.append(rss_kb) + breakdown_out: dict[str, float] | None = None if breakdown: breakdown_out = {k: _stats(v).p50 for k, v in phase_samples.items() if v} @@ -381,6 +450,8 @@ def _bench_read_workload( phase_attribution_ms={k: _stats(v).p50 for k, v in attribution_samples.items() if v}, op_count=op_count, op_unit="cells", + rss_kb_via_time=max(time_rss_samples) if time_rss_samples else None, + python_heap_peak_kb=max(heap_samples) if heap_samples else None, ) @@ -390,62 +461,59 @@ def _measure_read_iteration( test_file: Any, file_path: Path, breakdown: bool, + memory_mode: MemoryMode = "getrusage", ) -> dict[str, Any]: - import resource import time from excelbench.harness import runner as fidelity - rss_before = _ru_maxrss_mb(resource.getrusage(resource.RUSAGE_SELF).ru_maxrss) - - wall0 = time.perf_counter_ns() - cpu0 = time.process_time_ns() - phases: dict[str, float] = {} - t0 = time.perf_counter_ns() - workbook = adapter.open_workbook(file_path) - t1 = time.perf_counter_ns() - if breakdown: - phases["open"] = _ns_to_ms(t1 - t0) - - t0 = time.perf_counter_ns() - sheet_names = adapter.get_sheet_names(workbook) - default_sheet = sheet_names[0] if sheet_names else test_file.feature - t1 = time.perf_counter_ns() - if breakdown: - phases["sheets"] = _ns_to_ms(t1 - t0) - - t0 = time.perf_counter_ns() - for tc in test_file.test_cases: - _exercise_read_case( - fidelity=fidelity, - adapter=adapter, - workbook=workbook, - default_sheet=default_sheet, - test_case=tc, - feature=test_file.feature, - ) - t1 = time.perf_counter_ns() - if breakdown: - phases["exercise"] = _ns_to_ms(t1 - t0) - - t0 = time.perf_counter_ns() - adapter.close_workbook(workbook) - t1 = time.perf_counter_ns() - if breakdown: - phases["close"] = _ns_to_ms(t1 - t0) + with MemoryProbe(memory_mode) as probe: + wall0 = time.perf_counter_ns() + cpu0 = time.process_time_ns() + + t0 = time.perf_counter_ns() + workbook = adapter.open_workbook(file_path) + t1 = time.perf_counter_ns() + if breakdown: + phases["open"] = _ns_to_ms(t1 - t0) + + t0 = time.perf_counter_ns() + sheet_names = adapter.get_sheet_names(workbook) + default_sheet = sheet_names[0] if sheet_names else test_file.feature + t1 = time.perf_counter_ns() + if breakdown: + phases["sheets"] = _ns_to_ms(t1 - t0) + + t0 = time.perf_counter_ns() + for tc in test_file.test_cases: + _exercise_read_case( + fidelity=fidelity, + adapter=adapter, + workbook=workbook, + default_sheet=default_sheet, + test_case=tc, + feature=test_file.feature, + ) + t1 = time.perf_counter_ns() + if breakdown: + phases["exercise"] = _ns_to_ms(t1 - t0) - wall1 = time.perf_counter_ns() - cpu1 = time.process_time_ns() + t0 = time.perf_counter_ns() + adapter.close_workbook(workbook) + t1 = time.perf_counter_ns() + if breakdown: + phases["close"] = _ns_to_ms(t1 - t0) - rss_after = _ru_maxrss_mb(resource.getrusage(resource.RUSAGE_SELF).ru_maxrss) - rss_peak = max(rss_before, rss_after) + wall1 = time.perf_counter_ns() + cpu1 = time.process_time_ns() return { "wall_ms": _ns_to_ms(wall1 - wall0), "cpu_ms": _ns_to_ms(cpu1 - cpu0), - "rss_peak_mb": rss_peak, + "rss_peak_mb": _kb_to_mb(probe.sample.rss_via_getrusage_kb), + "python_heap_peak_kb": probe.sample.python_heap_peak_kb, "breakdown_ms": phases if breakdown else None, } @@ -508,6 +576,8 @@ def _bench_write( warmup: int, iters: int, breakdown: bool, + memory_mode: MemoryMode = "getrusage", + manifest_path: Path | None = None, ) -> PerfOpResult: workload = _extract_single_workload(test_file) if workload is not None: @@ -517,6 +587,8 @@ def _bench_write( iters=iters, breakdown=breakdown, workload=workload, + memory_mode=memory_mode, + manifest_path=manifest_path, ) import tempfile @@ -524,6 +596,8 @@ def _bench_write( wall_samples: list[float] = [] cpu_samples: list[float] = [] rss_samples: list[float] = [] + heap_samples: list[float] = [] + time_rss_samples: list[float] = [] phase_samples: dict[str, list[float]] = { "create": [], "add_sheets": [], @@ -541,11 +615,19 @@ def _bench_write( out_path = out_dir / f"{feature_stem}{ext}" for i in range(warmup + iters): - m = _measure_write_iteration( - adapter=adapter, - test_file=test_file, - output_path=out_path, - breakdown=breakdown, + m, rss_kb = _measure_one_sample( + memory_mode=memory_mode, + manifest_path=manifest_path, + adapter_name=adapter.name, + kind="write", + feature=test_file.feature, + in_process=lambda: _measure_write_iteration( + adapter=adapter, + test_file=test_file, + output_path=out_path, + breakdown=breakdown, + memory_mode=memory_mode, + ), ) if i < warmup: continue @@ -553,6 +635,8 @@ def _bench_write( cpu_samples.append(m["cpu_ms"]) if m.get("rss_peak_mb") is not None: rss_samples.append(float(m["rss_peak_mb"])) + if m.get("python_heap_peak_kb") is not None: + heap_samples.append(float(m["python_heap_peak_kb"])) if breakdown and m.get("breakdown_ms"): for k, v in m["breakdown_ms"].items(): phase_samples.setdefault(k, []).append(float(v)) @@ -560,6 +644,9 @@ def _bench_write( for k, v in coarse.items(): attribution_samples.setdefault(k, []).append(float(v)) + if rss_kb is not None: + time_rss_samples.append(rss_kb) + breakdown_out: dict[str, float] | None = None if breakdown: breakdown_out = {k: _stats(v).p50 for k, v in phase_samples.items() if v} @@ -570,6 +657,8 @@ def _bench_write( rss_peak_mb=max(rss_samples) if rss_samples else None, breakdown_ms=breakdown_out, phase_attribution_ms={k: _stats(v).p50 for k, v in attribution_samples.items() if v}, + rss_kb_via_time=max(time_rss_samples) if time_rss_samples else None, + python_heap_peak_kb=max(heap_samples) if heap_samples else None, ) @@ -580,6 +669,8 @@ def _bench_write_workload( iters: int, breakdown: bool, workload: dict[str, Any], + memory_mode: MemoryMode = "getrusage", + manifest_path: Path | None = None, ) -> PerfOpResult: import tempfile @@ -594,6 +685,8 @@ def _bench_write_workload( wall_samples: list[float] = [] cpu_samples: list[float] = [] rss_samples: list[float] = [] + heap_samples: list[float] = [] + time_rss_samples: list[float] = [] phase_samples: dict[str, list[float]] = { "create": [], "add_sheets": [], @@ -603,6 +696,7 @@ def _bench_write_workload( attribution_samples: dict[str, list[float]] = {"parse": [], "write": [], "verify": []} feature_stem = Path(str(workload.get("scenario") or "workload")).name + feature_name = str(workload.get("scenario") or workload.get("feature") or "") ext = adapter.output_extension with tempfile.TemporaryDirectory() as tmpdir: @@ -611,12 +705,20 @@ def _bench_write_workload( out_path = out_dir / f"{feature_stem}{ext}" for i in range(warmup + iters): - m = _measure_write_workload_iteration( - adapter=adapter, - output_path=out_path, - workload=workload, - cells=cells, - breakdown=breakdown, + m, rss_kb = _measure_one_sample( + memory_mode=memory_mode, + manifest_path=manifest_path, + adapter_name=adapter.name, + kind="write", + feature=feature_name, + in_process=lambda: _measure_write_workload_iteration( + adapter=adapter, + output_path=out_path, + workload=workload, + cells=cells, + breakdown=breakdown, + memory_mode=memory_mode, + ), ) if i < warmup: continue @@ -624,6 +726,8 @@ def _bench_write_workload( cpu_samples.append(m["cpu_ms"]) if m.get("rss_peak_mb") is not None: rss_samples.append(float(m["rss_peak_mb"])) + if m.get("python_heap_peak_kb") is not None: + heap_samples.append(float(m["python_heap_peak_kb"])) if breakdown and m.get("breakdown_ms"): for k, v in m["breakdown_ms"].items(): phase_samples.setdefault(k, []).append(float(v)) @@ -631,6 +735,9 @@ def _bench_write_workload( for k, v in coarse.items(): attribution_samples.setdefault(k, []).append(float(v)) + if rss_kb is not None: + time_rss_samples.append(rss_kb) + breakdown_out: dict[str, float] | None = None if breakdown: breakdown_out = {k: _stats(v).p50 for k, v in phase_samples.items() if v} @@ -643,6 +750,8 @@ def _bench_write_workload( phase_attribution_ms={k: _stats(v).p50 for k, v in attribution_samples.items() if v}, op_count=op_count, op_unit="cells", + rss_kb_via_time=max(time_rss_samples) if time_rss_samples else None, + python_heap_peak_kb=max(heap_samples) if heap_samples else None, ) @@ -653,51 +762,48 @@ def _measure_read_workload_iteration( workload: dict[str, Any], cells: list[str], breakdown: bool, + memory_mode: MemoryMode = "getrusage", ) -> dict[str, Any]: - import resource import time - rss_before = _ru_maxrss_mb(resource.getrusage(resource.RUSAGE_SELF).ru_maxrss) - - wall0 = time.perf_counter_ns() - cpu0 = time.process_time_ns() - phases: dict[str, float] = {} - t0 = time.perf_counter_ns() - workbook = adapter.open_workbook(file_path) - t1 = time.perf_counter_ns() - if breakdown: - phases["open"] = _ns_to_ms(t1 - t0) - - t0 = time.perf_counter_ns() - adapter.get_sheet_names(workbook) - t1 = time.perf_counter_ns() - if breakdown: - phases["sheets"] = _ns_to_ms(t1 - t0) - - t0 = time.perf_counter_ns() - _run_workload_read(adapter=adapter, workbook=workbook, workload=workload, cells=cells) - t1 = time.perf_counter_ns() - if breakdown: - phases["exercise"] = _ns_to_ms(t1 - t0) - - t0 = time.perf_counter_ns() - adapter.close_workbook(workbook) - t1 = time.perf_counter_ns() - if breakdown: - phases["close"] = _ns_to_ms(t1 - t0) - - wall1 = time.perf_counter_ns() - cpu1 = time.process_time_ns() - - rss_after = _ru_maxrss_mb(resource.getrusage(resource.RUSAGE_SELF).ru_maxrss) - rss_peak = max(rss_before, rss_after) + with MemoryProbe(memory_mode) as probe: + wall0 = time.perf_counter_ns() + cpu0 = time.process_time_ns() + + t0 = time.perf_counter_ns() + workbook = adapter.open_workbook(file_path) + t1 = time.perf_counter_ns() + if breakdown: + phases["open"] = _ns_to_ms(t1 - t0) + + t0 = time.perf_counter_ns() + adapter.get_sheet_names(workbook) + t1 = time.perf_counter_ns() + if breakdown: + phases["sheets"] = _ns_to_ms(t1 - t0) + + t0 = time.perf_counter_ns() + _run_workload_read(adapter=adapter, workbook=workbook, workload=workload, cells=cells) + t1 = time.perf_counter_ns() + if breakdown: + phases["exercise"] = _ns_to_ms(t1 - t0) + + t0 = time.perf_counter_ns() + adapter.close_workbook(workbook) + t1 = time.perf_counter_ns() + if breakdown: + phases["close"] = _ns_to_ms(t1 - t0) + + wall1 = time.perf_counter_ns() + cpu1 = time.process_time_ns() return { "wall_ms": _ns_to_ms(wall1 - wall0), "cpu_ms": _ns_to_ms(cpu1 - cpu0), - "rss_peak_mb": rss_peak, + "rss_peak_mb": _kb_to_mb(probe.sample.rss_via_getrusage_kb), + "python_heap_peak_kb": probe.sample.python_heap_peak_kb, "breakdown_ms": phases if breakdown else None, } @@ -709,52 +815,49 @@ def _measure_write_workload_iteration( workload: dict[str, Any], cells: list[str], breakdown: bool, + memory_mode: MemoryMode = "getrusage", ) -> dict[str, Any]: - import resource import time - rss_before = _ru_maxrss_mb(resource.getrusage(resource.RUSAGE_SELF).ru_maxrss) - - wall0 = time.perf_counter_ns() - cpu0 = time.process_time_ns() - phases: dict[str, float] = {} - t0 = time.perf_counter_ns() - workbook = adapter.create_workbook() - t1 = time.perf_counter_ns() - if breakdown: - phases["create"] = _ns_to_ms(t1 - t0) - - sheet = str(workload.get("sheet") or "S1") - t0 = time.perf_counter_ns() - adapter.add_sheet(workbook, sheet) - t1 = time.perf_counter_ns() - if breakdown: - phases["add_sheets"] = _ns_to_ms(t1 - t0) - - t0 = time.perf_counter_ns() - _run_workload_write(adapter=adapter, workbook=workbook, workload=workload, cells=cells) - t1 = time.perf_counter_ns() - if breakdown: - phases["exercise"] = _ns_to_ms(t1 - t0) - - t0 = time.perf_counter_ns() - adapter.save_workbook(workbook, output_path) - t1 = time.perf_counter_ns() - if breakdown: - phases["save"] = _ns_to_ms(t1 - t0) - - wall1 = time.perf_counter_ns() - cpu1 = time.process_time_ns() - - rss_after = _ru_maxrss_mb(resource.getrusage(resource.RUSAGE_SELF).ru_maxrss) - rss_peak = max(rss_before, rss_after) + with MemoryProbe(memory_mode) as probe: + wall0 = time.perf_counter_ns() + cpu0 = time.process_time_ns() + + t0 = time.perf_counter_ns() + workbook = adapter.create_workbook() + t1 = time.perf_counter_ns() + if breakdown: + phases["create"] = _ns_to_ms(t1 - t0) + + sheet = str(workload.get("sheet") or "S1") + t0 = time.perf_counter_ns() + adapter.add_sheet(workbook, sheet) + t1 = time.perf_counter_ns() + if breakdown: + phases["add_sheets"] = _ns_to_ms(t1 - t0) + + t0 = time.perf_counter_ns() + _run_workload_write(adapter=adapter, workbook=workbook, workload=workload, cells=cells) + t1 = time.perf_counter_ns() + if breakdown: + phases["exercise"] = _ns_to_ms(t1 - t0) + + t0 = time.perf_counter_ns() + adapter.save_workbook(workbook, output_path) + t1 = time.perf_counter_ns() + if breakdown: + phases["save"] = _ns_to_ms(t1 - t0) + + wall1 = time.perf_counter_ns() + cpu1 = time.process_time_ns() return { "wall_ms": _ns_to_ms(wall1 - wall0), "cpu_ms": _ns_to_ms(cpu1 - cpu0), - "rss_peak_mb": rss_peak, + "rss_peak_mb": _kb_to_mb(probe.sample.rss_via_getrusage_kb), + "python_heap_peak_kb": probe.sample.python_heap_peak_kb, "breakdown_ms": phases if breakdown else None, } @@ -1222,70 +1325,67 @@ def _measure_write_iteration( test_file: Any, output_path: Path, breakdown: bool, + memory_mode: MemoryMode = "getrusage", ) -> dict[str, Any]: - import resource import time from excelbench.harness import runner as fidelity - rss_before = _ru_maxrss_mb(resource.getrusage(resource.RUSAGE_SELF).ru_maxrss) - - wall0 = time.perf_counter_ns() - cpu0 = time.process_time_ns() - phases: dict[str, float] = {} - t0 = time.perf_counter_ns() - workbook = adapter.create_workbook() - t1 = time.perf_counter_ns() - if breakdown: - phases["create"] = _ns_to_ms(t1 - t0) - - t0 = time.perf_counter_ns() - sheet_names = fidelity._collect_sheet_names(test_file) # noqa: SLF001 - if not sheet_names: - sheet_names = [test_file.feature] - for name in sheet_names: - adapter.add_sheet(workbook, name) - t1 = time.perf_counter_ns() - if breakdown: - phases["add_sheets"] = _ns_to_ms(t1 - t0) - - t0 = time.perf_counter_ns() - for tc in test_file.test_cases: - if isinstance(tc.expected, dict) and "sheet_names" in tc.expected: - continue - target_sheet = tc.sheet or test_file.feature - target_cell = tc.cell or f"B{tc.row}" - _exercise_write_case( - fidelity=fidelity, - adapter=adapter, - workbook=workbook, - feature=test_file.feature, - sheet=target_sheet, - cell=target_cell, - test_case=tc, - ) - t1 = time.perf_counter_ns() - if breakdown: - phases["exercise"] = _ns_to_ms(t1 - t0) - - t0 = time.perf_counter_ns() - adapter.save_workbook(workbook, output_path) - t1 = time.perf_counter_ns() - if breakdown: - phases["save"] = _ns_to_ms(t1 - t0) + with MemoryProbe(memory_mode) as probe: + wall0 = time.perf_counter_ns() + cpu0 = time.process_time_ns() + + t0 = time.perf_counter_ns() + workbook = adapter.create_workbook() + t1 = time.perf_counter_ns() + if breakdown: + phases["create"] = _ns_to_ms(t1 - t0) + + t0 = time.perf_counter_ns() + sheet_names = fidelity._collect_sheet_names(test_file) # noqa: SLF001 + if not sheet_names: + sheet_names = [test_file.feature] + for name in sheet_names: + adapter.add_sheet(workbook, name) + t1 = time.perf_counter_ns() + if breakdown: + phases["add_sheets"] = _ns_to_ms(t1 - t0) + + t0 = time.perf_counter_ns() + for tc in test_file.test_cases: + if isinstance(tc.expected, dict) and "sheet_names" in tc.expected: + continue + target_sheet = tc.sheet or test_file.feature + target_cell = tc.cell or f"B{tc.row}" + _exercise_write_case( + fidelity=fidelity, + adapter=adapter, + workbook=workbook, + feature=test_file.feature, + sheet=target_sheet, + cell=target_cell, + test_case=tc, + ) + t1 = time.perf_counter_ns() + if breakdown: + phases["exercise"] = _ns_to_ms(t1 - t0) - wall1 = time.perf_counter_ns() - cpu1 = time.process_time_ns() + t0 = time.perf_counter_ns() + adapter.save_workbook(workbook, output_path) + t1 = time.perf_counter_ns() + if breakdown: + phases["save"] = _ns_to_ms(t1 - t0) - rss_after = _ru_maxrss_mb(resource.getrusage(resource.RUSAGE_SELF).ru_maxrss) - rss_peak = max(rss_before, rss_after) + wall1 = time.perf_counter_ns() + cpu1 = time.process_time_ns() return { "wall_ms": _ns_to_ms(wall1 - wall0), "cpu_ms": _ns_to_ms(cpu1 - cpu0), - "rss_peak_mb": rss_peak, + "rss_peak_mb": _kb_to_mb(probe.sample.rss_via_getrusage_kb), + "python_heap_peak_kb": probe.sample.python_heap_peak_kb, "breakdown_ms": phases if breakdown else None, } @@ -1359,10 +1459,163 @@ def _ns_to_ms(ns: int) -> float: return ns / 1_000_000.0 -def _ru_maxrss_mb(ru_maxrss: float) -> float: +def _kb_to_mb(value_kb: float | None) -> float | None: + if value_kb is None: + return None + return float(value_kb) / 1024.0 + + +def _measure_one_sample( + *, + memory_mode: MemoryMode, + manifest_path: Path | None, + adapter_name: str, + kind: str, + feature: str, + in_process: Callable[[], dict[str, Any]], +) -> tuple[dict[str, Any], float | None]: + """Run one bench-loop sample and return (metrics_dict, rss_kb_via_time_or_None). + + Behavior by mode: + + - ``time`` (only): run **only** the subprocess under ``/usr/bin/time`` and + use its JSON metrics for ``wall_ms``/``cpu_ms``. Avoids double-execution + that the previous "in-process + subprocess" sequence caused. + - ``all``: run the in-process iteration AND the subprocess. The divergence + is the whole point — we want both signals. + - ``getrusage`` / ``tracemalloc``: in-process only. + + Falls back to in-process if the subprocess is unavailable (Windows) or + fails for any reason — better to have a partial measurement than none. + """ + if memory_mode == "time" and manifest_path is not None and feature: + sub_metrics, rss_kb = _measure_iteration_under_time_l( + adapter_name=adapter_name, + kind=kind, + manifest_path=manifest_path, + feature=feature, + ) + if sub_metrics is not None: + m: dict[str, Any] = { + "wall_ms": float(sub_metrics.get("wall_ms", 0.0)), + "cpu_ms": float(sub_metrics.get("cpu_ms", 0.0)), + "rss_peak_mb": sub_metrics.get("rss_peak_mb"), + "python_heap_peak_kb": sub_metrics.get("python_heap_peak_kb"), + "breakdown_ms": None, + } + return m, rss_kb + # Subprocess unavailable; fall through to in-process measurement. + + m = in_process() + rss_kb_via_time: float | None = None + if includes_time(memory_mode) and manifest_path is not None and feature: + _, rss_kb_via_time = _measure_iteration_under_time_l( + adapter_name=adapter_name, + kind=kind, + manifest_path=manifest_path, + feature=feature, + ) + return m, rss_kb_via_time + + +def _measure_iteration_under_time_l( + *, + adapter_name: str, + kind: str, + manifest_path: Path, + feature: str, +) -> tuple[dict[str, float] | None, float | None]: + """Run one iteration of (adapter, kind, feature) under ``/usr/bin/time``. + + Returns ``(subprocess_metrics, rss_kb)``. Either may be ``None`` if the + platform lacks ``/usr/bin/time`` or the subprocess failed. The subprocess + is the ``excelbench.perf._iter_subprocess`` module — see that file for the + iteration body, which mirrors the in-process measure_*_iteration helpers. + + When the bench loop is in ``time``-only mode, the subprocess metrics are + used directly for ``wall_ms``/``cpu_ms`` so the iteration is measured once, + not twice. In ``all`` mode the in-process loop also runs (the divergence + between the two is the whole point of the deep-dive). + """ import sys - # macOS reports bytes; Linux reports kilobytes. - if sys.platform == "darwin": - return float(ru_maxrss) / (1024.0 * 1024.0) - return float(ru_maxrss) / 1024.0 + cli_args = [ + sys.executable, + "-m", + "excelbench.perf._iter_subprocess", + "--library", + adapter_name, + "--kind", + kind, + "--manifest", + str(manifest_path), + "--feature", + feature, + ] + return run_iteration_under_time_l(cli_args) + + +def run_one_iteration( + *, + adapter: Any, + kind: str, + test_file: Any, + test_dir: Path, + memory_mode: MemoryMode = "getrusage", +) -> dict[str, Any]: + """Run a single iteration of (adapter, kind, test_file) and return metrics. + + Shared between the in-process bench loop and the ``time -l`` subprocess + entrypoint. The dispatch mirrors ``_bench_read``/``_bench_write``: workload- + based fixtures use the workload helpers, otherwise the test-case path runs. + """ + import tempfile + + workload = _extract_single_workload(test_file) + file_path = test_dir / test_file.path + + if kind == "read": + if workload is not None: + cells = _cells_from_range(workload["range"]) + return _measure_read_workload_iteration( + adapter=adapter, + file_path=file_path, + workload=workload, + cells=cells, + breakdown=False, + memory_mode=memory_mode, + ) + return _measure_read_iteration( + adapter=adapter, + test_file=test_file, + file_path=file_path, + breakdown=False, + memory_mode=memory_mode, + ) + + if kind == "write": + feature_stem = Path(test_file.feature).name or "feature" + ext = adapter.output_extension + with tempfile.TemporaryDirectory() as tmpdir: + out_dir = Path(tmpdir) / adapter.name + out_dir.mkdir(parents=True, exist_ok=True) + out_path = out_dir / f"{feature_stem}{ext}" + if workload is not None: + cells = _cells_from_range(workload["range"]) + return _measure_write_workload_iteration( + adapter=adapter, + output_path=out_path, + workload=workload, + cells=cells, + breakdown=False, + memory_mode=memory_mode, + ) + return _measure_write_iteration( + adapter=adapter, + test_file=test_file, + output_path=out_path, + breakdown=False, + memory_mode=memory_mode, + ) + + raise ValueError(f"kind must be 'read' or 'write'; got {kind!r}") diff --git a/src/excelbench/results/html_dashboard.py b/src/excelbench/results/html_dashboard.py index ffca08c..bdd2715 100644 --- a/src/excelbench/results/html_dashboard.py +++ b/src/excelbench/results/html_dashboard.py @@ -1903,6 +1903,24 @@ def _section_performance(perf: dict[str, Any] | None) -> str: for op in sorted(ops_present): rows.append(f"

{op.title()}

") + # Detect whether any entry in this op has the time-l RSS field; if so, + # show the dual-memory column header with a tooltip explaining + # divergence between getrusage (in-process, sticky) and time -l + # (subprocess, OS-honest, includes Rust allocations). + has_time_rss = any( + ((e.get("perf") or {}).get(op) or {}).get("rss_kb_via_time") is not None + for e in entries + ) + rss_header = ( + "" + "RSS (MB) — getrusage / time -l" + if has_time_rss + else "RSS (MB)" + ) rows.append( '
' "" @@ -1910,7 +1928,7 @@ def _section_performance(perf: dict[str, Any] | None) -> str: "" "" "" - "" + f"{rss_header}" "" "" "" @@ -1932,9 +1950,33 @@ def _sort_key(e: dict[str, Any]) -> float: wall = od.get("wall_ms", {}) cpu = od.get("cpu_ms", {}) rss = od.get("rss_peak_mb") + rss_time_kb = od.get("rss_kb_via_time") + rss_time_mb = (rss_time_kb / 1024.0) if rss_time_kb is not None else None + heap_kb = od.get("python_heap_peak_kb") oc = od.get("op_count") rate = _fmt_rate(oc, wall.get("p50")) + if has_time_rss: + rss_cell_inner = ( + f"{_fmt_mb(rss)} / {_fmt_mb(rss_time_mb)}" + if rss_time_mb is not None + else f"{_fmt_mb(rss)} / —" + ) + rss_tooltip = ( + f" title='getrusage: {_fmt_mb(rss)} (sticky lifetime peak); " + f"time -l: {_fmt_mb(rss_time_mb)} (subprocess peak)" + + ( + f"; Python heap (tracemalloc): " + f"{(heap_kb / 1024.0):.1f} MB" + if heap_kb is not None + else "" + ) + + "'" + ) + else: + rss_cell_inner = _fmt_mb(rss) + rss_tooltip = "" + # Breakdown bar bd = od.get("breakdown_ms", {}) bar_html = "" @@ -1953,13 +1995,16 @@ def _sort_key(e: dict[str, Any]) -> float: bar_html = f'
{"".join(bar_parts)}
' perf_row_cls = " class='wolfxl-row'" if lib == "wolfxl" else "" + # Sort by the most honest available number: prefer time -l peak + # when present, else fall back to getrusage. + rss_sort_value = rss_time_mb if rss_time_mb is not None else (rss or 9e9) rows.append( f"" f"" f"" f"" f"" - f"" + f"" f"" f"" )
Libraryp95 (ms)min (ms)CPU p50RSS (MB)ThroughputPhase Breakdown
{_esc(lib)}{_fmt_ms(wall.get('p50'))}{_fmt_ms(wall.get('p95'))}{_fmt_ms(wall.get('min'))}{_fmt_ms(cpu.get('p50'))}{_fmt_mb(rss)}{rss_cell_inner}{rate}{bar_html}