Closed Bug 835356 Opened 11 years ago Closed 11 years ago

Awesomescreen slow to appear

Categories

(Firefox for Android Graveyard :: Awesomescreen, defect)

Product:
Firefox for Android Graveyard
Component:
Awesomescreen
Platform:
ARM
Android
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

(Not tracked)

Status:
RESOLVED FIXED
Milestone:
Firefox 21

People

(Reporter: snorp, Assigned: kats)

References

Details

Attachments

(2 files)

Fact-finding patch
2.12 KB, patch
snorp
: review+
kats
: checkin+
Details | Diff | Splinter Review
More aggressive logging/handling
4.18 KB, patch
blassey
: review+
snorp
: feedback+
cpeterson
: feedback+
Details | Diff | Splinter Review 
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
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?
(In reply to Kartikaya Gupta (email:kats@mozilla.com) 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 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
Attachment #707093 - Flags: review?(snorp) → review+
The stack trace from the exception should have enough info to tell us that.
(In reply to Kartikaya Gupta (email:kats@mozilla.com) from comment #5)
> The stack trace from the exception should have enough info to tell us that.

Ah, that's true.
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)
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)
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.
Attachment #707987 - Flags: review?(blassey.bugs)
Attachment #707987 - Flags: feedback?(snorp)
Attachment #707987 - Flags: feedback?(cpeterson)
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 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?
Attachment #707987 - Flags: review?(blassey.bugs) → review+
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?
Attachment #707987 - Flags: feedback?(cpeterson) → feedback+
(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 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.
Attachment #707987 - Flags: feedback?(snorp) → feedback+
(In reply to James Willcox (:snorp) (jwillcox@mozilla.com) 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
Assignee: nobody → bugmail.mozilla
Whiteboard: [leave open]
https://hg.mozilla.org/mozilla-central/rev/f32719879741
Status: NEW → RESOLVED
Closed: 11 years ago
Resolution: --- → FIXED
Target Milestone: --- → Firefox 21
Product: Firefox for Android → Firefox for Android Graveyard
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: