Playback wrapper lag - Githubissues

KatieWoe commented 3 years ago

For https://github.com/phetsims/qa/issues/662. Same issue as https://github.com/phetsims/molecule-shapes/issues/177 and https://github.com/phetsims/gravity-and-orbits/issues/376. Seems to be to a larger degree.

When you play back a recording the playback wrapper will pause and speed up at certain places. All events are still recorded and this does not seem to be impacted by either the platform that made the recording or the one playing it back. On NS, the pauses seem particularly long and are concentrated between generations. These pauses were not necessarily there when the recording was made.

pixelzoom commented 3 years ago

As I said in https://github.com/phetsims/qa/issues/662#issuecomment-873165491:

I'm not familiar with what the performance expectations are, or how performance might have changed due to recent PhET-iO changes. So please assign the issue to the PhET-iO team for evaluation.

zepumph commented 3 years ago

This is a known problem, and playback performance has never been a blocking issue up to this point.

KatieWoe commented 3 years ago

Yup. I only made an issue this time since it seemed to impact this sim more than others.

pixelzoom commented 3 years ago

We realize that performance has not been a blocking issue up to this point. But @KatieWoe has reported "particularly long" pauses, which may or may not be related to recent PhET-iO changes. So perhaps the PhET-iO team should take a look, compare 1.4 to 1.5, and decide whether the performance is still non-blocking.

zepumph commented 3 years ago

I did some investigation here, testing performance of NS on master with localFile recording and playback

My testing in general created a recording that loosely followed the steps to reproduce over in https://github.com/phetsims/studio/issues/223#issuecomment-875086340. That is a great way to get a stable population with quite a few bunnies churning through.

My first test recorded with assertions enabled (?phetioDebug), and I found that ~10% of the laggy bits are taken up with two actions. First is validation inside of merge calls, and the second is Display.assertSubtreeDisposed. These two seem reasonable and obvious to me, since we are creating/destroying something like 500 Bunnies in a single step.
Next I turned off assertions and tested again. I found that a large amount of time in general was being taken up from this line of progress-bar update, commit above to remove ~1.5 seconds of time from my 30 seconds of performance audit.
Then in the same recording I took a look at the single frame between gen 4 and 5 when bunnies are created. Below is a snapshot of just that frame. I noted it because it self identified as a "long task" in chrome dev tools that took 130s. Below note that ~9% is taken up from merge. I'm unsure how to solve that. Another ~9% is coming from Imageable hit testing. I'm surprised to see that, and I was wondering if that from a recentish change to use sprites for the Bunnies etc. @pixelzoom do you think that is worth some investigation?

All in all I see nothing obvious or blocking-worthy in my investigation, but I also noted that it takes multiple seconds to create the bunnies for the next generation. That could be a usability concern in some contexts I think, but it also didn't feel that different or new from other, previous recordings of the same content.

My vote would be to have @pixelzoom speak to sprite performance, @samreid review this investigation and offer his opinion, and then, if all agree, close in lieu of uprooted entrenched patterns like merge or something to gain better performance.

pixelzoom commented 3 years ago

Another ~9% is coming from Imageable hit testing. I'm surprised to see that, and I was wondering if that from a recentish change to use sprites for the Bunnies etc. @pixelzoom do you think that is worth some investigation?

NS has been using Sprites since 7/20/20, so this is not a recent change. @jonathanolson and I spent a lot of time performance optimizing, and sim performance has been excellent. Since there seems to be a consensus that performance of the State wrapper isn't really important, I'm not inclined to put more work into optimizing Sprites, or NS's use of Sprites.

zepumph commented 3 years ago

@kathy-phet and the gang determined this to not be blocking today.

Next steps for testing:

Does this lag occur in mirror inputs. @samreid mentioned that this wasn't laggy in his testing.
Is handlePlaybackEvent looking through many more messages than it needs to? Maybe we can prefilter non-playback messages eagerly so that during playback we don't look through unneeded events.
@jonathanolson mentioned that other sims he has worked on have been laggy in the playback wrapper, perhaps molecule-shapes.

@samreid and I will take it from there.

samreid commented 3 years ago

@zepumph can you please try this patch? It's working great over here:

```diff Index: playback/js/playSession.js IDEA additional info: Subsystem: com.intellij.openapi.diff.impl.patch.CharsetEP <+>UTF-8 =================================================================== diff --git a/playback/js/playSession.js b/playback/js/playSession.js --- a/playback/js/playSession.js (revision 153a7c8131cf160cc0d138f0706667e287293dae) +++ b/playback/js/playSession.js (date 1625765570436) @@ -145,9 +145,15 @@ const desiredNextPlaybackTime = recordedStartTime + seekTimeMS + elapsedTime * speed; const timeout = Math.max( nextEvent.time - desiredNextPlaybackTime, 0 ); - // Invoke the next event at the right time. - const id = setTimeout( () => playEvent( eventIndex + 1 ), timeout ); - window.phetio.wrappers.playback.scheduledPlaybackIntervals.push( id ); + if ( timeout > 0 ) { + + // Invoke the next event at the right time. + const id = setTimeout( () => playEvent( eventIndex + 1 ), timeout ); + window.phetio.wrappers.playback.scheduledPlaybackIntervals.push( id ); + } + else { + playEvent( eventIndex + 1 ); + } } ); }; ```

samreid commented 3 years ago

I tested more and checked the usages sites of scheduledPlaybackIntervals and this seems good enough to push.

samreid commented 3 years ago

I committed the change and added a guard to prevent stack overflows. @zepumph can you please review? @KatieWoe can you please test on master?

KatieWoe commented 3 years ago

Looks much smoother on master

zepumph commented 3 years ago

Looks really great to me, over to @pixelzoom to cherry pick. @samreid will you want to do the same for GAO?

samreid commented 3 years ago

Yes, I'll update gravity and orbits in https://github.com/phetsims/gravity-and-orbits/issues/404, thanks!

pixelzoom commented 3 years ago

Please summarize what needs to be cherry-picked. I'm guessing https://github.com/phetsims/phet-io-wrappers/commit/46731109c30c64c32ca7676c8146bd91fa88db32 and https://github.com/phetsims/phet-io-wrappers/commit/ee6afb8256d7fffd74ff50da28d54ca50c1995e2.

samreid commented 3 years ago

Yes, but please cherry-pick them in chronological order:

https://github.com/phetsims/phet-io-wrappers/commit/ee6afb8256d7fffd74ff50da28d54ca50c1995e2 https://github.com/phetsims/phet-io-wrappers/commit/46731109c30c64c32ca7676c8146bd91fa88db32

KatieWoe commented 3 years ago

Steps to Reproduce a Recording:

From the index, open the recording wrapper
Open the console
In the url, replace ?console with ?localFile and press enter/reload
In the sim, do actions you want to record (In this case let a few generations pass and/or let bunnies take over world)
In console, follow instructions to save file (window.saveLogToFile("name");)
From the index, open the playback wrapper
Load the file ("name") and play

pixelzoom commented 3 years ago

Thanks @KatieWoe. I tested the fix by recording a stable population up to Generation 9. It's running smoothly. Patched in the 1.4 branch in the above commits. Ready for testing in the next RC.

KatieWoe commented 3 years ago

I think this can be closed for rc.2. Will reopen if something else comes up

phetsims / natural-selection

Playback wrapper lag #297