How it works · write-up

Profiling Xenon 2 autoplay and replay

xenondoc/PROFILING.MD · 11 KB · updated 2026-09-17

Updated 2026-09-02. Prefer offline recordings: no emulator, input injection, snapshot restore, or new gameplay is needed. Keep outputs under xenon_tools/run_logs so they are not checked into Git.

For complete new captures use validate_campaign.py run NAME; see CAMPAIGN_VALIDATION.MD. After stopping, validate_campaign.py profile NAME --from-frame N --to-frame M --cprofile automatically supplies the archived starting controller state and per-level RAM terrain seeds. It writes timings and .pstats under NAME.validation, without connecting to Hatari. Omit --cprofile for a lower-overhead timing pass.

The three different costs

Do not equate any one with the entire displayed frame duration. cProfile adds substantial overhead to Python's many small geometry calls. Use a non-profiled pass for milliseconds/frame and a profiled pass for attribution.

1. Find slow live frames cheaply

Live runs already log decision_ms when --trace is enabled. No need to replay every frame just to locate the slowest cases. The new tool retains small timing records rather than loading every large object list into memory.

Campaign runs now also warn during recording when decision_ms reaches --slow-frame-ms (default100). validate_campaign.py slowdowns NAME lists periods, their first/last slow game frames, peak decision time/frame, and the checkpoint preceding their onset. Warnings are grouped until ten consecutive fast frames; continuing warnings are throttled to once per five seconds. The compact index is NAME.validation/slowdowns.jsonl. No rendering/AVI timer or additional checkpoint saves are involved. All individual decision times remain in the full JSONL even when console warnings are throttled.

python xenon_tools\profile_autoplay.py summary xenon_tools\run_logs\level5-tank-core-committed-escape-validation-0902-201.jsonl --top 10 --output xenon_tools\run_logs\tank201-timing-summary.json

Output includes mean, median, p95, maximum, the slowest game-frame numbers, and groups ranked by total time for (tactic, movement_authority). A single huge frame and a moderately expensive branch called hundreds of times are different optimization targets. Absent timings are not interpreted as zero time.

Measured live run201 baseline (600 canonical frames): mean 203.66 ms, median 116.49 ms, p95 673.11 ms, maximum 987.00 ms at frame92081. Frames with level5_tank_core / survival:space_time_beam consumed 58.11 seconds total; core_reveal / the same authority consumed another34.06 seconds. Even ordinary strategic frames averaged about110 ms, so missile search alone cannot explain all the latency. This is not adequate real-time performance.

2. Reconstruct offline with per-frame timings

python xenon_tools\profile_autoplay.py replay xenon_tools\run_logs\level5-tank-core-committed-escape-validation-0902-201.x2events --from-frame 92080 --to-frame 92100 --controller-state xenon_tools\run_logs\level5-tank-early-regional-validation-0902-198.sav.autoplay.json --output xenon_tools\run_logs\tank201-offline-timing

This writes .timings.jsonl and .summary.json. Each timing row has canonical frame, zero-based recording index, elapsed processing time, tactic, movement owner and object counts. There is no Tk window. The original Recording and ReplayModel classes are reused, not a second perception implementation.

The controller sidecar must be from immediately before this recording, not its ending save. The runner sequentially warms all earlier frames before --from-frame without profiling them; it never skips directly to a late frame with an empty controller and calls that an equivalent run. Omitting the sidecar is allowed but means cold-policy reconstruction. Requested frame bounds must exist; the tool refuses silent nearest-frame substitution.

Progress is printed at most once a second and reaches100% at the destination. The runner keeps one cached state, avoiding UI history-cache memory growth.

Limits of offline equivalence

Replay proposes actions but does not apply them to subsequent recorded states. It profiles the analysis of the observed trajectory, not a counterfactual playthrough. Older recordings cannot reproduce live's one-time full-RAM destructible sync unless that state is observed in the recording. New campaign captures archive those seeds: use --terrain-manifest NAME.validation/terrain.json with the lower level tool (the campaign profile command adds it automatically). The same map sync is applied at its recorded game frame, once per seed, before choosing an action. The current ReplayModel still does not inject the live driver's future FirePulse schedule into speculative side-shot defense, and uses the analysis shop branch rather than the full live ShopController dispatch. This can change candidate search work. Accordingly, compare live JSONL and offline function profiles, do not claim their decisions or timing will match exactly. These are known handoff issues, not reasons to build yet another prediction model.

