Marionette isn't involved at all once mochitests are started; it's only
used to bootstrap them.
It isn't a buffering artifact. The actual log from the slow case is:
14:10:32 INFO - I/GeckoDump( 686): 36509 INFO TEST-START |
/tests/content/html/content/test/test_track_disabled.html
14:10:32 INFO - I/GeckoDump( 686): 36510 INFO TEST-PASS |
/tests/content/html/content/test/test_track_disabled.html | Track should
actually be an HTMLUnknownElement.
14:10:32 INFO - I/GeckoDump( 686): 36511 INFO TEST-END |
/tests/content/html/content/test/test_track_disabled.html | finished in 331391ms
This time is calculated in JS inside the harness between the time the
test's onload handler is called, and the time the test calls
SimpleTest.finish(); the way in which this winds up in the log does not
affect how this time is calculated.
From the fast case, the log shows:
14:27:56 INFO - 36509 INFO TEST-START |
/tests/content/html/content/test/test_track_disabled.html
14:27:56 INFO - 36510 INFO TEST-PASS |
/tests/content/html/content/test/test_track_disabled.html | Track should
actually be an HTMLUnknownElement.
14:27:56 INFO - 36511 INFO TEST-END |
/tests/content/html/content/test/test_track_disabled.html | finished in 4635ms
There may in fact be some logging strangeness that you can see in other
situations, but it isn't the primary problemthe primary problem is
that tests can get hung up in this way at completely random points.
Most of the time they run predictably, but at some points they slow to a
crawl for a l-o-n-g time before continuing, and this causes lots of
follow-on problems, including timeouts.
Jonathan
On 7/23/2013 1:46 PM, Dave Hylands wrote:
Hey Jonathan,
So I've observed something like this when running tests on the emulator.
What exactly is marionette parsing to determine if tests pass or fail? Is it
the adb log? or console log?
Is there a buffering effect happening and maybe the output is just being
delayed in getting delivered?
Like maybe some test after the one thats timing out is causing lots of CPU to
be consumed and this winds up holding up the log data from being delivered?
Dave Hylands
- Original Message -
From: "Jonathan Griffin"
To: dev-b2g@lists.mozilla.org
Cc: "Lucas Adamski" , "Ryan Vandermeulen"
Sent: Tuesday, July 23, 2013 12:32:30 PM
Subject: [b2g] mochitests randomly timing out
We're seeing a frequent problem in which a random mochitest will take
orders of magnitude longer to execute than it normally does, causing the
testrun to timeout.
For example, in this log, the test
"/tests/content/html/content/test/test_track_disabled.html" takes 4635ms
to complete:
https://tbpl.mozilla.org/php/getParsedLog.php?id=25576635&tree=Mozilla-Inbound&full=1
However, in this log, the same test takes 331391ms to complete, which
results in a timeout:
https://tbpl.mozilla.org/php/getParsedLog.php?id=25575730&tree=Mozilla-Inbound&full=1
Does anyone have any idea why this might be happening? Is it a
GC-related issue, and if so, is there any way to make our tests handle
this more gracefully? We could increase the mochitest timeout by a
significant factor, but would this just be hiding a real problem?
Thanks,
Jonathan
___
dev-b2g mailing list
dev-b2g@lists.mozilla.org
https://lists.mozilla.org/listinfo/dev-b2g
___
dev-b2g mailing list
dev-b2g@lists.mozilla.org
https://lists.mozilla.org/listinfo/dev-b2g
