783639 - Robocop PixelTest failures on panda

Status: RESOLVED DUPLICATE of bug 787115

(Testing :: General, defect)

Description

[Geoff Brown [:gbrown] (pto Apr 11-18)]

PixelTest-derived Robocop tests fail on the panda boards.

Examining testPanCorrectness shows that loadAndVerifyBoxes calls loadAndPaint calls paintExpecter.blockUntilClear, which times out without receiving drawFinished events. Screenshots show a white screen and spinning throbber during this time.

By changing the roboboxes test page, it is possible to make the test pass. If the width is reduced to 1800 and the height to 900, the page loads and the test passes.

Logs showing both success and failure are at http://people.mozilla.org/~jmaher/gbrown/.

Comment 1

[Geoff Brown [:gbrown] (pto Apr 11-18)]

I am unable to reproduce this on the Galaxy Nexus -- seems to be specific to the pandas.

Comment 2

[Geoff Brown [:gbrown] (pto Apr 11-18)]

...but bug 767215 may indicate the same problem on tegras, only intermittent.

Comment 3

[Geoff Brown [:gbrown] (pto Apr 11-18)]

Attachment: diagnostic patch

:jmaher - please try this on a panda board when you get a chance - just one failing run of testPanCorrectness would be fine - and collect the logcat for me.

Comment 4

[Geoff Brown [:gbrown] (pto Apr 11-18)]

Attachment: diagnostic patch

Comment 5

[Geoff Brown [:gbrown] (pto Apr 11-18)]

The latest diagnostic patch shows CompositorParent::ShadowLayersUpdated called and mLayersUpdated set to true. However, before SyncViewportInfo can be called, PauseComposition is called. Composition is not resumed until after the test times out.

With a smaller test page, there is more of a time delay between the calls to ShadowLayersUpdated and PauseComposition, allowing SyncViewportInfo to run and the drawFinished notification to be sent.

Comment 6

[Geoff Brown [:gbrown] (pto Apr 11-18)]

Attachment: an obvious hack

:jmaher -- another patch for you to try.

Comment 7

[Joel Maher ( :jmaher ) (UTC -8)]

I uploaded 2 files today to:
http://people.mozilla.org/~jmaher/gbrown/

One is the failed and the other is with robocop_boxes.html adjusted to work, yet it didn't work.

Comment 8

[Geoff Brown [:gbrown] (pto Apr 11-18)]

(In reply to Joel Maher (:jmaher) from comment #7)

These are failing in a different way. Now the test is not really waiting for drawFinished at all, because a drawFinished is received before the page is loaded.

Consider this condensed view of one log:
08-27 14:36:46.576 D/Robocop ( 2377): unblocked on expecter for Gecko:Ready
08-27 14:36:47.271 D/GeckoLayerView( 2377): LayerView paint state set to 1
08-27 14:36:47.271 D/Robocop ( 2377): Received drawFinished notification
08-27 14:36:53.654 I/Robocop ( 2377): 2 INFO TEST-PASS | testPanCorrectness | Awesomebar URL typed properly - http://mochi.test:8888/tests/robocop/robocop_boxes.html should equal http://mochi.test:8888/tests/robocop/robocop_boxes.html
08-27 14:36:53.654 D/Robocop ( 2377): waiting for DOMContentLoaded
08-27 14:36:56.701 D/Robocop ( 2377): unblocked on expecter for DOMContentLoaded
08-27 14:36:57.755 I/dalvikvm-heap( 2377): Grow heap (frag case) to 11.208MB for 3153936-byte allocation
08-27 14:36:58.435 I/Robocop ( 2377): 3 INFO TEST-UNEXPECTED-FAIL | testPanCorrectness | Pixel at 0, 0 - Color rgba(255,255,255,255) not close enough to expected rgb(0,0,0)

drawFinished is received over 6000 ms before the test page URI has been entered -- and because of that, the blockUntilClear only waits for 1000 ms without a new drawFinished before proceeding to take and analyze the screenshot. I speculate that the 14:36:47.271 drawFinished is either 1. completely bogus or 2. late notification of paint of about:home. 

How to fix/avoid this? We need to start waiting for drawFinished before entering the test URL, otherwise we risk missing an event. We could start waiting a little later -- just before hitting Enter -- but it's unclear if that will be effective. We could also wait for a while after Gecko:Ready and before entering a URL, to drain bogus/late drawFinished events before proceeding with the test -- but how long?

As has been lamented in other Robocop bugs, it would be nice to have more specific event information: In this case, an event that said "drawFinished:.../robocop_boxes.html" might be handy.

Comment 9

[Geoff Brown [:gbrown] (pto Apr 11-18)]

Attachment: wait before registering for drawFinished

:jmaher -- try this on top of the previous patch.

Comment 10

[Geoff Brown [:gbrown] (pto Apr 11-18)]

Fixing/working around the issues in comments 5 and 8, the test continues to hang, as reported in bug 787115. In hindsight, the issues in comments 5 and 8 may be arising as a side-effect of bug 787115 (unexpected timing of events because a thread is hung, or because other threads are being starved).

Comment 11

[Geoff Brown [:gbrown] (pto Apr 11-18)]

Robocop PixelTests are running reliably on my pandaboard now.