Benchmark RouteLineApi and RouteLineView

[LukasPaczos]

Refs https://github.com/mapbox/mapbox-navigation-android/issues/4091. Capturing from a customer report, the refactored stack of MapboxRouteLineApi -> MapboxRouteLineView -> Map regressed in performance.

When I have a route Munich -> Madrid with 2 alternatives then switching between alternatives takes 4 seconds on 1.0 on 2.0 it takes over a minute

We should benchmark the stack in a couple of places and compare it with v1:

• What's the performance of parsing geometries and creating expressions in the MapboxRouteLineApi?
• What's the performance of switching the primary route and returning the selected one in the MapboxRouteLineApi?
• What's the performance of updating GeoJson sources in the MapboxRouteLineView? (refs https://github.com/mapbox/mapbox-gl-native/pull/12580 which is not yet ported to the Maps SDK v10 and can cause UI thread freezing)
• How long does it take to render the geometries?

/cc @mapbox/navigation-android @mapbox/maps-android @moritzzzzz

[tobrun]

refs mapbox/mapbox-gl-native#12580

I reverse linked the issue that should solve this.

[cafesilencio]

Here are some initial numbers:

Initiated a route(s) from San Francisco to Manhattan, N.Y. The numbers below are only for the calculation of the data to be rendered on the map. The rendering of the result isn't included in these numbers.

2.x before recent performance enhancement attempts - vanishing route line enabled average time for initial route(s) calculation: 949ms average time for selecting alternative route: 1165ms

2.x after recent performance enhancement attempts - vanishing route line enabled average time for initial route(s) calculation: 1246ms average time for selecting alternative route: 1098ms

Not much difference but the calculations are done on background threads so that is progress.

2.x after recent performance enhancement attempts - vanishing route line disabled average time for initial route(s) calculation: 146ms average time for selecting alternative route: 45ms

There's an easy remedy for this. Currently there are several computations on background threads. The computation to initialize the vanishing route line is resource intensive but there's no need to wait for it to complete in my opinion. The computation isn't needed to draw the lines. IMO we can fire and forget it because the result is not needed until the first route progress is received. Between the route draw calculation and the first route progress event the app has to draw the line(s) and the user has to initiate navigation. On an extremely long route like from SF to NY this takes on average 1 second so there's little risk that this task wouldn't be completed by the time the first route progress is received. Even if the first route progress arrives before the task has completed nothing breaks. It just means the very first route progress update doesn't update the vanishing route line but it will update the next route progress 1 second later. There is a PR for this solution here: https://github.com/mapbox/mapbox-navigation-android/pull/4209

2.x after recent performance enhancement attempts - vanishing route line enabled ( NO WAIT ) average time for initial route(s) calculation: 168ms average time for selecting alternative route: 53ms

These numbers are in line with the vanishing route line being disabled.

cc @LukasPaczos

[LukasPaczos]

@cafesilencio what about benchmarking against v1? Do we see any regressions?

[cafesilencio]

I haven't had a chance to get v1 numbers yet. Given the overwhelming bottleneck is the initialization of the vanishing route line and that code hasn't changed I don't think there will be a big difference in the numbers. I will however add them here soon.

[cafesilencio]

Here are some updated numbers based on PRs #4222 and #4209:

Average time to calculate draw data (setRoutes) for initial route across the U.S. 145ms

Average time to calculate draw data (setRoute) after choosing an alternative route across U.S. 28ms

Average time to update the map with the draw data: 420ms This one is out of our control as we're just making calls to the map SDK with data. We're not calculating anything. This includes setting the geojson source on at least 2 route lines and setting the traffic line gradients as well.

[LukasPaczos]

Tagging @mapbox/maps-android for optimization ideas.

[cafesilencio]

I can provide a data sample that is being sent to maps if that's helpful.

[LukasPaczos]

@cafesilencio what was your methodology for measuring the performance?

I'm testing on top of https://github.com/mapbox/mapbox-navigation-android/pull/4209, and I can still see a route from Poland -> Spain, which is much shorter than across the U.S. that still takes seconds to get rendered initially, and even more when selecting alternatives:

