835356 - Awesomescreen slow to appear

Status: RESOLVED FIXED

(Firefox for Android Graveyard :: Awesomescreen, defect)

Description

[James Willcox (:snorp) ([e-mail]) (he/him)]

Frequently I click the urlbar and it takes several seconds for the awesomescreen to show up, and still more for it to become usable. Usually I see the animation immediately (and mostly smoothly), but then it stalls after the animation for 1-3 seconds. Galaxy Nexus, Android 4.2.1

Comment 1

[Kartikaya Gupta (email:[e-mail])]

I've seen this too, and I suspect it happens because we get some sort of low-mem notification from android which causes us to block the UI thread. Do you see low-mem notifications in logcat when this happens?

Comment 2

[Kartikaya Gupta (email:[e-mail])]

Attachment: Fact-finding patch

Comment 3

[James Willcox (:snorp) ([e-mail]) (he/him)]

(In reply to Kartikaya Gupta (email:[e-mail]) from comment #1)
> I've seen this too, and I suspect it happens because we get some sort of
> low-mem notification from android which causes us to block the UI thread. Do
> you see low-mem notifications in logcat when this happens?

That sounds right, as I also get bug 822505 quite a bit on this device.

Comment 4

[James Willcox (:snorp) ([e-mail]) (he/him)]

Comment on attachment 707093 [details] [diff] [review]
Fact-finding patch

Review of attachment 707093 [details] [diff] [review]:
-----------------------------------------------------------------

Would be nice to pass a tag to geckoEventSync() so we knew which event was blocking stuff

Comment 5

[Kartikaya Gupta (email:[e-mail])]

The stack trace from the exception should have enough info to tell us that.

Comment 6

[James Willcox (:snorp) ([e-mail]) (he/him)]

(In reply to Kartikaya Gupta (email:[e-mail]) from comment #5)
> The stack trace from the exception should have enough info to tell us that.

Ah, that's true.

Comment 7

[Kartikaya Gupta (email:[e-mail])]

https://hg.mozilla.org/integration/mozilla-inbound/rev/4f080454a909

Comment 8

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/4f080454a909

Comment 9

[James Willcox (:snorp) ([e-mail]) (he/him)]

W/GeckoAppShell( 5700): Gecko event sync took too long! (3933 ms)
W/GeckoAppShell( 5700): java.lang.Exception
W/GeckoAppShell( 5700):         at org.mozilla.gecko.GeckoAppShell.geckoEventSync(GeckoAppShell.java:648)
W/GeckoAppShell( 5700):         at org.mozilla.gecko.MemoryMonitor.increaseMemoryPressure(MemoryMonitor.java:156)
W/GeckoAppShell( 5700):         at org.mozilla.gecko.MemoryMonitor.onTrimMemory(MemoryMonitor.java:99)
W/GeckoAppShell( 5700):         at org.mozilla.gecko.GeckoActivity.onTrimMemory(GeckoActivity.java:40)
W/GeckoAppShell( 5700):         at android.app.ActivityThread.handleTrimMemory(ActivityThread.java:4109)
W/GeckoAppShell( 5700):         at android.app.ActivityThread$H.handleMessage(ActivityThread.java:1426)
W/GeckoAppShell( 5700):         at android.os.Handler.dispatchMessage(Handler.java:99)
W/GeckoAppShell( 5700):         at android.os.Looper.loop(Looper.java:137)
W/GeckoAppShell( 5700):         at android.app.ActivityThread.main(ActivityThread.java:5039)
W/GeckoAppShell( 5700):         at java.lang.reflect.Method.invokeNative(Native Method)
W/GeckoAppShell( 5700):         at java.lang.reflect.Method.invoke(Method.java:511)
W/GeckoAppShell( 5700):         at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:793)
W/GeckoAppShell( 5700):         at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:560)
W/GeckoAppShell( 5700):         at dalvik.system.NativeStart.main(Native Method)

Comment 10

[James Willcox (:snorp) ([e-mail]) (he/him)]

