1068951 - 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)

Status: NEW

(Testing :: Mochitest, defect)

Description

[Daniel Holbert [:dholbert]]

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.

Comment 1

[Daniel Holbert [:dholbert]]

Attachment: pruned logcat

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.