https://user-images.githubusercontent.com/16925074/114174562-1043da80-9939-11eb-8c0c-3bb681ced858.mp4

On the video (don't mind the dropped frames) you can see that drawing the routes takes ~9 seconds while selecting alternatives ~20 seconds. Granted that I didn't dive into the example activity to optimize it very much, this is still far off from the measurements you've been seeing.

[LukasPaczos]

I'm noticing that when drawing a route, a huge amount of time is spent slicing the arrays and copying objects between them:

The same is true for the other thread in the thread pool that we're using. I'll try to see if there's an optimization that we could apply.

[LukasPaczos]

The results that we're seeing after applying the changes from #4222, #4209 and https://github.com/mapbox/mapbox-navigation-android/pull/4244 for a route from Wrocław in Poland to Seville in Spain:

	generating a route	selecting an alternative
Before	~10.5s	~24.5s
After	~0.3s	~0.2s

On top of the above measurements, we have ~0.5s of rendering latency, which I think fluctuates depending on the viewport position.

The latency is also significantly impacted by the presence of alternative routes, which now also contain traffic that needs to be parsed. We might want to consider exposing a method to disable or lazily load traffic segments for alternative routes that can be applied in performance-critical use-cases.

We should also stack the current implementation against v1 to ensure there are no additional regressions.

[cafesilencio]

One thing I noticed is the sequence of events when selecting an alternative route can result in duplication of route line related calculations and rendering.

After selecting an alternative route it's necessary for a developer to call the method updateToPrimaryRoute() to indicate the primary route has changed. This necessarily needs to update the state of the of the MapboxRouteLineApi class and returns the data so that the route line(s) can be re-rendered on the map. It's also necessary to update MapboxNavigation with a call to setRoutes(). However if a developer has a RoutesObserver and is initiating a draw of the routes in the onRoutesChanged() method then the calculation of the route drawing and rendering is done twice. Once as a result of choosing a new primary route and in response to the MapboxNavigation::setRoutes via the RoutesObserver::onRoutesChanged. A partial way to handle this is to not do the rendering of the route data in alternate route selection callback. This will avoid rendering the data twice but not the route calculations.

At first I thought the way to handle this would be to unregister the RoutesObserver -> update the routes in the MapboxRouteLineApi and render the result -> call setRoutes() on MapboxNavigation -> re-register the RoutesObserver. This doesn't work because registering the RoutesObserver will immediately call the new observer with the last data it received thus initiating a redraw of the route line.

This only becomes a major factor when drawing an extremely long route however in the interest of not wasting compute resources this duplicate calculation and redrawing should be avoided. With that said, I think the MapboxRouteLineApi is operating correctly, responding to the api calls being made without having knowledge of the world outside of itself. At the moment I'm not sure what solution we should pursue, but given this is a performance focused ticket I wanted to communicate my observation.

IMO the RoutesObserver shouldn't emit past events to new observers but this behavior has been in place since 1.x.

Perhaps the route line class should cache the results of it's calculations and if setRoutes is called with the same routes it already has it can return the cached results. It would still be up to the developer to render or not render the results accordingly.

cc @LukasPaczos

[cafesilencio]

UPDATE: This thread gets quite long as I worked through the testing of various performance improvements. Rather than delete the posts I've left them for context but for the conclusion skip to the last post by myself.

After some further investigation I found some interesting behavior related to my previous post but I don't yet have an explanation. I did some granular testing on the individual calculations performed when calculating the route related data. The initial set routes calculation happens in a short time using a route across the U.S. When selecting an alternative route the calculations for the route lines are done twice as I explained in my previous post. I noticed that for some reason the second calculation takes a very long time compared to the others.

The individual calculations are done like this:

val deferredResult = async(ThreadController.IODispatcher) {
...
}

There's something about using ThreadController.IODispatcher that is causing the slow down. If I replace ThreadController.IODispatcher with any other dispatcher the slow down doesn't occur.

Here are some results from the logs. All times are in ms.

-- current code base async(ThreadController.IODispatcher) -- initial set routes -- total calc time routeFeatureDataDefTotal: 61 total calc time trafficLineExpressionDefTotal: 64 total calc time routeLineExpressionDef: 1 total calc time routeLineCasingExpressionDef: 2 total calc time alternativeRoute1TrafficExpressionDef: 25 total calc time alternativeRoute2TrafficExpressionDef: 1 total calc time wayPointsFeatureCollectionDef: 0 total calc time: 159 total draw time: 375

-- select update to primary route -- total calc time routeFeatureDataDefTotal: 6 total calc time trafficLineExpressionDefTotal: 5 total calc time routeLineExpressionDef: 0 total calc time routeLineCasingExpressionDef: 1 total calc time alternativeRoute1TrafficExpressionDef: 3 total calc time alternativeRoute2TrafficExpressionDef: 0 total calc time wayPointsFeatureCollectionDef: 0 total calc time routeFeatureDataDefTotal: 5 total calc time trafficLineExpressionDefTotal: 3

-- set routes from RoutesObserver::onRoutesChanged total calc time routeLineExpressionDef: 1265 <--Look at this total calc time routeLineCasingExpressionDef: 0 total calc time alternativeRoute1TrafficExpressionDef: 3 total calc time alternativeRoute2TrafficExpressionDef: 1 total calc time wayPointsFeatureCollectionDef: 0 total calc time: 1279 total draw time: 201

The increase in time for routeLineExpressionDef isn't specific to this calculation. If I change the dispatcher for this async calculation the next one routeLineCasingExpressionDef will have the large number next to it. See below for the differences.

For the calculations below the ThreadController.IODispatcher was removed so the async calls were on the main thread but non-blocking:

val deferredResult = async {
...
}

-- initial set routes -- total calc time routeFeatureDataDefTotal: 62 total calc time trafficLineExpressionDefTotal: 41 total calc time routeLineExpressionDef: 0 total calc time routeLineCasingExpressionDef: 1 total calc time alternativeRoute1TrafficExpressionDef: 24 total calc time alternativeRoute2TrafficExpressionDef: 1 total calc time wayPointsFeatureCollectionDef: 1 total calc time: 136 total draw time: 351

-- select update to primary route -- total calc time routeFeatureDataDefTotal: 6 total calc time trafficLineExpressionDefTotal: 5 total calc time routeLineExpressionDef: 1 total calc time routeLineCasingExpressionDef: 0 total calc time alternativeRoute1TrafficExpressionDef: 4 total calc time alternativeRoute2TrafficExpressionDef: 1 total calc time wayPointsFeatureCollectionDef: 0

-- set routes from RoutesObserver::onRoutesChanged total calc time routeFeatureDataDefTotal: 6 total calc time trafficLineExpressionDefTotal: 3 total calc time routeLineExpressionDef: 0 <-- no drastic time increase total calc time routeLineCasingExpressionDef: 1 total calc time alternativeRoute1TrafficExpressionDef: 2 total calc time alternativeRoute2TrafficExpressionDef: 1 total calc time wayPointsFeatureCollectionDef: 0 total calc time: 15 total draw time: 242

Notice there is no drastic increasing in the execution times. The caching that was implemented is working.

With the numbers below I created a dispatcher with a thread pool size of 1 similar to the way ThreadController does. The async calculations look like:

val deferredResult = async(RouteLineDispatcher) {
...
}

-- initial set routes -- total calc time routeFeatureDataDefTotal: 55 total calc time trafficLineExpressionDefTotal: 45 total calc time routeLineExpressionDef: 0 total calc time routeLineCasingExpressionDef: 0 total calc time alternativeRoute1TrafficExpressionDef: 25 total calc time alternativeRoute2TrafficExpressionDef: 0 total calc time wayPointsFeatureCollectionDef: 1 total calc time: 131 total draw time: 328

-- select update to primary route -- total calc time routeFeatureDataDefTotal: 6 total calc time trafficLineExpressionDefTotal: 3 total calc time routeLineExpressionDef: 1 total calc time routeLineCasingExpressionDef: 0 total calc time alternativeRoute1TrafficExpressionDef: 4 total calc time alternativeRoute2TrafficExpressionDef: 0 total calc time wayPointsFeatureCollectionDef: 0

-- set routes from RoutesObserver::onRoutesChanged total calc time routeFeatureDataDefTotal: 6 total calc time trafficLineExpressionDefTotal: 10 total calc time routeLineExpressionDef: 1 <-- no drastic time increase total calc time routeLineCasingExpressionDef: 0 total calc time alternativeRoute1TrafficExpressionDef: 3 total calc time alternativeRoute2TrafficExpressionDef: 1 total calc time wayPointsFeatureCollectionDef: 0 total calc time: 22 total draw time: 255

Notice again there's no drastic increase in the calculation times. I've also tested with Dispatchers.IO with the same results (no drastic increase in calculation times.)

I don't have an explanation for this but as a next iteration for improving performance I suggest creating a dispatcher in the route line API class with a thread pool of 1 and using it instead of the IO dispatcher in ThreadController.

The branch I was working with is sb-route-line-perf-improvements.

[cafesilencio]

After further testing I think the cause of the anomalous calculation described above is contributed to by the vanishing route line initialization. When I disable the vanishing route line in the options I don't see the extremely long calculation time. The IODispatcher in ThreadController has a pool size of 2. So this double calculation scenario I described is resulting the vanishing route line being initialized twice. This long running calculation operates using the IODispatcher and takes up both threads in the pool.

[cafesilencio]

After some further testing I find that if I move the vanishing route line initialization to the end of the setRoutes calculations then the problem is solved. The other calculations needed for the route drawing get done and then the vanishing route line initialization gets fired and forgotten allowing the route line redrawing to occur without delay.

When there's a double call the first vanishing route line init call gets cancelled and the calculation only gets done once. I'll prepare a PR with these modifications for review and comment.

Sorry for the verbose thread but at least there's context.

[cafesilencio]

Update: Currently in the 2.x code for a route from San Francisco to N.Y. I'm seeing: average time to calculate routes (set routes): 200ms average time to calculate routes when selecting alternative route: 29ms average time to render route data (map): 274ms

For 1.x I see an average time to calculate routes (set routes): 33ms. However, this doesn't include the traffic line calculations. This is done in a coroutine so the call to calculate the traffic gradient is non-blocking. This is taking on average 2171ms.

1.x has the appearance of being faster because the initial route line is drawn and the traffic gradient applied later. In 2.x all of the calculations are done before returning the result to be rendered. In addition 2.x is calculating much more like alternative traffic gradients as well as road closures and restricted road areas.

Notice the orange traffic indication to the upper left of the label "Newark". When the alternative route is selected the alt. route gets the same traffic indication because it hasn't been reset yet. A moment later the gradient is updated and the orange section disappears. When the original primary route is selected again it turns blue quickly but it takes a moment for the orange traffic section to appear.

[LukasPaczos]

Thanks for the investigation @cafesilencio! This would confirm the suspicion that the same improvements done in https://github.com/mapbox/mapbox-navigation-android/pull/4244 could be applied to the v1 codebase. The slowdown just wasn't apparent due to the async loading of the traffic segments.

Do you think there could be a way for us to reintroduce the lazy/async traffic loading in v2? Perhaps as an option? Another method? It looks like we would be able to cut the time to render some data (route without traffic) by nearly half by doing so.

[cafesilencio]

Yes. Right now the API class generates the expression and returns it in the result which is rendered by the view. My idea is to return a partially applied function that produces the expression instead of the expression. When render is called on the view it will first apply the feature collections for the route lines and then call invoke on the the expression producing functions, when they return their respective expressions they view will apply them as line gradients to the map. This will have the same effect I described above.

[cafesilencio]

Using the strategy I described above I"m seeing average time to calculate routes (set routes): < 100ms.

About 50-70ms (on average) was added to the view's render call but the traffic line expression calculations are performed after setting the feature collection sources to the map. So while the overall render call takes a little longer to return the perception is a more performant operation because the main lines are rendered before the traffic calculations are performed and applied to the map.

Keep in mind this is for routes from San Francisco to N.Y. For more realistic routes these times are substantially faster.

PR for this work is here: https://github.com/mapbox/mapbox-navigation-android/pull/4292

[cafesilencio]

Improvements have been made and the progress documented here. At this time I don't have any more benchmarking to do. Closing this issue.