Main thread lag and skipped frames when mapboxNavigation.startTripSession() called

JustinmClapperton commented 3 years ago

This issue occurs in our code, Ive provided a stripped down version of this issue on the following github link.

Android API: 21 Mapbox Navigation SDK version: 1.4.0 Code: https://github.com/JustinmClapperton/mapboxAndroidTest Example: https://youtu.be/t0DjKnAMDN8

(You will need to add your own Mapbox API key to gradle.properties and strings.xml) video:

Steps to trigger behavior

Run the app
Try to drag the map around and watch for skips

Expected behavior

App performs smoothly with no lag on the main thread. LocationEngineRequest Params should be respected

Actual behavior

App performs incredibly slow with several skipped frames on the main thread. No matter what I set the following code snippet too updates still happen less than every second, this could likely be part of the lag I'm experiencing.

LocationEngineRequest request = new LocationEngineRequest.Builder(10000L)
                .setFastestInterval(5000L)
                .setDisplacement(1)
                .setPriority(LocationEngineRequest.PRIORITY_HIGH_ACCURACY)
                .build();

Logs


I/pboxandroidtes: Background concurrent copying GC freed 259824(6913KB) AllocSpace objects, 0(0B) LOS objects, 46% free, 7027KB/12MB, paused 301us total 146.792ms
I/Choreographer: Skipped 48 frames!  The application may be doing too much work on its main thread.
I/pboxandroidtes: Background concurrent copying GC freed 256244(6982KB) AllocSpace objects, 0(0B) LOS objects, 46% free, 7006KB/12MB, paused 322us total 135.444ms
I/Choreographer: Skipped 45 frames!  The application may be doing too much work on its main thread.
I/pboxandroidtes: Background concurrent copying GC freed 259217(6978KB) AllocSpace objects, 0(0B) LOS objects, 46% free, 7196KB/13MB, paused 333us total 160.829ms
I/Choreographer: Skipped 47 frames!  The application may be doing too much work on its main thread.
I/pboxandroidtes: Background concurrent copying GC freed 271095(7222KB) AllocSpace objects, 0(0B) LOS objects, 45% free, 7318KB/13MB, paused 1.486ms total 163.121ms
I/pboxandroidtes: Background concurrent copying GC freed 269248(7251KB) AllocSpace objects, 0(0B) LOS objects, 46% free, 7011KB/12MB, paused 237us total 135.379ms
I/Choreographer: Skipped 45 frames!  The application may be doing too much work on its main thread.
I/pboxandroidtes: Background concurrent copying GC freed 259356(6983KB) AllocSpace objects, 0(0B) LOS objects, 47% free, 6891KB/12MB, paused 305us total 151.584ms
I/Choreographer: Skipped 46 frames!  The application may be doing too much work on its main thread.
I/pboxandroidtes: Background concurrent copying GC freed 258053(6855KB) AllocSpace objects, 0(0B) LOS objects, 45% free, 7301KB/13MB, paused 481us total 165.290ms
I/pboxandroidtes: Background concurrent copying GC freed 270151(7256KB) AllocSpace objects, 0(0B) LOS objects, 46% free, 7004KB/12MB, paused 398us total 141.638ms
I/Choreographer: Skipped 46 frames!  The application may be doing too much work on its main thread.
I/pboxandroidtes: Background concurrent copying GC freed 259398(6968KB) AllocSpace objects, 0(0B) LOS objects, 47% free, 6900KB/12MB, paused 320us total 156.619ms
I/pboxandroidtes: Background concurrent copying GC freed 257282(6864KB) AllocSpace objects, 0(0B) LOS objects, 46% free, 7028KB/12MB, paused 381us total 139.903ms
I/Choreographer: Skipped 47 frames!  The application may be doing too much work on its main thread.
I/pboxandroidtes: Background concurrent copying GC freed 256008(6948KB) AllocSpace objects, 0(0B) LOS objects, 47% free, 6864KB/12MB, paused 2.410ms total 141.356ms
I/Choreographer: Skipped 46 frames!  The application may be doing too much work on its main thread.
I/pboxandroidtes: Background concurrent copying GC freed 252915(6819KB) AllocSpace objects, 0(0B) LOS objects, 46% free, 7005KB/12MB, paused 422us total 135.958ms
I/Choreographer: Skipped 45 frames!  The application may be doing too much work on its main thread.
I/pboxandroidtes: Background concurrent copying GC freed 265328(7078KB) AllocSpace objects, 0(0B) LOS objects, 45% free, 7383KB/13MB, paused 526us total 190.145ms
I/pboxandroidtes: Background concurrent copying GC freed 272371(7317KB) AllocSpace objects, 0(0B) LOS objects, 46% free, 7105KB/12MB, paused 332us total 143.023ms
I/Choreographer: Skipped 46 frames!  The application may be doing too much work on its main thread.
I/pboxandroidtes: Background concurrent copying GC freed 263058(7078KB) AllocSpace objects, 0(0B) LOS o```

zugaldia commented 3 years ago

Thanks @JustinmClapperton for the report.

@Guardiola31337 @abhishek1508 would you be able to take a look at this one?

Guardiola31337 commented 3 years ago

Is this the same issue as https://github.com/mapbox/mapbox-navigation-android/issues/3881? Could you check @JustinmClapperton when you have a chance? If so, there are some suggestions on how to fix it. Could you check those out and see if any of them work for you?

JustinmClapperton commented 3 years ago

@Guardiola31337 Ill check

JustinmClapperton commented 3 years ago

@Guardiola31337 It doesnt appear related no, The app never freezes, it just reacts very slow and we have no issues starting or stopping navigation. Is your team aware that the settings for LocationEngineRequest are completely ignored? ie. If you set that value to a frequency and displacement of your choosing and then add a LocationObserver you will see the OnEnhancedLocation is still called every fraction of a second. My assumption was that this was part of the issue as we are trying to update the map so much its overloading memory. My phone can sit still on my desk and I can watch those updates happen every update even when my device is not moving. This is why I tried setting a larger displacement for LocationEngineRequest as we really only need an update if the device moves 5 meters and a frequency of probably 3-5 seconds. Hope this helps, let me know if you need any more information.

For reference Im using

                  LocationEngineRequest request = new LocationEngineRequest.Builder(10000L)
                        .setFastestInterval(5000L)
                        .setDisplacement(5)
                        .setPriority(LocationEngineRequest.PRIORITY_HIGH_ACCURACY)
                        .build();
                initLocationEngine();
                NavigationOptions navigationOptions = MapboxNavigation
                        .defaultNavigationOptionsBuilder(this.context, this.context.getString(R.string.mapbox_access_token))
                        .locationEngineRequest(request)
                        .locationEngine(locationEngine)
                        .build();
                mapboxNavigation = new MapboxNavigation(navigationOptions);

To trigger initialize my LocationEngineRequest but upon testing I found that w/e values I set are ignored.

in MapboxTripSession.kt I can see that it should be using the Navigation options value for the request

    private fun startLocationUpdates() {
        navigationOptions.locationEngine.requestLocationUpdates(
            navigationOptions.locationEngineRequest,
            locationEngineCallback,
            Looper.getMainLooper()
        )
        navigationOptions.locationEngine.getLastLocation(locationEngineCallback)
    }

But as I mentioned above this doesnt seem to be the case, somewhere its using the default settings and ignoring the users inputted values.

JustinmClapperton commented 3 years ago

@truburt Hi, just curious if your team actually confirmed this is a bug of if its just marked as a bug for investigation.

zugaldia commented 3 years ago

@Guardiola31337 could you confirm if this report is still under investigation? If so, are you able to reproduce it on the 2.x codebase too?

Guardiola31337 commented 3 years ago

If you set that value to a frequency and displacement of your choosing and then add a LocationObserver you will see the OnEnhancedLocation is still called every fraction of a second.

That is working as designed. Note that LocationObserver implements 2 callbacks onEnhancedLocationChanged and onRawLocationChanged. onEnhancedLocationChanged callback is handled internally and it's fired off "every second".

To be accurate following you can find the logic implemented:

On every location update (this is directly related to the LocationEngine frequency setup, by default the SDK uses 1s interval)
Every 1s (not configurable at the moment) if no locations are received after a 2 seconds patience period (not configurable at the moment either)

onRawLocationChanged should be called every time a new location is retrieved by the LocationEngine. Could you confirm that LocationEngineRequest params are respected looking at the logs generated in https://github.com/JustinmClapperton/mapboxAndroidTest/blob/8e5720776224171e127c925293dfc27596b11149/android/app/src/main/java/com/mapboxandroidtest/RoutificMapboxFragment.java#L501-L504 If that's not the case, that's definitely a bug.

That being said, it seems that you're hitting second condition above-explained (working as expected) and that should be unrelated to the lag reported. In this regard, could you double-check that the app is not doing any other work on the main thread causing the lag? Wondering if it's related to how React and the React platform implementation handles it or/and if it's an app setup issue.

JustinmClapperton commented 3 years ago

The version of the app above that I took the video with was a skeleton version of the app just to show the issue, The reactnative portion os only loading the native view and the rest is all native app. The only code working on the main thread is the code started when I fire mapboxNavigation.startTripSession() (This is when the lag starts) The lag then stops when I fire mapboxNavigation.stopTripSession().

One of the issues with the constant onEnhancedLocation updates is it's also triggering an off route state on nearly every update so if Im sitting still with navigation running the app is constantly trying to reroute itself. I would recommend increasing the displacement value for those updates as currently that experience is very unfavourable.

Also currently ( I did this as a test to see if it was a cause of the lag) your documentation here https://docs.mapbox.com/android/navigation/guides/off-route/ to disable off route detection doesnt appear to work either. mapboxNavigation.setRerouteController(null) appears to have no affect on enabling/disabling off route detection and re-routing.

Is there somewhere Ive missed in the docs on how we can change how off route detection is configured?

Also im curious why the second condition would be unrelated to the lag? It seems that the lag is only existing when im getting location events from onEnhancedLocation (When startTripSession is active) the moment I stop these location updates the lag is gone (When I call stopTripSession) at least at high level for me that points to the issue being directly related to location updates (or something fired based on the high frequency of location updates). With the app being the skeleton it is and having no other logic except for displaying the native navigation view and starting navigation im still concerned that the issue is related to location updates

Also I will test and confirm the piece you mentioned around onRawLocationChanged

Guardiola31337 commented 3 years ago

Could you try reproducing with a regular Android project? Even easier, could you try reproducing adding the problematic piece of code to any of the examples from the test app? https://github.com/mapbox/mapbox-navigation-android/tree/release-v1.x/examples We're not able to reproduce and all these examples are working fine - without any lag (even sitting for long periods of time at the same location) 🤔

Also, let me explain further the OffRoute behavior:

Internally we keep track of the OFF_ROUTE state. When isOffRoute is true an off-route state changed notification is emitted (OffRouteObserver). Also the SDK listens to these updates and by default requests a new route when the callback is fired off (and of course isOffRoute is true). Note that only one request is emitted to avoid unnecessary requests while an on-going request is in-flight. That prevents entering in a re-route loop and handles greatly one request at a time irrespective of potential consecutive OFF_ROUTE events. This behavior can be overridden by providing a custom RerouteController. Along with this, the different request states are reported through RerouteStateObserver and can be listened to when registering to it.

Note that all these cases are already handled internally and it’s recommended to not keep track of the RouteProgress#currentState directly and rely on the APIs and callbacks available.

Also currently ( I did this as a test to see if it was a cause of the lag) your documentation here https://docs.mapbox.com/android/navigation/guides/off-route/ to disable off route detection doesnt appear to work either. mapboxNavigation.setRerouteController(null) appears to have no affect on enabling/disabling off route detection and re-routing.

Is there somewhere Ive missed in the docs on how we can change how off route detection is configured?

Are you able to reproduce this consistently? Setting null should stop off-route logic altogether (as described in the docs) 👀

https://github.com/mapbox/mapbox-navigation-android/blob/ef4d3d43e17143889b4650282f8a70d7ef6f69df/libnavigation-core/src/main/java/com/mapbox/navigation/core/MapboxNavigation.kt#L551-L565

https://github.com/mapbox/mapbox-navigation-android/blob/ef4d3d43e17143889b4650282f8a70d7ef6f69df/libnavigation-core/src/main/java/com/mapbox/navigation/core/MapboxNavigation.kt#L747-L755

If rerouteController is null, reroute shouldn't be called.

Also im curious why the second condition would be unrelated to the lag? It seems that the lag is only existing when im getting location events from onEnhancedLocation (When startTripSession is active) the moment I stop these location updates the lag is gone (When I call stopTripSession) at least at high level for me that points to the issue being directly related to location updates (or something fired based on the high frequency of location updates). With the app being the skeleton it is and having no other logic except for displaying the native navigation view and starting navigation im still concerned that the issue is related to location updates

What are you doing inside the onEnhancedLocation callback? Could you share? If you're doing any long blocking operation in there that's going to be definitely the root cause of the lag as onEnhancedLocation is going to be called every second and therefore blocking the UI.

mapbox / mapbox-navigation-android