Activity startup becomes very slow after many tests using Compose

[bvschaik]

Description

Context: we're slowly migrating an app to Jetpack Compose. This app has an extensive test suite using Robolectric (~500 tests).

The problem: we noticed that the tests slow down to a crawl when executing all tests. Starting the activity (using ActivityScenario.launch) takes longer and longer: the first activity in the suite starts up instantly, activity in test 200 takes more than half a minute to start up.

Meanwhile, it is spamming the log with these messages, while all it is doing is starting an activity that displays a screen with a button..

I/Choreographer: Skipped 1000000 frames!  The application may be doing too much work on its main thread.
I/Choreographer: Skipped 1000000 frames!  The application may be doing too much work on its main thread.

I tracked it down to this line in ActivityController. Adding some debug logging revealed that the shadowMainLooper.idleIfPaused(); call handles 1000+ more messages for activity start N+1 than for activity start N. Meaning: the 100th test is processing 100,000+ messages before it starts.

Something keeps hanging around after each test execution, but I'm not familiar enough with the internals of Android or Compose to figure out what exactly.

Note: this ONLY happens when using Compose. When using plain old layout XMLs, the number of messages is stable at 5 for each activity start.

Also interesting: having animations increase the number of messages by a lot. For example, every fragment transition adds around 400 messages to the next test.

Steps to Reproduce

1. Open the example repo linked below.
2. Run the only unit test in it: it will run the same test 100 times.
3. Note that the run times for the tests increase: earlier tests run in ~120 ms on my machine, test 100 needs 400+ ms.

Now, set MainActivity.useCompose to false, so the UI will use layouts instead of Compose.

1. Run the unit test again.
2. Note that the run times don't increase.

Robolectric & Android Version

Robolectric: 4.12.1 Android version: target 34 Compose version: 1.6.7

Link to a public git repo demonstrating the problem:

https://github.com/bvschaik/robolectric-compose-leak

Workaround

For now, we've set forkEvery to 1 to ensure each test starts with a clean environment, but that's of course not a solution.

Possible related issues

I suspect the root cause of #7055 will be the same. I tried the suggestions mentioned in that issue but none of them made any difference.

[hoisie]

Have you tried to disable animations?

ShadowUiAutomation.setAnimationScale(0)

https://github.com/robolectric/robolectric/blob/3ab3afe02e21fee8d66843d11fdbadae0119b7ef/shadows/framework/src/main/java/org/robolectric/shadows/ShadowUiAutomation.java#L75

[bvschaik]

I just did. That makes no difference: test 100 will still process 121372 messages at startup.

[hoisie]

The first step to diagnose performance issues is to run the tests under a JVM profiler with CPU sampling enabled. This will show you where the time is spent. You could use a tool like VisualVM or YourKit.

Although calling ShadowUiAutomation.setAnimationScaleCompat(0) did not work, it still could still be an issue with animations. Some animation libraries (e.g. Lottie) do not really pay attention to these system settings. Also time-based animations (TimeAnimator) could still cause issues because they do not have any duration.

[bvschaik]

The issue is: it's not just the animations, they only make the problem more visible. Without doing anything other than starting the activity with any Compose function in it (even just an empty ComposeView), every activity start will add 4 messages to the queue that carry over to the next test.

And I could run visualvm or similar, but we already know that the sheer amount of Looper messages is the problem. The issue is that I have no clue where they come from or why they survive activity destruction.

[hoisie]

@bvschaik if you want to see what tasks are run, you can set a breakpoint here in IdlingRunnable. I believe this gets called when idle() is called on ShadowLooper:

https://github.com/robolectric/robolectric/blob/3ab3afe02e21fee8d66843d11fdbadae0119b7ef/shadows/framework/src/main/java/org/robolectric/shadows/ShadowPausedLooper.java#L600

If you look at the members of msg, you should be able to see the Runnable that is going to be executed.

You could try to use that to get a sense of which tasks get posted.

[bvschaik]

It's thousands of the same messages: { when=0 callback=android.view.Choreographer$FrameDisplayEventReceiver target=android.view.Choreographer$FrameHandler }

I tried printing the stacktrace where they're coming from, by adding logging to:

https://github.com/robolectric/robolectric/blob/81831fc059a6f098466063cb95b8df670929ee8d/shadows/framework/src/main/java/org/robolectric/shadows/ShadowPausedMessageQueue.java#L194

Those messages come from android.view.Choreographer$FrameDisplayEventReceiver...

For reference, these are the messages processed in the first test:

{ when=-1ms callback=android.view.ViewRootImpl$7 target=android.view.ViewRootImpl$ViewRootHandler }
{ when=0 callback=android.view.Choreographer$FrameDisplayEventReceiver target=android.view.Choreographer$FrameHandler }
{ when=-1ms callback=androidx.appcompat.app.AppCompatDelegateImpl$2 target=android.view.ViewRootImpl$ViewRootHandler }
{ when=-1ms callback=androidx.compose.ui.platform.AndroidUiDispatcher$dispatchCallback$1 target=android.os.Handler }
{ when=0 callback=android.view.Choreographer$FrameDisplayEventReceiver target=android.view.Choreographer$FrameHandler }

These are the message processed in the subsequent tests:

{ when=-2ms callback=androidx.compose.ui.platform.AndroidUiDispatcher$dispatchCallback$1 target=android.os.Handler }
{ when=-1ms callback=android.view.Choreographer$FrameDisplayEventReceiver target=android.view.Choreographer$FrameHandler }
I/Choreographer: Skipped 1000000 frames!  The application may be doing too much work on its main thread.
{ when=-2ms callback=android.view.ViewRootImpl$7 target=android.view.ViewRootImpl$ViewRootHandler }
{ when=-1ms callback=android.view.Choreographer$FrameDisplayEventReceiver target=android.view.Choreographer$FrameHandler }
I/Choreographer: Skipped 1000000 frames!  The application may be doing too much work on its main thread.
{ when=-1ms callback=android.view.Choreographer$FrameDisplayEventReceiver target=android.view.Choreographer$FrameHandler }
I/Choreographer: Skipped 1000000 frames!  The application may be doing too much work on its main thread.
{ when=-2ms callback=androidx.appcompat.app.AppCompatDelegateImpl$2 target=android.view.ViewRootImpl$ViewRootHandler }
{ when=-2ms callback=androidx.compose.ui.platform.AndroidUiDispatcher$dispatchCallback$1 target=android.os.Handler }
{ when=-1ms callback=android.view.Choreographer$FrameDisplayEventReceiver target=android.view.Choreographer$FrameHandler }
I/Choreographer: Skipped 1000000 frames!  The application may be doing too much work on its main thread.
{ when=0 callback=android.view.Choreographer$FrameDisplayEventReceiver target=android.view.Choreographer$FrameHandler }
{ when=0 callback=android.view.Choreographer$FrameDisplayEventReceiver target=android.view.Choreographer$FrameHandler }
{ when=0 callback=android.view.Choreographer$FrameDisplayEventReceiver target=android.view.Choreographer$FrameHandler }
{ when=0 callback=android.view.Choreographer$FrameDisplayEventReceiver target=android.view.Choreographer$FrameHandler }
{ when=0 callback=android.view.Choreographer$FrameDisplayEventReceiver target=android.view.Choreographer$FrameHandler }
...

I'm unsure how to proceed to debug this further.

[hoisie]

So it looks like the tasks are related to Conmpose's AndroidUiDispatcher. I am not an expert on Compose internals, but this appears to be a way to get coroutines to run in the Android UI thread.

The next step is to figure out when AndroidUiDispatcher is used, and see if the behavior can be configured.

[bvschaik]

I am not an expert on Compose internals

Neither am I, and I suppose there isn't an expert on Compose internals that we can magically summon? 😉

What I've been able to gather:

1. The very first setContent on a compose view (in onAttachedToWindow) will call GlobalSnapshotListener.ensureStarted(), which starts up a channel on the AndroidUiDispatcher.Main coroutine dispatcher. This channel is used for passing messages from the coroutine to the choreographer to be executed on vsync for some frame (?) for Compose recompositions (?)
2. When the second test runs, the GlobalSnapshotListener is already started, and the corresponding AndroidUiDispatcher is active and passing messages. This is the reason that we get a second AndroidUiDispatcher message in the queue on the second and subsequent runs: one from onCreate() and one from onAttachedToWindow()
3. There's also an AndroidUiFrameClock involved but I'm not not sure how, and whether this interferes with Robolectric's internal clock

I tried writing a shadow for AndroidUiDispatcher to ignore the call to dispatch() from onCreate() in the second test, but that resulted in an infinite loop.

I tried not advancing the compose clock using composeTestRule.mainClock.autoAdvance = false - it had no effect.

I tried calling AndroidUiDispatcher.Main.cancel() after the first test to hopefully reset the dispatcher - it had no effect.

I tried dumping the memory after the first test and after the 100th test and comparing the objects in them, hoping to find some queue with thousands of messages in them, but that got me nowhere.

I'm going to stop investigating - I spent a week on this already - and just apply the "forkEvery = 1" workaround for our tests.

[hoisie]

@bvschaik if you are interested in digging deeper, is there a repro of this bug that is possible to make available? Without being able to tinker with this, it may be difficult to progress on this issue.

[hoisie]

Nvm @bvschaik , I saw there is a repro of the issue already, I will take a look at that.

[brettchabot]

I suspect this issue has the same root cause 755

AndroidUiDispatcher keeps a static reference to Choreographer.getInstance which is then reused among tests. This is bad because Robolectric resets the state of the Android environment between tests, including the current system time. See ShadowPausedChoreographer#reset

Reusing the Choreographer between tests results in the Choreographer in use having an incorrect view of the current system time which leads to things generally going haywire. Running the provided sample shows a symptom of this as it starts spitting out many logs like

    I/Choreographer: Skipped 1000000 frames!  The application may be doing too much work on its main thread.

I can workaround this issue in the provided sample by resetting the AndroidUIDispatcher's Choreographer reference before each test:

    @Before
    fun init() {
        MainActivity.useCompose = true

        val clazz =
            javaClass.classLoader.loadClass("androidx.compose.ui.platform.AndroidUiDispatcher")
        val combinedContextClass =
            javaClass.classLoader.loadClass("kotlin.coroutines.CombinedContext")
        val companionClazz = clazz.getDeclaredField("Companion").get(clazz)
        val combinedContext = companionClazz.javaClass.getDeclaredMethod("getMain")
            .invoke(companionClazz)
        val androidUiDispatcher = clazz.cast(
            combinedContextClass.getDeclaredField("element").apply { isAccessible = true }
                .get(combinedContext)
        )
        var choreographerField =
            clazz.getDeclaredField("choreographer").apply { isAccessible = true }

        // reset the Choreographer instance to get the current one for the sandbox
        choreographerField.set(androidUiDispatcher, Choreographer.getInstance())

I can't think of a great way to workaround this issue in Robolectric. In the past I've tried to change Robolectric's Choreographer resetter to just clear the local state as opposed to requiring a new instance, but its quite involved to do so in a safe way across all supported Android versions.

I'll discuss with the compose team to see if we can figure out something.

[brettchabot]

This is still ugly but I was able to simplify the workaround to the following:

        val uiDispatcher : AndroidUiDispatcher = ReflectionHelpers.getField(AndroidUiDispatcher.Main, "element", )
        ReflectionHelpers.setField(uiDispatcher, "choreographer", Choreographer.getInstance())

[hoisie]

@bvschaik Robolectric 4.13 was released last night which I believe should fix this issue. Would you like to give it a try?

[bvschaik]

@hoisie I tried it out but unfortunately the issue is still present, and possibly a bit worse than before. We have a project that contains around 450 Robolectric tests. Timings:

• Robolectric 4.12.1: killed after 60 minutes with 160 tests completed
• Robolectric 4.13: killed after 60 minutes with 154 tests completed
• Robolectric 4.12.1 with the workaround from @brettchabot: 10 minutes

[brettchabot]

Sorry for the confusion, the fix is not in 4.13. I just submitted it to the google branch now, hopefully it will be in upcoming releases.

[johngray1965]

This is still ugly but I was able to simplify the workaround to the following:

        val uiDispatcher : AndroidUiDispatcher = ReflectionHelpers.getField(AndroidUiDispatcher.Main, "element", )
        ReflectionHelpers.setField(uiDispatcher, "choreographer", Choreographer.getInstance())

For me, I had put this in a Junit Rule and order it before the compose rule. The tests were failing trying to run the compose rule. Once I had in the Junit Rule and ordered it before the compose rule, all my problems went away (both slowness and tests failing with AppNotIdleException).

https://gist.github.com/johngray1965/24d7a3f1e5ae5f0fc1adc24444fe12ac