docs: durable sprint plan + baseline harness for perf batch #342-#348

- tests/benchmarks/sprint_perf_baseline.py: one harness, four isolated stress
  scenarios (anim-dispatch #342, scene-update #343, key-dispatch #344,
  grid-churn #348), wall-clock timed, step()-only/pure-loop (no screenshots).
  Doubles as a Callgrind target for per-function instruction counts.
- docs/sprint-perf-342-348.md: durable plan with pre-fix baselines captured
  (wall-clock median/3 + Callgrind self-Ir per target function), the A/B
  re-measurement protocol, per-issue root cause / fix direction / files /
  acceptance / risk, suggested order (#348, #342, then #343/#344), and DoD.

Baselines (Callgrind self-Ir, harness total 3.52B Ir): setProperty 158.6M
(4.50%, #342); get_grid 72.5M (2.06%, 0% cache hit, #348); enum-ctor 19.18M
over 6000 calls (#344); per-step update GetAttrString ~3.4k Ir/call (#343).

Refs #342, #343, #344, #345, #348.

Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com>
This commit is contained in:
John McCardle 2026-07-10 22:00:51 -04:00
commit f0a44fe3e3
2 changed files with 249 additions and 0 deletions

133
docs/sprint-perf-342-348.md Normal file
View file

@ -0,0 +1,133 @@
# Sprint plan: hot-path perf batch (#342, #343, #344, #348)
Durable plan to fix four profiler-identified hot paths in one sprint, with
**before/after measurement built in**. Baselines below were captured on the
pre-fix tree (master tip `03c9b9f`/`ef0408e`, engine code = #331 `182da62`).
Companion: `docs/profiling.md` (the rig). All four share the same class of fix as
#331 — stop re-doing per-call ceremony on a hot path.
## Measurement protocol (run identically before and after)
One harness drives all four scenarios in isolation, step()-only / pure-loop (no
screenshots — avoids the PNG trap):
```
tests/benchmarks/sprint_perf_baseline.py
```
**Wall-clock** (Release `build/`, representative -O3), median of 3 runs:
```
./build/mcrogueface --headless --exec tests/benchmarks/sprint_perf_baseline.py
```
**Instruction counts** (profile `build-profile/`, deterministic), one run:
```
valgrind --tool=callgrind --callgrind-out-file=build-profile/cg_baseline.out \
build-profile/mcrogueface --headless --exec tests/benchmarks/sprint_perf_baseline.py
callgrind_annotate [--inclusive=yes] build-profile/cg_baseline.out
```
Re-run both after each fix; compare the same `BASELINE | ...` lines and the same
per-function Ir. Callgrind is the primary acceptance signal (deterministic);
wall-clock is the sanity check.
**Note on wall-clock vs Callgrind divergence** (observed here, expected): the key
scenario dominates wall-clock (`automation.keyDown` blocks on X11/OS syscalls — many
ms, few app instructions) while the animation scenario dominates Callgrind
(`Animation::update` ~42% of instructions — pure CPU, no syscalls). Judge each fix by
the metric that reflects its cost: CPU-bound fixes (#342/#348) by Callgrind Ir;
per-event fixes (#344) by Callgrind Ir (wall-clock too noisy).
## Baseline numbers (pre-fix)
Harness scale: anim=500 frames×2 props/200 steps, update=5000 steps, keys=3000
events, grid=120²×5 passes. Callgrind harness total = **3,522,924,932 Ir**.
| Issue | Wall-clock (median/3) | Target function (Callgrind) | Self Ir | % harness | calls (observed) |
|---|---|---|---|---|---|
| #342 | 6.68 ms / 200k ops | `UIFrame::setProperty(string,float)` | 158.6M | 4.50% | 5.2M |
| #343 | 172 ms / 5k steps | `PyObject_GetAttrString("update")`/step | ~3.4k Ir/call | small | ~1/step |
| #344 | 665 ms / 6k ops (noisy 98135 µs) | `PyObject_CallFunction` (enum ctor) | 19.18M | 0.54% | 6,000 |
| #348 | 81.8 ms / 72k ops | `UIGridView::get_grid` | 72.5M | 2.06% | 72,000 |
Supporting inclusive costs for #342: `Animation::applyValue` 621M (17.63%),
`Animation::update` 1,479M (41.99%). For #344: `injectKeyEvent` 308M (8.76%) is
harness-only injection machinery, **not** a fix target. For #348: `get_grid`'s
callees `lookup`/`registerObject`/`PyWeakref_NewRef` each fire 72,000× → **0% cache
hit** (the defect).
## Suggested order
1. **#348** first — biggest self-cost after animation, cleanest fix, clearest
Callgrind signal (cache-hit rate 0%→~100%), and it de-risks the shim for the
others touching the grid.
2. **#342** — highest % of harness instructions; the win is CPU/frame-budget, which
Callgrind reveals even though wall-clock hid it.
3. **#343**, **#344** — smaller, mechanical; batch together.
## Per-issue plan
### #348 — get_grid re-allocates a Grid wrapper + weakref per call
- **Root cause** (`src/UIGridView.cpp` `get_grid`): allocates a temporary `UIGrid`
wrapper, caches only a **weakref** to it, returns it; caller drops it → weakref
dies → next call misses and re-allocates. 0% cache hit.
- **Fix direction**: give the shim a persistent handle to its own `UIGrid` wrapper
(strong ref owned for the shim's lifetime, or store `PyObject*` on GridData and
return it INCREF'd) so repeated access reuses one object. Mind the Grid↔wrapper
ownership cycle — reuse the `#251` tp_dealloc `use_count()` break pattern.
- **Files**: `src/UIGridView.cpp`, `src/UIGrid.h/.cpp`, possibly `PythonObjectCache`.
- **Acceptance**: `get_grid` inclusive Ir drops sharply; `PyWeakref_NewRef` /
`registerObject` call counts under `get_grid` fall from 72,000 to ~1;
`348_grid_churn` wall-clock improves. No new leak (ASan test suite clean).
- **Risk**: ownership/lifetime — must not leak the grid or double-free. Add a
regression test that hammers `grid.at()` in a loop and checks refcount stability.
### #342 — Animation applyValue → setProperty strcmp cascade
- **Root cause** (`src/Animation.cpp` `applyValue` → `UIDrawable::setProperty(const
std::string&, ...)`, e.g. `src/UIFrame.cpp:843`): per active animation per frame,
the property name is re-resolved by a linear string-compare chain.
- **Fix direction**: resolve the property **once** at `Animation::start()` to a
stable handle — an enum id or a cached setter (member function pointer / small
dispatch struct) — and call that each frame. Keep the string path for the
one-time resolve and for `setProperty`'s existing public callers.
- **Files**: `src/Animation.h/.cpp`, `src/UIFrame.cpp`, `src/UICaption.cpp`,
`src/UISprite.cpp`, `src/UIEntity.cpp`, `src/UIGrid.cpp` (each `setProperty`).
- **Acceptance**: `setProperty` self Ir (158.6M) and `applyValue` inclusive (621M)
drop; `342_anim_dispatch` wall-clock improves modestly. Common props (`x`,
`opacity`) already hit early in the cascade, so expect a larger win on deep props
(`fill_color.a`) — consider adding a deep-property variant to the harness.
- **Risk**: keep behavior identical for every property/type combination; the
existing animation tests must stay green.
### #343 — PyScene::update GetAttrString every frame
- **Root cause** (`src/PySceneObject.cpp:405`): `PyObject_GetAttrString(self,
"update")` every frame even when the subclass doesn't override `update`.
- **Fix direction**: resolve once whether the subclass overrides `update` (cache a
bool or the bound method), skip the lookup otherwise — mirror the hover fast-path
guard at `src/PyScene.cpp:361` (`is_python_subclass`).
- **Files**: `src/PySceneObject.cpp` (+ wherever per-scene override state lives).
- **Acceptance**: per-step `GetAttrString("update")` calls → 0 for a plain scene;
`343_scene_update` wall-clock improves. Overriding scenes still get `update` called.
- **Risk**: must still invoke `update` when it IS overridden (incl. late-bound /
monkeypatched). Test both a plain and an overriding scene.
### #344 — on_key rebuilds Key/InputState enum members per event
- **Root cause** (`src/PySceneObject.cpp:362,373`): `PyObject_CallFunction(enum_class,
"i", value)` per event constructs the IntEnum member via Python `EnumMeta.__call__`.
- **Fix direction**: pre-build the enum members once into a lookup table (array/dict
keyed by int value) and return the cached `PyObject*` (INCREF) per event.
- **Files**: `src/PySceneObject.cpp`, `src/PyKey.cpp`, `src/PyInputState*` (enum defs).
- **Acceptance**: `PyObject_CallFunction` (enum ctor) 6,000-call / 19.18M-Ir cost →
near-zero (replaced by an array index + INCREF). Wall-clock is too noisy to gate on.
- **Risk**: cached members must stay valid for the interpreter lifetime; hold strong
refs. Enum identity/equality must be unchanged (existing `test_callback_enums.py`).
## Definition of done
- All four target metrics improved in `cg_baseline.out` A/B (documented in the issue
comments with before/after Ir).
- `cd tests && python3 run_tests.py` green, incl. new regression tests per issue.
- ASan suite clean for #348 (lifetime) and #344 (refcounts).
- Each commit references its issue (`closes #NNN`); this doc updated with post-fix
numbers.

View file

@ -0,0 +1,116 @@
"""Sprint perf baseline — isolated stress scenarios for #342/#343/#344/#348.
Wall-clock timed, step()-only / pure-loop (NO screenshots avoids the PNG-encode
trap that buries engine work; see docs/profiling.md). Run BEFORE and AFTER the fixes
and compare the stable-format lines. Also usable under `make callgrind SCRIPT=...`
to capture function-level instruction counts for the four target hot paths in one run.
Usage:
./build/mcrogueface --headless --exec tests/benchmarks/sprint_perf_baseline.py
"""
import mcrfpy
from mcrfpy import automation
import sys
import time
# Scale knobs (kept modest so a Callgrind run finishes in a couple minutes).
ANIM_TARGETS = 500 # frames, each animating 2 properties => 1000 active animations
ANIM_STEPS = 200 # step() calls (animations have long duration -> stay active)
UPDATE_STEPS = 5000 # bare-scene step() calls (isolates PyScene::update overhead)
KEY_EVENTS = 3000 # keyDown/keyUp pairs (isolates on_key enum construction)
GRID_DIM = 120 # NxN grid
GRID_PASSES = 5 # full-grid at()/set() sweeps
def _report(name, ops, seconds):
us = (seconds / ops) * 1e6 if ops else 0.0
print(f"BASELINE | {name:22s} | {ops:8d} ops | {seconds*1000:9.2f} ms | "
f"{us:8.3f} us/op")
def bench_anim_dispatch():
"""#342 — Animation::applyValue -> setProperty(std::string,...) strcmp cascade,
per active animation per frame."""
scene = mcrfpy.Scene("anim")
ui = scene.children
frames = []
for i in range(ANIM_TARGETS):
f = mcrfpy.Frame(pos=(i % 400, (i * 3) % 400), size=(10, 10))
ui.append(f)
# long duration so the animation never completes during the run
f.animate("x", 9999.0, 1000.0, mcrfpy.Easing.LINEAR)
f.animate("opacity", 0.1, 1000.0, mcrfpy.Easing.LINEAR)
frames.append(f)
mcrfpy.current_scene = scene
t0 = time.perf_counter()
for _ in range(ANIM_STEPS):
mcrfpy.step(0.016)
dt = time.perf_counter() - t0
# ops = animation-value applications = active_anims * steps
_report("342_anim_dispatch", ANIM_TARGETS * 2 * ANIM_STEPS, dt)
def bench_scene_update():
"""#343 — PyScene::update GetAttrString('update') every frame on a plain scene."""
scene = mcrfpy.Scene("bare")
mcrfpy.current_scene = scene
t0 = time.perf_counter()
for _ in range(UPDATE_STEPS):
mcrfpy.step(0.016)
dt = time.perf_counter() - t0
_report("343_scene_update", UPDATE_STEPS, dt)
def bench_key_dispatch():
"""#344 — on_key rebuilds Key/InputState IntEnum members per event."""
scene = mcrfpy.Scene("keys")
count = [0]
def on_key(key, state):
count[0] += 1
scene.on_key = on_key
mcrfpy.current_scene = scene
t0 = time.perf_counter()
for _ in range(KEY_EVENTS):
automation.keyDown('a')
automation.keyUp('a')
dt = time.perf_counter() - t0
_report("344_key_dispatch", KEY_EVENTS * 2, dt)
if count[0] == 0:
print(" WARN: on_key never fired — key injection did not reach the handler")
def bench_grid_churn():
"""#348 — get_grid re-allocates a Grid wrapper + weakref per cell access."""
color_layer = mcrfpy.ColorLayer(z_index=-1, name="c")
grid = mcrfpy.Grid(grid_size=(GRID_DIM, GRID_DIM), pos=(0, 0), size=(800, 800),
layers=[color_layer])
col = mcrfpy.Color(20, 20, 20, 255)
t0 = time.perf_counter()
ops = 0
for _ in range(GRID_PASSES):
for x in range(GRID_DIM):
for y in range(GRID_DIM):
c = grid.at(x, y)
c.walkable = True
color_layer.set((x, y), col)
ops += 1
dt = time.perf_counter() - t0
_report("348_grid_churn", ops, dt)
def main():
print(f"=== sprint perf baseline (anim={ANIM_TARGETS}x2/{ANIM_STEPS}, "
f"update={UPDATE_STEPS}, keys={KEY_EVENTS}, grid={GRID_DIM}^2x{GRID_PASSES}) ===")
bench_anim_dispatch()
bench_scene_update()
bench_key_dispatch()
bench_grid_churn()
print("=== done ===")
if __name__ == "__main__":
main()
sys.exit(0)