This one is even worse, and triggered an ANR:

    W/GeckoAppShell( 5700): Gecko event sync took too long! (6482 ms)
    W/GeckoAppShell( 5700): java.lang.Exception
    W/GeckoAppShell( 5700):         at org.mozilla.gecko.GeckoAppShell.geckoEventSync(GeckoAppShell.java:648)
    W/GeckoAppShell( 5700):         at org.mozilla.gecko.GeckoAppShell.sendEventToGeckoSync(GeckoAppShell.java:595)
    W/GeckoAppShell( 5700):         at org.mozilla.gecko.gfx.GeckoLayerClient.compositionPauseRequested(GeckoLayerClient.java:599)
    W/GeckoAppShell( 5700):         at org.mozilla.gecko.gfx.LayerView.onDestroyed(LayerView.java:363)
    W/GeckoAppShell( 5700):         at org.mozilla.gecko.gfx.LayerView.access$300(LayerView.java:42)
    W/GeckoAppShell( 5700):         at org.mozilla.gecko.gfx.LayerView$SurfaceListener.surfaceDestroyed(LayerView.java:405)
    W/GeckoAppShell( 5700):         at android.view.SurfaceView.updateWindow(SurfaceView.java:553)
    W/GeckoAppShell( 5700):         at android.view.SurfaceView.onWindowVisibilityChanged(SurfaceView.java:231)
    W/GeckoAppShell( 5700):         at android.view.View.dispatchWindowVisibilityChanged(View.java:7537)
    W/GeckoAppShell( 5700):         at android.view.ViewGroup.dispatchWindowVisibilityChanged(ViewGroup.java:1039)
    W/GeckoAppShell( 5700):         at android.view.ViewGroup.dispatchWindowVisibilityChanged(ViewGroup.java:1039)
    W/GeckoAppShell( 5700):         at android.view.ViewGroup.dispatchWindowVisibilityChanged(ViewGroup.java:1039)
    W/GeckoAppShell( 5700):         at android.view.ViewGroup.dispatchWindowVisibilityChanged(ViewGroup.java:1039)
    W/GeckoAppShell( 5700):         at android.view.ViewGroup.dispatchWindowVisibilityChanged(ViewGroup.java:1039)
    W/GeckoAppShell( 5700):         at android.view.ViewGroup.dispatchWindowVisibilityChanged(ViewGroup.java:1039)
    W/GeckoAppShell( 5700):         at android.view.ViewGroup.dispatchWindowVisibilityChanged(ViewGroup.java:1039)
    W/GeckoAppShell( 5700):         at android.view.ViewRootImpl.performTraversals(ViewRootImpl.java:1211)
    W/GeckoAppShell( 5700):         at android.view.ViewRootImpl.doTraversal(ViewRootImpl.java:989)
    W/GeckoAppShell( 5700):         at android.view.ViewRootImpl$TraversalRunnable.run(ViewRootImpl.java:4351)
    W/GeckoAppShell( 5700):         at android.view.Choreographer$CallbackRecord.run(Choreographer.java:749)
    W/GeckoAppShell( 5700):         at android.view.Choreographer.doCallbacks(Choreographer.java:562)
    W/GeckoAppShell( 5700):         at android.view.Choreographer.doFrame(Choreographer.java:532)
    W/GeckoAppShell( 5700):         at android.view.Choreographer$FrameDisplayEventReceiver.run(Choreographer.java:735)
    W/GeckoAppShell( 5700):         at android.os.Handler.handleCallback(Handler.java:725)
    W/GeckoAppShell( 5700):         at android.os.Handler.dispatchMessage(Handler.java:92)
    W/GeckoAppShell( 5700):         at android.os.Looper.loop(Looper.java:137)
    W/GeckoAppShell( 5700):         at android.app.ActivityThread.main(ActivityThread.java:5039)
    W/GeckoAppShell( 5700):         at java.lang.reflect.Method.invokeNative(Native Method)
    W/GeckoAppShell( 5700):         at java.lang.reflect.Method.invoke(Method.java:511)
    W/GeckoAppShell( 5700):         at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:793)
    W/GeckoAppShell( 5700):         at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:560)
    W/GeckoAppShell( 5700):         at dalvik.system.NativeStart.main(Native Method)

Comment 11

[Geoff Brown [:gbrown]]

I am also seeing "Gecko event sync took too long" in recent test failures for robocop testNewTab: 

https://tbpl.mozilla.org/php/getParsedLog.php?id=19255854&tree=Mozilla-Inbound&full=1#error0
https://tbpl.mozilla.org/php/getParsedLog.php?id=19255080&tree=Mozilla-Inbound&full=1#error0

Comment 12

[Kartikaya Gupta (email:[e-mail])]

Attachment: More aggressive logging/handling

blassey asked me to implement something more like this today. It (a) logs more aggressively when we block for a long time and (b) prevents ANRs by unblocking automatically after 4 seconds if it's blocking the UI thread.

That second part concerns me a lot, as I think it might cause other bad behaviour that is potentially harder to track down, so requesting feedback from others to see what they think.

I tested this patch by artificially forcing a memory pressure scenario on top of a compositor block:

1) Start fennec
2) Immediately open the awesomebar
3) Wait a few seconds for gecko to finish starting up. Wait until "AndroidBridge::RegisterCompositor" shows in logcat
4) run "adb shell am broadcast -a org.mozilla.gecko.FORCE_MEMORY_PRESSURE"

Output from the above:

01-29 23:20:18.507 D/GeckoAppShell(26187): Gecko event sync taking too long: 101ms
01-29 23:20:18.600 D/GeckoAppShell(26187): Gecko event sync taking too long: 201ms
01-29 23:20:18.702 D/GeckoAppShell(26187): Gecko event sync taking too long: 302ms
01-29 23:20:18.804 D/GeckoAppShell(26187): Gecko event sync taking too long: 403ms
01-29 23:20:18.905 D/GeckoAppShell(26187): Gecko event sync taking too long: 503ms
01-29 23:20:19.007 D/GeckoAppShell(26187): Gecko event sync taking too long: 604ms
01-29 23:20:19.108 D/GeckoAppShell(26187): Gecko event sync taking too long: 705ms
01-29 23:20:19.210 D/GeckoAppShell(26187): Gecko event sync taking too long: 805ms
01-29 23:20:19.311 D/GeckoAppShell(26187): Gecko event sync taking too long: 906ms
01-29 23:20:19.413 D/GeckoAppShell(26187): Gecko event sync taking too long: 1008ms
01-29 23:20:19.514 D/GeckoAppShell(26187): Gecko event sync taking too long: 1109ms
01-29 23:20:19.608 D/GeckoAppShell(26187): Gecko event sync taking too long: 1210ms
01-29 23:20:19.718 D/GeckoAppShell(26187): Gecko event sync taking too long: 1310ms
01-29 23:20:19.811 D/GeckoAppShell(26187): Gecko event sync taking too long: 1411ms
01-29 23:20:19.913 D/GeckoAppShell(26187): Gecko event sync taking too long: 1512ms
01-29 23:20:20.014 D/GeckoAppShell(26187): Gecko event sync taking too long: 1613ms
01-29 23:20:20.116 D/GeckoAppShell(26187): Gecko event sync taking too long: 1714ms
01-29 23:20:20.218 D/GeckoAppShell(26187): Gecko event sync taking too long: 1815ms
01-29 23:20:20.319 D/GeckoAppShell(26187): Gecko event sync taking too long: 1917ms
01-29 23:20:20.421 D/GeckoAppShell(26187): Gecko event sync taking too long: 2018ms
01-29 23:20:20.522 D/GeckoAppShell(26187): Gecko event sync taking too long: 2119ms
01-29 23:20:20.624 D/GeckoAppShell(26187): Gecko event sync taking too long: 2220ms
01-29 23:20:20.725 D/GeckoAppShell(26187): Gecko event sync taking too long: 2321ms
01-29 23:20:20.827 D/GeckoAppShell(26187): Gecko event sync taking too long: 2422ms
01-29 23:20:20.929 D/GeckoAppShell(26187): Gecko event sync taking too long: 2523ms
01-29 23:20:21.030 D/GeckoAppShell(26187): Gecko event sync taking too long: 2624ms
01-29 23:20:21.124 D/GeckoAppShell(26187): Gecko event sync taking too long: 2725ms
01-29 23:20:21.225 D/GeckoAppShell(26187): Gecko event sync taking too long: 2826ms
01-29 23:20:21.335 D/GeckoAppShell(26187): Gecko event sync taking too long: 2927ms
01-29 23:20:21.436 D/GeckoAppShell(26187): Gecko event sync taking too long: 3028ms
01-29 23:20:21.530 D/GeckoAppShell(26187): Gecko event sync taking too long: 3130ms
01-29 23:20:21.632 D/GeckoAppShell(26187): Gecko event sync taking too long: 3231ms
01-29 23:20:21.733 D/GeckoAppShell(26187): Gecko event sync taking too long: 3332ms
01-29 23:20:21.835 D/GeckoAppShell(26187): Gecko event sync taking too long: 3433ms
01-29 23:20:21.936 D/GeckoAppShell(26187): Gecko event sync taking too long: 3534ms
01-29 23:20:22.038 D/GeckoAppShell(26187): Gecko event sync taking too long: 3635ms
01-29 23:20:22.139 D/GeckoAppShell(26187): Gecko event sync taking too long: 3736ms
01-29 23:20:22.241 D/GeckoAppShell(26187): Gecko event sync taking too long: 3837ms
01-29 23:20:22.343 D/GeckoAppShell(26187): Gecko event sync taking too long: 3938ms
01-29 23:20:22.444 D/GeckoAppShell(26187): Gecko event sync taking too long: 4039ms
01-29 23:20:22.444 W/GeckoAppShell(26187): Gecko event sync took too long, aborting!
01-29 23:20:22.444 W/GeckoAppShell(26187): java.lang.Exception
01-29 23:20:22.444 W/GeckoAppShell(26187): 	at org.mozilla.gecko.GeckoAppShell.geckoEventSync(GeckoAppShell.java:661)
01-29 23:20:22.444 W/GeckoAppShell(26187): 	at org.mozilla.gecko.MemoryMonitor.increaseMemoryPressure(MemoryMonitor.java:156)
01-29 23:20:22.444 W/GeckoAppShell(26187): 	at org.mozilla.gecko.MemoryMonitor.onReceive(MemoryMonitor.java:122)
01-29 23:20:22.444 W/GeckoAppShell(26187): 	at android.app.LoadedApk$ReceiverDispatcher$Args.run(LoadedApk.java:758)
01-29 23:20:22.444 W/GeckoAppShell(26187): 	at android.os.Handler.handleCallback(Handler.java:725)
01-29 23:20:22.444 W/GeckoAppShell(26187): 	at android.os.Handler.dispatchMessage(Handler.java:92)
01-29 23:20:22.444 W/GeckoAppShell(26187): 	at android.os.Looper.loop(Looper.java:137)
01-29 23:20:22.444 W/GeckoAppShell(26187): 	at android.app.ActivityThread.main(ActivityThread.java:5039)
01-29 23:20:22.444 W/GeckoAppShell(26187): 	at java.lang.reflect.Method.invokeNative(Native Method)
01-29 23:20:22.444 W/GeckoAppShell(26187): 	at java.lang.reflect.Method.invoke(Method.java:511)
01-29 23:20:22.444 W/GeckoAppShell(26187): 	at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:793)
01-29 23:20:22.444 W/GeckoAppShell(26187): 	at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:560)
01-29 23:20:22.444 W/GeckoAppShell(26187): 	at dalvik.system.NativeStart.main(Native Method)

