Closed Bug 797615 Opened 9 years ago Closed 8 years ago

Intermittent testHistoryTab, testHistory, testSystemPages, testVkbOverlap | PaintExpecter - blockUtilClear timeout (x3)

Categories

(Firefox for Android Graveyard :: General, defect)

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

Tracking

(Not tracked)

Status:
RESOLVED WORKSFORME
Milestone:
Firefox 24

People

(Reporter: philor, Unassigned)

References

Details

(Keywords: intermittent-failure, Whiteboard: [see comment 534, 549, 553, 562, 709])

Attachments

(2 files, 2 obsolete files)

Part 1 - cleanup
5.51 KB, patch
cwiiis
: review+
Details | Diff | Splinter Review
Part 2 - Mostly fix isBrowserContentDocumentDisplayed intermittently returning the wrong value (v2)
19.60 KB, patch
cwiiis
: review+
Details | Diff | Splinter Review 
https://tbpl.mozilla.org/php/getParsedLog.php?id=15783475&tree=Mozilla-Inbound
Android no-ionmonkey Tegra 250 mozilla-inbound opt test robocop on 2012-10-03 12:23:57 PDT for push 6925601f4299
slave: tegra-283

4 INFO TEST-UNEXPECTED-FAIL | testHistoryTab | PaintExpecter - blockUtilClear timeout
junit.framework.AssertionFailedError: 4 INFO TEST-UNEXPECTED-FAIL | testHistoryTab | PaintExpecter - blockUtilClear timeout
5 INFO TEST-UNEXPECTED-FAIL | testHistoryTab | Exception caught - junit.framework.AssertionFailedError: 4 INFO TEST-UNEXPECTED-FAIL | testHistoryTab | PaintExpecter - blockUtilClear timeout
https://tbpl.mozilla.org/php/getParsedLog.php?id=15797026&tree=Mozilla-Inbound
Summary: Intermittent testHistoryTab | PaintExpecter - blockUtilClear timeout (x3) → Intermittent testHistoryTab, testBookmark | PaintExpecter - blockUtilClear timeout (x3)
Blocks: 784186
(In reply to TinderboxPushlog Robot from comment #9)

This log actually has logcat data for the failed test! But I don't see anything helpful there.... :(
The failure in comments 12, 13, and 14 - blockUntilClear timeout in testHistoryTab - occurs when no drawFinished event is received after trying to load a url. This test actually loads 2 urls back-to-back; the first seems to succeed, the second fails -- I do not know why.
Whiteboard: [orange]
Summary: Intermittent testHistoryTab, testBookmark | PaintExpecter - blockUtilClear timeout (x3) → Intermittent testHistoryTab, testBookmark, testHistory | PaintExpecter - blockUtilClear timeout (x3)
https://tbpl.mozilla.org/php/getParsedLog.php?id=19437014&tree=Mozilla-Inbound
Summary: Intermittent testHistoryTab, testBookmark, testHistory | PaintExpecter - blockUtilClear timeout (x3) → Intermittent testHistoryTab, testBookmark, testHistory, testSystemPages | PaintExpecter - blockUtilClear timeout (x3)
Assignee: nobody → gbrown
logcat excerpt from successful run of testSystemPages:

01-01 01:54:48.356  9264  9272 I Robocop : 5 INFO TEST-PASS | testSystemPages | Awesomebar URL typed properly - about:rights should equal about:rights
01-01 01:54:48.366  9264  9272 D Robocop : waiting for DOMContentLoaded
01-01 01:54:48.396  9264  9276 D GeckoApp: State - 983041
01-01 01:54:48.396  9264  9276 D GeckoApp: Got a document start event.
01-01 01:54:48.426  9264  9264 I GeckoToolbar: zerdatime 6872009 - Throbber start
01-01 01:54:48.466  9264  9276 I GeckoApp: Security Mode - unknown
01-01 01:54:48.536  9264  9307 D Robocop : Received drawFinished notification
01-01 01:54:48.576  9264  9307 D Robocop : Received drawFinished notification
01-01 01:54:48.616  9264  9264 I GeckoToolbar: zerdatime 6872191 - Throbber start
01-01 01:54:48.646  9264  9307 D Robocop : Received drawFinished notification
01-01 01:54:48.666  9264  9273 W GeckoGlobalHistory: Rebuilding visited link set...
01-01 01:54:48.666  9264  9307 D Robocop : Received drawFinished notification
01-01 01:54:48.676  9264  9276 D Robocop : Waking up on handleMessage
01-01 01:54:48.676  9264  9276 D Robocop : received event DOMContentLoaded
01-01 01:54:48.676  9264  9276 D Robocop : Waking up on handleMessage
01-01 01:54:48.676  9264  9276 D Robocop : received event DOMContentLoaded
01-01 01:54:48.676  9264  9272 D Robocop : unblocked on expecter for DOMContentLoaded
01-01 01:54:48.756  9264  9276 D GeckoApp: State - 786448
01-01 01:54:48.756  9264  9276 D GeckoApp: Got a document stop event.
01-01 01:54:48.806  9264  9264 I GeckoToolbar: zerdatime 6872383 - Throbber stop
01-01 01:54:48.926  9264  9264 D dalvikvm: GC_EXTERNAL_ALLOC freed 8535 objects / 494544 bytes in 57ms
01-01 01:54:48.926  9264  9307 D Robocop : Received drawFinished notification
01-01 01:54:48.966  9264  9269 I dalvikvm: Jit: resizing JitTable from 8192 to 16384
01-01 01:54:48.988  9264  9307 D Robocop : Received drawFinished notification
01-01 01:54:49.066  9264  9307 D Robocop : Received drawFinished notification
01-01 01:54:49.086  9264  9315 D GeckoFavicons: The provided favicon URL is not valid
01-01 01:54:52.156  9264  9272 D dalvikvm: GC_FOR_MALLOC freed 4260 objects / 218904 bytes in 71ms
01-01 01:54:52.166  9264  9272 I dalvikvm-heap: Grow heap (frag case) to 7.063MB for 2846736-byte allocation
01-01 01:54:52.206  9264  9285 D dalvikvm: GC_FOR_MALLOC freed 68 objects / 3128 bytes in 39ms
01-01 01:54:52.376  9264  9272 I global  : Default buffer size used in BufferedOutputStream constructor. It would be better to be explicit if an 8k buffer is required.
01-01 01:54:52.876  9264  9272 I Robocop : 6 INFO TEST-PASS | testSystemPages | The correct number of tabs are opened - 1 should equal 1
...and from failed run (Comment 58):

02-05 10:53:48.153 I/Robocop ( 9218): 5 INFO TEST-PASS | testSystemPages | Awesomebar URL typed properly - about:rights should equal about:rights
02-05 10:53:48.153 D/Robocop ( 9218): waiting for DOMContentLoaded
02-05 10:53:50.103 I/ALL_PAGES( 9218): Got cursor in 10658ms
02-05 10:53:50.103 I/ALL_PAGES( 9218): Got cursor in 6267ms
02-05 10:53:50.163 I/ALL_PAGES( 9218): Got cursor in 53ms
02-05 10:53:50.263 E/Surface ( 9218): using an invalid surface id=0, identity=378 should be 381
02-05 10:53:50.263 I/CompositorParent( 9218): Unable to renew compositor surface; remaining in paused state
02-05 10:53:53.983 D/GeckoApp( 9218): State - 983041
02-05 10:53:53.983 D/GeckoApp( 9218): Got a document start event.
02-05 10:53:53.983 I/GeckoToolbar( 9218): zerdatime 2922168 - Throbber start
02-05 10:53:54.043 I/GeckoApp( 9218): Security Mode - unknown
02-05 10:53:54.153 I/GeckoToolbar( 9218): zerdatime 2922333 - Throbber start
02-05 10:53:54.843 D/Robocop ( 9218): Waking up on handleMessage
02-05 10:53:54.843 D/Robocop ( 9218): received event DOMContentLoaded
02-05 10:53:54.843 D/Robocop ( 9218): Waking up on handleMessage
02-05 10:53:54.843 D/Robocop ( 9218): received event DOMContentLoaded
02-05 10:53:54.843 D/Robocop ( 9218): unblocked on expecter for DOMContentLoaded
02-05 10:53:54.923 W/GeckoGlobalHistory( 9218): Rebuilding visited link set...
02-05 10:53:54.933 D/GeckoApp( 9218): State - 786448
02-05 10:53:54.933 D/GeckoApp( 9218): Got a document stop event.
02-05 10:53:54.933 I/GeckoToolbar( 9218): zerdatime 2923118 - Throbber stop
02-05 10:53:55.043 D/GeckoFavicons( 9218): The provided favicon URL is not valid
02-05 10:54:57.923 E/GeckoConsole( 9218): [JavaScript Warning: "WARN addons.updates: Request failed: 404: Not Found" {file: "resource://gre/modules/AddonUpdateChecker.jsm" line: 464}]
02-05 10:55:24.943 E/Robocop ( 9218): Dumping ALL the threads!
I reviewed the last 6 failure logs. They all have:

...
D/GeckoAppShell( 9217): Gecko event sync taking too long: 4022ms
W/GeckoAppShell( 9217): Gecko event sync took too long, aborting!
W/GeckoAppShell( 9217): java.lang.Exception
W/GeckoAppShell( 9217): 	at org.mozilla.gecko.GeckoAppShell.geckoEventSync(GeckoAppShell.java:675)
W/GeckoAppShell( 9217): 	at org.mozilla.gecko.GeckoAppShell.sendEventToGeckoSync(GeckoAppShell.java:610)
W/GeckoAppShell( 9217): 	at org.mozilla.gecko.gfx.GeckoLayerClient.compositionPauseRequested(GeckoLayerClient.java:599)
W/GeckoAppShell( 9217): 	at org.mozilla.gecko.gfx.LayerView.onDestroyed(LayerView.java:363)
W/GeckoAppShell( 9217): 	at org.mozilla.gecko.gfx.LayerView.access$300(LayerView.java:42)
W/GeckoAppShell( 9217): 	at org.mozilla.gecko.gfx.LayerView$SurfaceListener.surfaceDestroyed(LayerView.java:405)
W/GeckoAppShell( 9217): 	at android.view.SurfaceView.reportSurfaceDestroyed(SurfaceView.java:568)
W/GeckoAppShell( 9217): 	at android.view.SurfaceView.updateWindow(SurfaceView.java:472)
W/GeckoAppShell( 9217): 	at android.view.SurfaceView.onWindowVisibilityChanged(SurfaceView.java:206)
W/GeckoAppShell( 9217): 	at android.view.View.dispatchWindowVisibilityChanged(View.java:3891)
W/GeckoAppShell( 9217): 	at android.view.ViewGroup.dispatchWindowVisibilityChanged(ViewGroup.java:719)
W/GeckoAppShell( 9217): 	at android.view.ViewGroup.dispatchWindowVisibilityChanged(ViewGroup.java:719)
W/GeckoAppShell( 9217): 	at android.view.ViewGroup.dispatchWindowVisibilityChanged(ViewGroup.java:719)
W/GeckoAppShell( 9217): 	at android.view.ViewGroup.dispatchWindowVisibilityChanged(ViewGroup.java:719)
W/GeckoAppShell( 9217): 	at android.view.ViewGroup.dispatchWindowVisibilityChanged(ViewGroup.java:719)
W/GeckoAppShell( 9217): 	at android.view.ViewGroup.dispatchWindowVisibilityChanged(ViewGroup.java:719)
W/GeckoAppShell( 9217): 	at android.view.ViewRoot.performTraversals(ViewRoot.java:744)
W/GeckoAppShell( 9217): 	at android.view.ViewRoot.handleMessage(ViewRoot.java:1727)
W/GeckoAppShell( 9217): 	at android.os.Handler.dispatchMessage(Handler.java:99)
W/GeckoAppShell( 9217): 	at android.os.Looper.loop(Looper.java:123)
W/GeckoAppShell( 9217): 	at android.app.ActivityThread.main(ActivityThread.java:4627)
W/GeckoAppShell( 9217): 	at java.lang.reflect.Method.invokeNative(Native Method)
W/GeckoAppShell( 9217): 	at java.lang.reflect.Method.invoke(Method.java:521)
W/GeckoAppShell( 9217): 	at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:868)
W/GeckoAppShell( 9217): 	at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:626)
W/GeckoAppShell( 9217): 	at dalvik.system.NativeStart.main(Native Method)

...

E/Surface ( 9218): using an invalid surface id=0, identity=378 should be 381
I/CompositorParent( 9218): Unable to renew compositor surface; remaining in paused state


:snorp, :kats -- what does this mean?
(In reply to Geoff Brown [:gbrown] from comment #62)
> 
> E/Surface ( 9218): using an invalid surface id=0, identity=378 should be 381
> I/CompositorParent( 9218): Unable to renew compositor surface; remaining in
> paused state
> 
> 
> :snorp, :kats -- what does this mean?

The "unable to renew" message means that when the command to resume the compositor was executed (on the compositor thread) there was no surface available. The usual cause for this is us calling scheduleResumeCompositor() just before the awesome screen comes up and kills the surface. By the time the resume executes on the compositor thread the surface is gone and so it cannot actually resume. In theory this message should be benign since we'll do another resume when we dismiss the awesomescreen and that one will actually resume the compositor and renew the surface.

As for the geckoEventSync stack, well, it means that gecko was busy doing something when we tried to pause the compositor. Doing what I don't know. I wonder if there's some way to reliably get a stack from Gecko when this happens. Or attach gdb if you can reproduce it locally.