Fenix: [Bug] Performance: 300ms of UI thread jank when pressing enter in the URL bar on a new tab, delays network requests

[mstange]

Steps to reproduce

1. Open the tab tray.
2. Tap the plus button.
3. Enter "go" and let it autocomplete to "google.com/".
4. Press "enter" (the button on the keyboard with the "Go" arrow).

Expected behavior

Network loads triggered by the GeckoView content process should be initiated as quickly as possible. The Java UI thread should always be available and never blocked for more than a few milliseconds at a time.

Actual behavior

Network loads in the GeckoView content process wait for the Java UI thread, and the Java UI thread is busy for ~300ms. The first network load is delayed by 240ms.

Profile: https://perfht.ml/2Tmvwd8

The important section is this one: https://perfht.ml/3885rEk
During this section, the content process is waiting for a response to a "GeckoView:OnLoadRequest" message, and this message is handled with the help of the Java UI thread.

Device information

• Android device: Moto G5
• Fenix version: Nightly 200223 18:01 (Build #20541806) 34.0.0, ba59da83d GV: 75.0a1-20200222095208

[csadilek]

We have the following observers of onLoadRequest all doing work on the main thread:

• The BrowserFragment expands the toolbar: https://github.com/mozilla-mobile/fenix/blob/13c9c39658e9f3b8ac29838e6153e394afb8919d/app/src/main/java/org/mozilla/fenix/browser/BaseBrowserFragment.kt#L421
• The AppRequestInterceptor adjust tracking protection, and forwards to the FxA and AppLink interceptors: https://github.com/mozilla-mobile/fenix/blob/9612c3f16d6ce11a32eae4c01b8ac0fb6008fc7f/app/src/main/java/org/mozilla/fenix/AppRequestInterceptor.kt#L26
  https://github.com/mozilla-mobile/fenix/blob/9612c3f16d6ce11a32eae4c01b8ac0fb6008fc7f/app/src/main/java/org/mozilla/fenix/AppRequestInterceptor.kt#L37
• In A-C, we extract the host name and invoke the interceptors above: https://github.com/mozilla-mobile/android-components/blob/master/components/browser/engine-gecko-nightly/src/main/java/mozilla/components/browser/engine/gecko/GeckoEngineSession.kt#L363

Marking this for A-C triage to see what/how we can improve performance of these observers.

[rocketsroger]

In this use case, the delay is not from the AppLinksInterceptor. By going to google.com, there are three onLoadRequest that triggered AppLinksInterceptor. However, all three request results in doNotIntercept equals to true. Which short circuits and stops further processing of the URL.

https://github.com/mozilla-mobile/android-components/blob/1e5bfb168bb86962367171a4decca0cb8cf617bc/components/feature/app-links/src/main/java/mozilla/components/feature/app/links/AppLinksInterceptor.kt#L62

[mcomella]

Triage: rocktesroger is taking a look and we'll periodically check in on the status from the Waiting column.

[rocketsroger]

After investigation, looks like there's no one particular operation that caused the delay. Each operation takes similar amount of time. onLoadRequest needs to block GeckoView because it needs to determine if this is an intent that needs to be launched by another application.

[rocketsroger]

With https://bugzilla.mozilla.org/show_bug.cgi?id=1619796 implemented, the onLoadRequest will not be in the code path when user enters an URL.

[csadilek]

@mstange Thanks for filing this!

The GV patch (https://bugzilla.mozilla.org/show_bug.cgi?id=1619796) as well as an A-C fix (https://github.com/mozilla-mobile/android-components/issues/6193) for this landed, which both should improve the time spent in onLoadRequest.

Would you be able to verify the improvements? I will keep this ticket open for now.

[mstange]

It's definitely better, but I think it can be better still. It looks like the shouldLoadUri call has simply moved to a different place but still happens, and it still seems to require one trip through the UI thread's event loop, so it is still delayed by the UI work that happens when you press enter.

Let me explain:

Old profile: https://perfht.ml/2U13Egp
New profiles: https://perfht.ml/397x1lD and https://perfht.ml/3bjnjy3

I've constrained the time range in all profiles so that they show what happens between pressing the "enter" key on the keyboard and the initiation of the network request in the content process.

Before: 425ms, after: 285ms, 210ms

So we have a 150ms-200ms speedup. Great! But I think the remaining 210ms+ can be eliminated as well.

There are four events here that we care about:

1. Enter is pressed in the onscreen keyboard.
2. loadURI is called in Gecko in the parent process.
3. PContent::Msg_LoadURI arrives in the content process.
4. The content process kicks off the network load.

The delay between 2 and 3 is negligible.
In the original profile, the bulk of the delay was between 3 and 4 (300ms): that's where the synchronous event loop was waiting for a response from Fenix. The delay between 1 and 2 was small (125ms), it was dominated by the Gecko work to create a new tab.
The Gecko work to create a new tab happens much earlier in the new profiles! It happens before the user even enters the URL. That's great.
In the new profiles, the delay between 3 and 4 is completely eliminated. But now we have a huge delay between 1 and 2: There's a 280ms / 195ms gap between pressing Enter and loadURI being called in Gecko.
During this gap, the Java UI thread is busy with BrowserFragment.initializeUI and other UI work.
Here's the shouldLoadUri stack: https://perfht.ml/2WrhxpQ

Verdict: Great improvements, but please make sure loadURI is called in Gecko before UI / fragment / view updates happen.

[csadilek]

Thanks!

This makes sense considering the GV fix wasn't to stop calling onLoadRequest entirely for user initiated loads (which would have caused problems for other consumers), but to post it to a handler instead. However, we still need to complete the provided GeckoResult before the URL actually starts loading. So, all our code still runs before this happens. That's the interceptors and the notification of all observers. We can't skip the interceptor but we could notify observers after we complete the gecko result which should be safe to do. Let's try.

/cc @rocketsroger

[csadilek]

We have looked into this now.

The notifications of our observers in onLoadRequest do not consume any significant time anymore. The remaining or new problem here is that GV now posts the onLoadRequest calls to a handler, which gives other UI code a chance to run before the URL starts loading. This is code that originally would have run after the URL started loading and explains the new delay Markus is seeing in latest profiles above.

This also seems to be the cause of a new black/white flickering we see in Nightly when opening a new tab and loading a URL. We'd appreciate some guidance here, as we don't see an obvious way of fixing that in Fenix or A-C.

@snorp @agi IIRC, the original idea to not call onLoadRequest for user initiated loads would've broken other consumers, right? Looking at this again, couldn't we just add a check for this ourselves in A-C? If we check loadRequest.triggerUri == null in onLoadRequest that would mean the load request is user initiated and we could skip all expensive logic. Is that correct? If so, could we remove the code again that posts to a handler, as we should still see the same performance gains? What do you think?

[agi90]

Discussed with @snorp and @csadilek on slack, we're gonna call onLoadRequest synchronously instead of posting it to the UI thread and give a way to the app to know if the request came from the app itself or from somewhere else.

Bugzilla: https://bugzilla.mozilla.org/show_bug.cgi?id=1624675

[rocketsroger]

@mstange We have merged multiple changes that shortens the time between user input and the network load. The remaining delays are UI related. Most of them are unavoidable due to layout initialization etc.

Please confirm these performance improvements are sufficient. If not we can open another issue to track performance investigation targeting UI.

Note: the changes should be in Nightly 200402 18:00.

[mstange]

I just rechecked: There is no improvement compared to the last time I checked.
Profile: https://perfht.ml/34dvFVA
In this profile, the time between pressing the "Enter" key and the network request being initiated is still 275ms. I'm afraid we will need the "UI" fix as well: the UI thread contributes 250ms to the delay in this profile.

[mstange]

Most of them are unavoidable due to layout initialization etc.

But does layout initialization need to run before Gecko is told to load the URI? I would think not.

[csadilek]

Thanks, @mstange.

We've looked into this again and (with @snorp's help) found out what's happening now. The good news is that onLoadRequest doesn't consume any time anymore due to the various improvements above. However, the listeners of the returned GeckoResult are not notified until the main thread is free again, which essentially prevents the loadUri message from being dispatched: https://searchfox.org/mozilla-central/source/mobile/android/geckoview/src/main/java/org/mozilla/geckoview/GeckoSession.java#1676

Here's the GV ticket: https://bugzilla.mozilla.org/show_bug.cgi?id=1628449

[mstange]

Thanks!

[mstange]

Here's the GV ticket: https://bugzilla.mozilla.org/show_bug.cgi?id=1628449

That did the trick!

Here are two profiles captured from a local build which includes that change: https://perfht.ml/2x9Fw2C, https://perfht.ml/3e7zzni
The delay between org.mozilla.fenix.search.SearchInteractor.onUrlCommitted and the network request being started in the content process is now reduced to 50-80ms. onUrlCommitted itself took 25-35ms in this profile, but this is a debuggable Fenix build, so it'll probably be faster in a production build.
The remaining 25-45ms are completely Gecko's fault.

Great work!

[csadilek]

Nice, thanks for verifying so quickly!