WiP: Main loop instrumentation #244

nbraud · 2019-04-29T21:00:08Z

Optionally collect per-frame statistics in the main loop.
Pull in a somewhat-representative example (mutant-games/hugs)
Add automatic-play ability to the example, produce main loop statistics files.
For simplicity, I did it by defining an AISprite variant of PlayerSprite that implements custom behaviour, rather than simulating input events.
Improve automatic play by computing trajectory intercepts (see commit msg in 93ccbc0)
This is entirely unnecessary, but I somewhat nerdsnipped myself.
Process the per-frame statistics into more-useful data (convert to actual runtimes, ...)
Visualise the per-frame statistics
Extend statistics to include GC activity

Pulled in as of commit 1c897126a704fe848469ae8247a3f09e2e5a00a8

This is useful for collecting statistics or running an end-to-end test of PPB.

Also, make the frame's start time be its index in the dataframe

Feather is a binary data format that's lighter in space and processing time.

Possible now that the engine doesn't use an unconventional index

Instead of moving towards the humans, move the AI towards the point where its trajectory will intersect with the human's, assuming constant velocities. The assumption of constant velocities is violated in several ways: 1. the humans have slight, random angular motion, rather than going in straight lines; 2. the humans bounce off the sides of the game area; 3. once the AI gets close enough, the humans get scared, speeding up themselves and the AI. As the intercepts are recomputed at each frame, the random perturbations (1) are smoothly followed by the AI. Unlike those, (2) and (3) are large, punctual changes in velocity; those result in slightly-suboptimal steering (i.e. a better AI could catch up slightly faster) and discontinuities (i.e. the AI suddenly changes direction when its target bounces or gets close enough to be scared).

Previously, the slowest intercept was used, to guarantee that the solution is valid (i.e. t>0, the AI cannot travel backwards in time :P) However, in some configurations, two positive solutions are possible; we now select the smallest such solution (i.e. the fastest intercept).

This gives greater confidence that AISprite.intercept isn't raising ValueError; min() was expected to raise it when `targets` is empty (no runners are left), which happens at the end of the game.

nbraud · 2019-04-29T21:05:23Z

Does the suggested instrumentation design makes sense?

I pulled in pandas, which is a pretty heavy dependency (pulls in numpy and a bunch of other things), which I believe to be reasonable because:

this is entirely optional (only imported when producing statistics) and only useful for developers;
the data analysis script would likely depend on it (or something similar) anyhow, since I'm so not NIHing a statistics & tabular computations package :3

nbraud · 2019-04-29T21:07:04Z

Ohno, the nanosecond counters only exist in Python 3.7 and later :(
I guess I should revert to the float counters?

Nanosecond timers are only available starting with Python 3.7

Currently, we are running the GC every 100th frame; as less basic implementation could use the collection statistics and average GC duration to decide when to run.

Avoid loading the pandas library and interacting with it until the game ends. This results in a 10× performance improvement (with profiling turned on), i.e. a reduction in instrumentation overhead of at least 90%. Moreover, pandas creates reference cycles which need to be cleaned up by the garbage collector, falsifying the GC-related measurements.

Pandas infers the correct datatypes in the first place. Moreover, coercing gc_unreachable from integers to floats is wrong.

Switched to pandas' built-in matplotlib integration.

nbraud · 2019-05-11T23:58:42Z

OK, now that I have visualisation & stats output, I made the most basic control loop for the engine, and there is already a 12-fold improvement in jitter (0.9ms RMS -> 0.075ms RMS) and a large CPU usage reduction (we now spend the vast majority of our time sleeping).

I would suggest the following changes to the PR before merging:

Make engine.main_loop(collect_statistics=True) return a sequence of statistics data objects, remove all (optional) dependencies on pandas from the engine, and instead convert to a pandas dataframe when saving the statistics.
Move main_loop_statistics.py from examples/ to an optional feature, so it can be installed (along with dependencies) by installing ppb[stats] or somesuch.
Start documenting in docs/discussion how the main loop's timing is controlled.

I'd like feedback from @ppb/maintainers before doing all that, though.

Next steps after this PR could be adding GC scheduling (right now it's just being run every 100th iteration), so we can avoid running the GC when short on time, or when we predict no garbage is being produced.

Without control loop (runs as fast as possible)

signal for 2.07902856865076us, std. dev. 1.2948423539554727us
events for 227.00274972899868us, std. dev. 262.62686745205524s
gc for 87.50765258101441us, std. dev. 870.4983390314795us
sleep for 2.5642694571424347us, std. dev. 1.3434179359617922us

Output frame every 0.319141841796805ms (3133.402985863232 fps), std. dev. 0.9098870778953516ms

With control loop (aimed at ~120fps)

signal for 11.737676056137905us, std. dev. 5.277532576202894us.
events for 1234.130141274278us, std. dev. 1063.7694681388045us.
gc for 0.42927634756347627us, std. dev. 0.4182789372143108us.
sleep for 7161.184066404758us, std. dev. 1054.3064573523095us.

Output frame every 8.405620852343532ms (118.9680117110201 fps), std. dev. 0.07588957643094331ms

nbraud added 17 commits April 29, 2019 16:48

engine/main_loop: Add optional timing instrumentation

2de6959

engine: Add missing linebreak at EOF

598c5d5

examples: Pull in hugs.py from mutant-games

ad76339

Pulled in as of commit 1c897126a704fe848469ae8247a3f09e2e5a00a8

examples/hugs: Add a mode where the game plays itself

89ef827

This is useful for collecting statistics or running an end-to-end test of PPB.

examples/hugs: Collect & save statistics in automatic mode

c7e8208

ppb/engine: Switch main loop timers to nanoseconds

5019d7b

Also, make the frame's start time be its index in the dataframe

.gitignore: Add CSV files

8872afc

WiP: Data analysis of the main loop timing statistics

c9429f0

examples/main_loop_stats: Support loading CSV or Feather files

118c822

Feather is a binary data format that's lighter in space and processing time.

main_loop_stats: Stacked area plots for per-frame timings (WiP)

0b21de9

engine: Avoid a non-default index for per-frame statistics

adf4ee5

examples/hugs: Serialize statistics in the Feather binary format

0eb3062

Possible now that the engine doesn't use an unconventional index

examples/hugs: Refactor AISprite.on_update

b7f8888

example/hugs: Refactor AISprite.on_update, don't swallow ValueError

07ac140

This gives greater confidence that AISprite.intercept isn't raising ValueError; min() was expected to raise it when `targets` is empty (no runners are left), which happens at the end of the game.

examples/hugs: Minor readability improvements in intercept()

aa1e341

nbraud requested a review from a team as a code owner April 29, 2019 21:00

nbraud added 2 commits April 30, 2019 12:31

engine: Revert to floating second timers for frame statistics

4f30090

Nanosecond timers are only available starting with Python 3.7

engine: Run the GC at predictable times, save collection statistics

94a15b6

Currently, we are running the GC every 100th frame; as less basic implementation could use the collection statistics and average GC duration to decide when to run.

nbraud mentioned this pull request Apr 30, 2019

Avoid creating reference cycles on every frame #245

Closed

nbraud added 7 commits May 1, 2019 01:47

engine: Avoid unnecessarily coercing dataframe columns

6e0ddaa

Pandas infers the correct datatypes in the first place. Moreover, coercing gc_unreachable from integers to floats is wrong.

Merge branch 'master' into fps-gc-control

37dca7e

examples/main_loop_stats.py: First working version

1f05081

Switched to pandas' built-in matplotlib integration.

examples/main_loop_stats: Support saving the plot to a file

681ff3b

examples/main_loop_stats: Produce interframe jitter chart

ffc5047

examples/main_loop_stats: Output additional fps & jitter information

e17877f

nbraud added 2 commits May 11, 2019 18:09

examples/main_loop_stats: Give phase timing in microseconds

85e0b19

ppb/engine: Cap execution speed to 120 fps

cebb1e8

nbraud mentioned this pull request May 12, 2019

Decouple world updates & rendering #268

Closed

pathunstrom changed the base branch from master to canon June 27, 2020 11:02

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

WiP: Main loop instrumentation #244

WiP: Main loop instrumentation #244

nbraud commented Apr 29, 2019 •

edited

Loading

nbraud commented Apr 29, 2019

nbraud commented Apr 29, 2019

nbraud commented May 11, 2019

WiP: Main loop instrumentation #244

Are you sure you want to change the base?

WiP: Main loop instrumentation #244

Conversation

nbraud commented Apr 29, 2019 • edited Loading

nbraud commented Apr 29, 2019

nbraud commented Apr 29, 2019

nbraud commented May 11, 2019

Without control loop (runs as fast as possible)

With control loop (aimed at ~120fps)

nbraud commented Apr 29, 2019 •

edited

Loading