Open Bug 1068951 Opened 10 years ago Updated 2 years ago

Mochitests may be reported as timing out, when they actually completed >20 seconds shy of the limit. (possibly "timing out" due to a post-test-completion GC)

Categories

(Testing :: Mochitest, defect)

ARM
Android
defect

Tracking

(Not tracked)

People

(Reporter: dholbert, Unassigned)

Details

Attachments

(1 file)

As noted in bug 1041075 comment 136, we've got a log there with these facts: Test: test_value_storage.html Allowed time: 15 min (900000ms) Test runtime: 14 min 38s (878560ms) ...and yet the test is reported as timing out. This ends up looking like this in the TBPL log: { > INFO - 83 INFO TEST-START | /tests/layout/style/test/test_value_storage.html > INFO - 84 INFO TEST-OK | /tests/layout/style/test/test_value_storage.html | took 878560ms > INFO - 85 INFO TEST-UNEXPECTED-FAIL | /tests/layout/style/test/test_value_storage.html | Test timed out. - expected PASS > INFO - > INFO - 86 INFO TEST-UNEXPECTED-FAIL | /tests/layout/style/test/test_value_storage.html | Test timed out. - Result logged after SimpleTest.finish() } The android logcat output has more information (including all the individual sub-test results). In particular, it shows there being some GC'ing between the "test finished" message and the reported timeout. I'm assuming that's the cause of the discrepancy. We should fix things here to make the messaging consistent. (Either the test finished in its allotted time, or it did not; but right now, our logging is saying that it *both* did *and* did not.) In particular, we should either: (1) Make the post-test GC officially part of the test (and not print a "test finished in..." message until it's complete) ...OR: (2) Make the post-test GC officially *NOT* part of the test, and don't count it against the test's allotted time.
Summary: Mochitests may be reported as timing out, when they actually completed >20 seconds shy of the limit. (possibly due to a post-test-completion GC) → Mochitests may be reported as timing out, when they actually completed >20 seconds shy of the limit. (possibly "timing out" due to a post-test-completion GC)
Attached file pruned logcat (deleted) —
Here are the links to the logs from the testrun that prompted me to file this bug: TBPL Log: https://tbpl.mozilla.org/php/getParsedLog.php?id=47819311&tree=Mozilla-Inbound Full logcat: http://mozilla-releng-blobs.s3.amazonaws.com/blobs/mozilla-inbound/sha512/39291468a5542b31a3461bc0b7b6ed24dfc129c8f0ade16d6d461dc746521c2d2810f3e8795f22220c555c6db96b78f6104f9761c9107c1b45624344a4ad632a I'm attaching a pruned version of the logcat output, showing this test starting, finishing, and then being reported as a timeout after a GC happens.
Severity: normal → S3
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: