Animation performance

[trvrb]

Check if there's low hanging fruit to improve animation performance. The 100ms tick can probably be improved for Zika. @colinmegill: How was 100ms tick chosen? Ideally, we want this to tick as fast as render works but no faster.

[colinmegill]

@trvrb am going to do a branch for requestAnimationFrame now that we know we want animations with fixed times, I would expect this to be an improvement.

[trvrb]

Excellent.

[jameshadfield]

Cool. For what it's worth, I think the fixed times should be faster. flu with slow takes 4min to animate on my laptop!

[jameshadfield]

Flu animation render stack time (i.e. the code executed during each setInterval) is around 560ms for me (about 1/3 of the way through the tree). Of this, getLatLongs is running twice and taking 260ms + 175ms. updateStylesAndAttrs (tree) is taking 80ms. Those 3 calls are 92% of the stack time. maybeUpdateDemesAndTransmissions is running at least 3 times.

[trvrb]

I'm getting 220ms frames (4 FPS) for default Ebola animation on production. This looks to be about 100 ms for tree and 100 ms for map. getLatLongs is indeed running twice (taking 20ms each time). updateVisibility is a separate call taking 70ms.

This more what I'm expecting. 3y flu is about as big as Ebola and I'm getting 410ms frames on production. getLatLongs is taking 200 ms (twice). I thought that this might be because this was "country" geo resolution, but we have the same issue with "region" geo resolution when flu has 10 regions and Ebola has 50. Or I guess it has 30 given it's tripled. Okay. This makes sense. If flu is not tripled then performance is similar to Ebola with getLatLongs taking 20ms instead of 200 ms. Tripling demes results in 9x more lines. So 20ms vs 200ms makes sense.

Moving forward I see two obvious ideas:

• Don't fully triple map. We need a "west" copy of Japan, but not a "west" copy of Europe. Need a half copy on the left and a half copy on the right giving 2x demes. I don't know how difficult this would be to implement. Edit: fixed in 6986d7b
• Avoid the duplicate geLatLongs call. Just checked and latLongs is definitely getting called twice via maybeUpdateDemesAndTransmissions every animation loop. Edit: fixed in e405742

There may be internal logic that can get cleaned up as well.

[trvrb]

Commit e405742 fixes the duplicate latLongs call. This was happening because componentDidUpdate fires twice after updating dateMin or dateMax. One firing because of props.controls and then a second firing once tree finishes updating it's visibility. I'll merge this commit but we can keep working on the issue.

[trvrb]

Digging in more I see two avenues for substantial improvement. Slow calls are getLatLongs and updateVisibility. The two take up almost 100% of the animation redraw.

- getLatLongs - EDIT: see #392

The thing that takes up all the time is this loop:

https://github.com/nextstrain/auspice/blob/master/src/util/mapHelpersLatLong.js#L130

For each of 3 offsets x each of ~500 transmission events x 3 offsets = ~4500 calculations each cycle for flu. These are basically the same calculations being done each cycle. The output is just for each transmission (that has an origin and a destination) compute the lat/long of the origin and the lat/long of the destination. offsets (due to map tripling) result in duplicating transmissions at different lat/longs.

However, this information only needs to be computed on load. We have a list of all transmissions in the tree (regardless of visibility) for the specified geoResolution. Can pre-compute this transmission list (with lat/longs) on load from the full tree. Store this in map state. Then each render cycle, just find the visible transmissions in this list. Will be immensely faster.

- updateVisibility - EDIT: see #381

This is slow because Bezier is recomputed every render cycle. The Bezier points are fixed through the animation. They can be pre-computed on load as well. It's just the set of drawn points along this curve that changes each render cycle.

https://github.com/nextstrain/auspice/blob/master/src/util/mapHelpers.js#L29

I would propose to store Bezier curves within each transmission object in map state. Then when running extractLineSegmentForAnimationEffect just pull the appropriate set of points.

[jameshadfield]

After merge of PR #377 the code execution of map is much improved:

EDIT: this may or may not be the truth.... performance tools paints a very different story - see below comment

setInterval stack start
map CWRP starting
map CWRP finished
map CDU starting
map CDU finished
map CWRP starting
map CWRP finished
map CDU starting
maybeUpdateDemesAndTransmissions running
getLatLongs running
map CDU finished
setInterval stack finished