For shop animation/UI latency, this headless tool only isolates reconstruction. If it is fast but the UI is slow, profile replay_ui.py itself while opening the same range; that includes Tk, atlas drawing and optional AVI decoding.

3. Attribute the hotspots to functions

Repeat the same command with --cprofile and a different output prefix:

python xenon_tools\profile_autoplay.py replay xenon_tools\run_logs\level5-tank-core-committed-escape-validation-0902-201.x2events --from-frame 92080 --to-frame 92100 --controller-state xenon_tools\run_logs\level5-tank-early-regional-validation-0902-198.sav.autoplay.json --cprofile --output xenon_tools\run_logs\tank201-offline-profile

This also writes .pstats and prints the top cumulative-time functions. cumtime includes children; tottime is the function's own work. Do not sum parent and child cumulative times as though they were independent costs.

The checked example profile from this command is xenon_tools/run_logs/tank201-offline-profile.pstats. For the21 measured frames:

The immediate finding is whole-map grid generation/query work, not just A* or sprite rendering. _ensure_navigation_grid was called3772 times and uses the revision/geometry/collision-sprite cache; investigate actual cache misses, revision changes, and repeated geometry variants before changing search width. Within survival, missile/side-bullet branch evolution is the other major cost. These profile values have instrumentation overhead and are not a new live FPS measurement. No navigation or safety horizon was weakened to obtain them.

The companion non-cProfile offline run of those21 frames measured451.55 ms mean, 223.15 ms median and1359.13 ms p95 (including cold reconstruction and different replay work). Its outputs are tank201-offline-timing.*. These absolute values are not comparable to the600-frame live distribution above; preserve the same interval and warm-up for any before/after optimization.

The old profile_autoplay_frame.py is still available for an approximate single-frame microprofile. It cheaply rebuilds perception but calls choose only once with a fresh/restored controller. It does not warm policy through the preceding decisions; use the sequential tool above for authoritative replay profiling, especially committed escapes and retained routes.

Visual viewers

For these .pstats files, use SnakeViz. It reads cProfile output and provides interactive icicle/sunburst call views plus sortable function tables. Installation is optional; no third-party profiler dependency is added to autoplay. SnakeViz documentation.

python -m pip install snakeviz
snakeviz xenon_tools\run_logs\tank201-offline-profile.pstats

For lower-overhead stack sampling and a file that can be opened in Speedscope, use py-spy around the same offline command, without --cprofile:

py-spy record --format speedscope -o xenon_tools\run_logs\tank201.speedscope.json -- python xenon_tools\profile_autoplay.py replay xenon_tools\run_logs\level5-tank-core-committed-escape-validation-0902-201.x2events --to-frame 92100 --controller-state xenon_tools\run_logs\level5-tank-early-regional-validation-0902-198.sav.autoplay.json --output xenon_tools\run_logs\tank201-sampled

Open the result in Speedscope. py-spy samples an external process and supports this output format; platform permissions may be required. The outer sampler includes setup/warm-up too, unlike the scoped cProfile interval. py-spy documentation. Do not feed binary .pstats directly to Speedscope.

Optimization gate

1. Record the exact source revision, Python version, atlas assets, checkpoint, recording interval, sidecar and profiling mode.
2. Find both recurring cost and pathological p95/max frames.
3. Change one cache/allocation/batched-geometry issue while preserving the collision and movement model. Do not trade away hazard horizon as a hidden performance fix.
4. Run the identical non-profiled offline interval at least twice before/after. Compare actions, targets, route validity and contact predictions as well as milliseconds. A faster different decision is not automatically an optimization.
5. Run synthetic regressions and one normal-speed live validation with events and both AVIs. Cheat tests prove exploration progress, not ordinary survival.

Tests: python -m unittest discover -s xenon_tools -p test_profile_autoplay.py.