It did not however result in a deadlock, and allowed me to type stuff into the awesomebar and load pages; generally speaking it recovered fine. I don't know if that will be the case for everything though.

Comment 13

[Kartikaya Gupta (email:[e-mail])]

Also, as an aside, while looking around the widget code to see if I could safely reuse the event object (seems like I can) I noticed that the AndroidGeckoEvent wrapper we create at [1] keeps a copy of the local ref jobject [2] and then the wrapper is put into the event queue (e.g. at [3]) which is then made available to the gecko thread at [4]. Although I don't think we currently call any of the wrapper functions from the gecko thread that access the wrapped_obj, this seems like a footgun that we should take care of earlier rather than later. Can somebody check to make sure I'm reading the code right?

[1] http://mxr.mozilla.org/mozilla-central/source/widget/android/AndroidJNI.cpp#63
[2] http://mxr.mozilla.org/mozilla-central/source/widget/android/AndroidJavaWrappers.cpp#527
[3] http://mxr.mozilla.org/mozilla-central/source/widget/android/nsAppShell.cpp#731
[4] http://mxr.mozilla.org/mozilla-central/source/widget/android/nsAppShell.cpp#285

Comment 14

[Kartikaya Gupta (email:[e-mail])]

Also try build for the patch: https://tbpl.mozilla.org/?tree=Try&rev=256814a77fe2

Comment 16

[Brad Lassey [:blassey] (use needinfo?)]

Comment on attachment 707987 [details] [diff] [review]
More aggressive logging/handling

Review of attachment 707987 [details] [diff] [review]:
-----------------------------------------------------------------

::: mobile/android/base/GeckoAppShell.java
@@ +639,4 @@
>  
> +        synchronized (sSyncEvent) {
> +            if (sWaitingForSyncAck) {
> +                // should never happen since we always leave it as true when we exit this function.

you mean false?

Comment 17

[Chris Peterson [:cpeterson]]

Comment on attachment 707987 [details] [diff] [review]
More aggressive logging/handling

Review of attachment 707987 [details] [diff] [review]:
-----------------------------------------------------------------

LGTM

::: mobile/android/base/GeckoAppShell.java
@@ +639,4 @@
>  
> +        synchronized (sSyncEvent) {
> +            if (sWaitingForSyncAck) {
> +                // should never happen since we always leave it as true when we exit this function.

`if (sWaitingForSyncAck)` is correct because geckoEventSync() should not reenter itself when it is already waiting for acknowledgeEventSync().

@@ +668,5 @@
>  
>      // Signal the Java thread that it's time to wake up
>      public static void acknowledgeEventSync() {
> +        synchronized (sSyncEvent) {
> +            sWaitingForSyncAck = false;

Is it possible for acknowledgeEventSync() to be called multiple time, such that sWaitingForSyncAck is true here? Is that OK or would that be a problem worth logging?

Comment 18

[Kartikaya Gupta (email:[e-mail])]

(In reply to Brad Lassey [:blassey] from comment #16)
> 
> you mean false?

Yeah, I forgot to update the comment from an earlier version of the patch

(In reply to Chris Peterson (:cpeterson) from comment #17)
> Is it possible for acknowledgeEventSync() to be called multiple time, such
> that sWaitingForSyncAck is true here? Is that OK or would that be a problem
> worth logging?

I assume you meant "false" instead of "true" in your question..
If we abort the wait in geckoEventSync() then it will exit with sWaitingForSyncAck set to false, so it would be false on entry here. I don't think that's worth logging.

Comment 19

[James Willcox (:snorp) ([e-mail]) (he/him)]

Comment on attachment 707987 [details] [diff] [review]
More aggressive logging/handling

Review of attachment 707987 [details] [diff] [review]:
-----------------------------------------------------------------

Looks good, but I worry that we're going to get some bizarre crashes now when we abort a sync. I wish we could somehow mark the instance as "tainted" after that.

Also, it might be nice to have some telemetry data whenever we give up on the sync.

Comment 20

[Kartikaya Gupta (email:[e-mail])]

(In reply to James Willcox (:snorp) ([e-mail]) from comment #19)
> I wish we could somehow mark the instance as "tainted"
> after that.

What "instance" are you referring to?

> Also, it might be nice to have some telemetry data whenever we give up on
> the sync.

Yeah. Presumably if it causes crashes we'll see some of the logging in the logcat at least.

https://hg.mozilla.org/integration/mozilla-inbound/rev/f32719879741

Comment 21

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/f32719879741