As noted by @trvrb, changeDateFilter results in 2 actions (see #348) - it may be possible to combine these into 1, however the above console.logs show that all the maybe functions in map are exiting appropriately so it's probably not going to make a dramatic difference.

[jameshadfield]

Current status of flu @ 006b892

Putting console log statements in the setInterval block led me to believe that (e.g.) maybeUpdateDemesAndTransmissions was only running once, however the above screenshots indicate a different story. There appear to be 7 dispatches, but this is misleading as thunks wrap code in the dispatch function - i.e. there are not 7 actions dispatched.

Tick compute time: 475ms

• setState on some component: 16ms (unsure which component)
• calcVisibility: 7ms (inside thunk)
• (tree) updateStylesAndAttrs: 14ms (via componentWillRecieveProps)
• EDIT: the following will disappear once improve initial tree colour logic #384 is fixed
• (tree) updateStylesAndAttrs (again!): 121ms (via componentWillRecieveProps)
  • calcStrokeCols: 74ms
• (tree) updateStylesAndAttrs (a third time!): 31ms (via componentWillRecieveProps)
  • mapToScreen: 25ms
• maybeUpdateDemesAndTransmissions: 16ms (via componentDidUpdate)
• maybeUpdateDemesAndTransmissions (again): 111ms (via componentDidUpdate)
  • getLatLongs: 34ms
  • updateVisibility: 77ms (incl Bezier calcs)
• maybeUpdateDemesAndTransmissions (a third time): 138ms (via componentDidUpdate)
  • updateVisibility: 138ms (incl Bezier calcs)

[trvrb]

This is excellent. Thanks James. I believe maybeUpdateDemesAndTransmissions was getting called multiple times for flu but not for Zika.

[jameshadfield]

Summary of things to do now:

• stop unnecessary tree colorBy changes improve initial tree colour logic #384
• single dispatch during tick single dispatch during animation tick  #385
• precompute leaflet lat long objects precalculate LatLongs #392
• precompute bezier curve arrays
• don't update SVG transmissions not in view
• debounce mapToScreen Debounce or otherwise improve mapToScreen #387
• look into CSS updates understand / speed up react CSSPropertyOperations.js #393

[jameshadfield]

Recalculate Style (CSSPropertOperations.js?...) takes around 30ms on flu - anyone know what this is from? Radium?
Broken out into an issue #393

[jameshadfield]

Profile as of master 1f07afc (single dispatch during tick, no unnecessary tree colorBy updates)

EDIT: updated to use non-development builds (very, very different!)

Profile in development mode:

Profile in production mode:

A single action is always being dispatched through the reducer (confirmed, to the best of my ability, via console logs -- see #389 (comment)). It's harder to see what functions are being called, as they are renamed in the production code, but on the development builds, maybeDemesAndTransmissions is called between 1 and 7 (!) times (it varies between ticks). I'll leave it to @colinmegill to track down the cause (issue #391), but I'm very interested in why it's doing this.

Testing at http://localhost:8080/flu/h3n2/ha/6y?c=region&dmin=2013-09-20&r=region, ticks take between 180 and 200ms plus around 25ms to recalculate CSS styles. It appears that

• Almost the entire time is spent inside (tree) updateStylesAndAttrs, (map) maybeUpdateDemesAndTransmissions and the the recalculation of CSS styles.
• calculateVisibilityAndBranchThickness (in the action creator) takes around 5ms
• (tree) updateStylesAndAttrs takes around 25ms
  • phyloTree.mapToScreen is around 50-80% of this
• the rest of the time is (I think) in maybeUpdateDemesAndTransmissions - ~150ms
  • lots of time is spend performing Garbage Collection - could this be improved?

At http://localhost:8080/zika?dmin=2015-10-03 ticks take around 40ms 🎉 🎉 , plus around 10ms to recalculate CSS styles. It appears that

• calculateVisibilityAndBranchThickness (in the action creator) takes around 1ms
• (tree) updateStylesAndAttrs takes around 8ms
• maybeUpdateDemesAndTransmissions takes around 25ms

[jameshadfield]

I've been investigating React Peformance Tools - https://facebook.github.io/react/docs/perf.html - and have implemented on the branch react-perf to display the time taken in each component during an animation tick. Note: React and some other libraries needed updating, so you'll have to run npm install.

Time spent during each animation tick (on flu, link above):

Not sure if I can get it to break Map apart more, and the times taken to render are somewhat meaningless (as we manipulate the DOM ourselves), but this is a quantitative way by which we may examine performance.

[trvrb]

Cool. Thanks for adding this James. Do you have a TLDR version of getting this readout?

[jameshadfield]

# be prepared for npm issues
git checkout react-perf
npm install
node dev-server.js
# play animation and look at console

don't forget to run npm install after going back to master

[jameshadfield]

As of 69158da the animation speed is much improved - now it really looks as if the tree is the bottleneck

[trvrb]

If we debounce mapToScreen (#387) and fix Bezier redrawing (#381) I think we'll be close to 50ms for Ebola which is where I'd like to be.

[trvrb]

Commit 4e1119b has mapToScreen debounced (#387) and Bezier fixed (#381). This is showing hugely improved performance. Original map PR (at 31516f2) had Ebola with 115ms render (plus 15ms repaint):

Current animation has Ebola with 15ms render (plus 15ms repaint):

So, we just need to clean up the last remaining issues in fix Bezier (#381) so it can be merged (edited). And then separately we need to switch to requestAnimationFrame (#404). With #381 and #404 in place this issue will be resolved and animation can launch.

[trvrb]

I'm going to close this now. With #381 and #387 in place animation performance is what it should be. I'm considering animation timing (#404) a separate issue.