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)

NEW
Unassigned

Status

Testing
Mochitest
3 years ago
3 years ago

People

(Reporter: dholbert, Unassigned)

Tracking

Firefox Tracking Flags

(Not tracked)

Details

Attachments

(1 attachment)

(Reporter)

Description

3 years ago
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.
(Reporter)

Updated

3 years ago
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)
(Reporter)

Comment 1

3 years ago
Created attachment 8491068 [details]
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.
You need to log in before you can comment on or make changes to this bug.