https://tbpl.mozilla.org/php/getParsedLog.php?id=21581707&tree=Mozilla-Inbound Ubuntu VM 12.04 mozilla-inbound debug test mochitest-5 on 2013-04-08 16:22:08 PDT for push 3f85757613d2 slave: tst-linux32-ec2-049 23:34:35 INFO - 110326 INFO TEST-PASS | /tests/layout/style/test/test_transitions_per_property.html | integer-valued property order: clamping of negatives 23:34:35 INFO - 110327 ERROR TEST-UNEXPECTED-FAIL | /tests/layout/style/test/test_transitions_per_property.html | Test timed out. 23:34:35 INFO - args: ['/builds/slave/test/build/tests/bin/screentopng'] 23:34:35 INFO - Xlib: extension "RANDR" missing on display ":0". 23:34:46 INFO - SCREENSHOT: <see log> 23:34:47 INFO - 110328 ERROR TEST-UNEXPECTED-FAIL | /tests/layout/style/test/test_transitions_per_property.html | [SimpleTest.finish()] this test already called finish! 23:34:47 INFO - 110329 ERROR TEST-UNEXPECTED-FAIL | /tests/layout/style/test/test_transitions_per_property.html | called finish() multiple times 23:34:47 INFO - 110330 INFO TEST-END | /tests/layout/style/test/test_transitions_per_property.html | finished in 305930ms
dbaron, can you please take a look at this and bug 906378 or suggest someone else who can?
For this bug, it looks like we're just still running the test when we hit the standard-mochitest-timeout. The full logs shows: 10:22:04 INFO - 47091 INFO TEST-START | /tests/layout/style/test/test_transitions_per_property.html [... many, many lines of test results ...] 10:27:08 INFO - 117267 INFO TEST-PASS | /tests/layout/style/test/test_transitions_per_property.html | integer-valued property order: clamping of negatives 10:27:08 INFO - 117268 ERROR TEST-UNEXPECTED-FAIL | /tests/layout/style/test/test_transitions_per_property.html | Test timed out. Note that we're still dutifully outputting test results, when the test times out. So, this is just a long test. We should just request a longer timeout, with requestLongerTimeout. (NOTE: bug 906378 appears to be different -- in that bug, there's a long wait between the last line of test-results and the timeout being caught. So I wouldn't necessarily expect a requestLongerTimeout to fix *that* bug.)
Created attachment 799067 [details] [diff] [review] fix v1: request longer timeout, per comment 55
Shouldn't our "detect long running tests" machinery catch this? None of the stars here seem to be giving that warning.
I am unfamiliar with that machinery/warning, so I can't comment on its effectiveness or why it wouldn't be catching this. As a human, looking at the logs from comment 49 & comment 52 (which I exerpted in comment 55), this sure looks like a long-running test that gets interrupted, to me.
Comment on attachment 799067 [details] [diff] [review] fix v1: request longer timeout, per comment 55 Worth a try, I guess, but I'm also skeptical.
Also, for what it's worth, we could do something to test fewer values for the properties that (a) don't support transitions and (b) have long lists of values in property_database.js. That would improve the part of the test that's slow. For example, we could test the first 10 and some deterministically-random subset of the rest. That said, it's also not clear to me why this got worse recently, though perhaps it was related to additions to property_database.js.
(Even so, if it did get worse recently, it's not clear why we'd have an *intermittent* performance problem.)
Assigning to Daniel while he's looking at it.
(In reply to David Baron [:dbaron] (needinfo? me) from comment #61) > (Even so, if it did get worse recently, it's not clear why we'd have an > *intermittent* performance problem.) I don't think it's intermittent. I think we're just close to the 5 minute boundary and we occasionally overstep it. I just checked the 2 most recent green Linux Debug M-5 logs (same platform as comment 52), on mozilla-inbound, and they say: > INFO Slowest: 270656ms - /tests/layout/style/test/test_transitions_per_property.html Source: https://tbpl.mozilla.org/php/getParsedLog.php?id=27389978&tree=Mozilla-Inbound > INFO Slowest: 271249ms - /tests/layout/style/test/test_transitions_per_property.html Source: https://tbpl.mozilla.org/php/getParsedLog.php?id=27388604&tree=Mozilla-Inbound So in those green logs, this test took ~ 4 minutes 31 seconds. Very close to 5 minutes, and close enough that it's believable that it might go over 5 minutes every once in a while.
Setting as "leave open" for now, since the landed fix is somewhat speculative and might not fix this. (Note also that the last few reports came several days apart (e.g. comment 49 - comment 50 were 5 days apart), so we might not know right away whether this has been fixed.) If 1-2 weeks go by with no reports in branches that have received this fix, then I think we could probably call this fixed.
(Comment 68 looks like bug 906378, not this bug, FWIW.) It's looking like this is fixed, but I'll give it another week before closing to be sure.
Hooray, it looks like this is fixed! Closing. [Clearing needinfo=dbaron from comment 53, as both this bug and the other bug mentioned there are now resolved.]