Closed Bug 797615 Opened 12 years ago Closed 11 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.