jeremy
a129aa4792
The previous fix stopped the animation from running when nothing was on screen. It did not make the animation itself cheap, and the user correctly reported that spawning a new session still lagged. That report was right, and my first repro could not see it: an isolated `JCODE_HOME` lands on the onboarding screen with no transcript, while a real spawn resumes a real session. Measured against the real environment instead (`scripts/repro_real_spawn_lag.py`, `scripts/measure_animation_cpu_cost.py`), the animation cost 0.257 CPU cores over an idle client and nearly doubled keystroke latency. `draw-stats` could not show it, because the animation-only partial repaint deliberately skips `record_draw_call_attribution`: it reported `draws_per_s: 0.0` while the client burned 0.3 cores. `perf` on that client named the work. Two fixes, both measured: 1. Stop cloning the whole screen twice per animation frame. The "cheap" partial repaint did `clone_from` to seed a working buffer and `clone` to keep a copy, even though only the animated rectangle changes: ~920k cell copies a second at 60fps on a 160x48 terminal to update ~2200 cells. Now it seeds once and thereafter copies only the animated rows, and keeps the remembered frame current by re-rendering those same rows (deterministic for a given elapsed time) instead of copying 7680 cells. Every path that rewrites the buffer clears `seeded_animation_area`, so the "outside the rectangle is already correct" assumption can never go stale. 2. Cap the decorative animation at 30fps. Its cost is linear in frame rate while its perceived smoothness is not, and the sweep (`scripts/sweep_animation_fps.py`) shows where the curve flattens: | fps | CPU over idle baseline | |-----|------------------------| | 60 | 0.224 cores | | 30 | 0.104 cores | | 20 | 0.080 cores | Functional motion (status spinners, scroll catch-up, streaming) keeps the full configured `animation_fps`, because there smoothness is the feature. A user who configures a *lower* rate keeps it: the cap is a ceiling, not an override. Net effect on the reported symptom, same real session: | | before | after | |---|---|---| | keystroke latency p50 | 6.6ms | 1.08ms | | keystroke latency p95 | 13.8ms | 1.21ms | | animation cost | 0.257 cores | 0.121 cores | Keystroke latency is the number the user feels, and it improved 6x. The optimization is a correctness risk, not just a speed change, so `copying_only_the_animated_rows_matches_cloning_the_whole_frame` proves the row-copy sequence is byte-identical to a full clone every tick across sizes and a run of ticks, plus a degenerate empty rectangle. Two existing cadence tests asserted the decoration runs at exactly the configured 60fps; they now assert it animates (faster than idle, still smooth) and the cap has its own test, so the intent is pinned without freezing the number this commit deliberately changes. The measurement scripts are committed because the bug was invisible to every existing instrument: harnesses that fake the environment measure the wrong thing, and CPU is the only honest signal when a render path is exempt from draw counting.
86 lines
3.6 KiB
Python
86 lines
3.6 KiB
Python
#!/usr/bin/env python3
|
|
"""
|
|
Profile a client spawned into the user's *real* environment.
|
|
|
|
`repro_real_spawn_lag.py` showed the shape of the problem: 0.3 CPU cores burned
|
|
while `draws_per_s` reads 0.0. Those are not full frames, so `draw-stats` cannot
|
|
see them: the animation-only partial repaint path deliberately skips
|
|
`record_draw_call_attribution`. `perf` sees the work regardless of which path
|
|
does it, so this attributes the burn on a real session.
|
|
"""
|
|
from __future__ import annotations
|
|
|
|
import argparse, json, os, signal, subprocess, sys, tempfile, time
|
|
from pathlib import Path
|
|
|
|
REPO_ROOT = Path(__file__).resolve().parent.parent
|
|
sys.path.insert(0, str(REPO_ROOT / "scripts"))
|
|
import repro_slash_flicker as flick # noqa: E402
|
|
from repro_real_spawn_lag import recent_session # noqa: E402
|
|
|
|
|
|
def main() -> int:
|
|
ap = argparse.ArgumentParser(description=__doc__)
|
|
ap.add_argument("--binary", default=str(REPO_ROOT / "target" / "selfdev" / "jcode"))
|
|
ap.add_argument("--session", default=None)
|
|
ap.add_argument("--seconds", type=float, default=8.0)
|
|
ap.add_argument("--freq", type=int, default=997)
|
|
args = ap.parse_args()
|
|
|
|
flick.ROWS, flick.COLS = 48, 160
|
|
binary = str(Path(args.binary).resolve())
|
|
runtime = Path(os.environ.get("JCODE_RUNTIME_DIR") or f"/run/user/{os.getuid()}")
|
|
env = os.environ.copy()
|
|
env["JCODE_SOCKET"] = env.get("JCODE_SOCKET") or str(runtime / "jcode.sock")
|
|
env["JCODE_DEBUG_CONTROL"] = "1"
|
|
env["JCODE_THEME"] = "dark"
|
|
debug_sock = runtime / "jcode-debug.sock"
|
|
|
|
scratch = Path(os.environ.get("JCODE_SCRATCH_DIR") or tempfile.gettempdir())
|
|
root = Path(tempfile.mkdtemp(prefix="jcode-profile-real-", dir=str(scratch)))
|
|
cmd_path, resp_path = root / "client_cmd", root / "client_resp"
|
|
|
|
session = args.session or recent_session(debug_sock, str(REPO_ROOT))
|
|
if not session:
|
|
session = flick.dbg(debug_sock, f"create_session:{REPO_ROOT}").strip().split()[-1]
|
|
print(f"== profiling real spawn ==\n binary : {binary}\n session: {session}")
|
|
|
|
client = None
|
|
try:
|
|
client = flick.launch(binary, env, session, cmd_path, resp_path)
|
|
if not flick.settle(cmd_path, resp_path, timeout_s=90.0):
|
|
print("client never came up")
|
|
return 3
|
|
time.sleep(3.0)
|
|
sched = (json.loads(flick.client_cmd(cmd_path, resp_path, "draw-stats 1"))
|
|
.get("redraw_schedule") or {})
|
|
print(f" donut={sched.get('idle_animation_active')} "
|
|
f"area={sched.get('idle_animation_area')} "
|
|
f"interval={sched.get('interval_ms')}ms")
|
|
|
|
data = root / "perf.data"
|
|
print(f" sampling {args.seconds}s at {args.freq}Hz ...")
|
|
rec = subprocess.run(["perf", "record", "-F", str(args.freq), "-g",
|
|
"--pid", str(client.proc.pid), "-o", str(data),
|
|
"--", "sleep", str(args.seconds)],
|
|
capture_output=True, text=True)
|
|
if rec.returncode != 0 or not data.exists():
|
|
print(" perf record failed:"); print((rec.stderr or rec.stdout)[-1500:]); return 3
|
|
rep = subprocess.run(["perf", "report", "-i", str(data), "--stdio",
|
|
"--no-children", "--percent-limit", "1.0", "-g", "none"],
|
|
capture_output=True, text=True)
|
|
print("\n=== self time ===")
|
|
for line in rep.stdout.splitlines():
|
|
if line.strip() and not line.startswith("#"):
|
|
print(line[:150])
|
|
return 0
|
|
finally:
|
|
if client:
|
|
client.shutdown()
|
|
import shutil
|
|
shutil.rmtree(root, ignore_errors=True)
|
|
|
|
|
|
if __name__ == "__main__":
|
|
sys.exit(main())
|