Closed Bug 1491257 Opened 2 years ago Closed 1 year ago

Intermittent [TV] testing/marionette/test/unit/test_sync.js | test_PollPromise_interval - [test_PollPromise_interval : 111] 2 == 3

Categories

(Testing :: Marionette, defect, P1)

Version 3
defect

Tracking

(Not tracked)

RESOLVED INCOMPLETE

People

(Reporter: intermittent-bug-filer, Assigned: ato)

References

Details

(Keywords: intermittent-failure)

Attachments

(1 file, 1 obsolete file)

Filed by: cbrindusan [at] mozilla.com

https://treeherder.mozilla.org/logviewer.html#?job_id=199246467&repo=mozilla-central

https://queue.taskcluster.net/v1/task/DOurrE1nTc-YlGV5fHAMcg/runs/0/artifacts/public/logs/live_backing.log

05:48:41     INFO -  TEST-START | testing/marionette/test/unit/test_sync.js
05:48:43  WARNING -  TEST-UNEXPECTED-FAIL | testing/marionette/test/unit/test_sync.js | xpcshell return code: 0
05:48:43     INFO -  TEST-INFO took 2440ms
05:48:43     INFO -  >>>>>>>
05:48:43     INFO -  PID 2284 | *** You are running in chaos test mode. See ChaosMode.h. ***
05:48:43     INFO -  (xpcshell/head.js) | test MAIN run_test pending (1)
05:48:43     INFO -  (xpcshell/head.js) | test run_next_test 0 pending (2)
05:48:43     INFO -  (xpcshell/head.js) | test MAIN run_test finished (2)
05:48:43     INFO -  running event loop
05:48:43     INFO -  testing/marionette/test/unit/test_sync.js | Starting test_PollPromise_funcTypes
05:48:43     INFO -  (xpcshell/head.js) | test test_PollPromise_funcTypes pending (2)
05:48:43     INFO -  TEST-PASS | testing/marionette/test/unit/test_sync.js | test_PollPromise_funcTypes - [test_PollPromise_funcTypes : 15] ..
05:48:43     INFO -  TEST-PASS | testing/marionette/test/unit/test_sync.js | test_PollPromise_funcTypes - [test_PollPromise_funcTypes : 15] ..
05:48:43     INFO -  TEST-PASS | testing/marionette/test/unit/test_sync.js | test_PollPromise_funcTypes - [test_PollPromise_funcTypes : 15] ..
05:48:43     INFO -  TEST-PASS | testing/marionette/test/unit/test_sync.js | test_PollPromise_funcTypes - [test_PollPromise_funcTypes : 15] ..
05:48:43     INFO -  TEST-PASS | testing/marionette/test/unit/test_sync.js | test_PollPromise_funcTypes - [test_PollPromise_funcTypes : 15] ..
05:48:43     INFO -  TEST-PASS | testing/marionette/test/unit/test_sync.js | test_PollPromise_funcTypes - [test_PollPromise_funcTypes : 15] ..
05:48:43     INFO -  TEST-PASS | testing/marionette/test/unit/test_sync.js | test_PollPromise_funcTypes - [test_PollPromise_funcTypes : 15] ..
05:48:43     INFO -  (xpcshell/head.js) | test run_next_test 1 pending (3)
05:48:43     INFO -  (xpcshell/head.js) | test test_PollPromise_funcTypes finished (3)
05:48:43     INFO -  (xpcshell/head.js) | test run_next_test 0 finished (2)
05:48:43     INFO -  testing/marionette/test/unit/test_sync.js | Starting test_PollPromise_timeoutTypes
05:48:43     INFO -  (xpcshell/head.js) | test test_PollPromise_timeoutTypes pending (2)
05:48:43     INFO -  TEST-PASS | testing/marionette/test/unit/test_sync.js | test_PollPromise_timeoutTypes - [test_PollPromise_timeoutTypes : 25] ..
05:48:43     INFO -  TEST-PASS | testing/marionette/test/unit/test_sync.js | test_PollPromise_timeoutTypes - [test_PollPromise_timeoutTypes : 25] ..
05:48:43     INFO -  TEST-PASS | testing/marionette/test/unit/test_sync.js | test_PollPromise_timeoutTypes - [test_PollPromise_timeoutTypes : 25] ..
05:48:43     INFO -  TEST-PASS | testing/marionette/test/unit/test_sync.js | test_PollPromise_timeoutTypes - [test_PollPromise_timeoutTypes : 25] ..
05:48:43     INFO -  TEST-PASS | testing/marionette/test/unit/test_sync.js | test_PollPromise_timeoutTypes - [test_PollPromise_timeoutTypes : 25] ..
05:48:43     INFO -  TEST-PASS | testing/marionette/test/unit/test_sync.js | test_PollPromise_timeoutTypes - [test_PollPromise_timeoutTypes : 28] ..
05:48:43     INFO -  TEST-PASS | testing/marionette/test/unit/test_sync.js | test_PollPromise_timeoutTypes - [test_PollPromise_timeoutTypes : 28] ..
05:48:43     INFO -  (xpcshell/head.js) | test run_next_test 2 pending (3)
05:48:43     INFO -  (xpcshell/head.js) | test test_PollPromise_timeoutTypes finished (3)
05:48:43     INFO -  (xpcshell/head.js) | test run_next_test 1 finished (2)
05:48:43     INFO -  testing/marionette/test/unit/test_sync.js | Starting test_PollPromise_intervalTypes
05:48:43     INFO -  (xpcshell/head.js) | test test_PollPromise_intervalTypes pending (2)
05:48:43     INFO -  TEST-PASS | testing/marionette/test/unit/test_sync.js | test_PollPromise_intervalTypes - [test_PollPromise_intervalTypes : 37] ..
05:48:43     INFO -  TEST-PASS | testing/marionette/test/unit/test_sync.js | test_PollPromise_intervalTypes - [test_PollPromise_intervalTypes : 37] ..
05:48:43     INFO -  TEST-PASS | testing/marionette/test/unit/test_sync.js | test_PollPromise_intervalTypes - [test_PollPromise_intervalTypes : 37] ..
05:48:43     INFO -  TEST-PASS | testing/marionette/test/unit/test_sync.js | test_PollPromise_intervalTypes - [test_PollPromise_intervalTypes : 37] ..
05:48:43     INFO -  TEST-PASS | testing/marionette/test/unit/test_sync.js | test_PollPromise_intervalTypes - [test_PollPromise_intervalTypes : 37] ..
05:48:43     INFO -  TEST-PASS | testing/marionette/test/unit/test_sync.js | test_PollPromise_intervalTypes - [test_PollPromise_intervalTypes : 40] ..
05:48:43     INFO -  TEST-PASS | testing/marionette/test/unit/test_sync.js | test_PollPromise_intervalTypes - [test_PollPromise_intervalTypes : 40] ..
05:48:43     INFO -  (xpcshell/head.js) | test run_next_test 3 pending (3)
05:48:43     INFO -  (xpcshell/head.js) | test test_PollPromise_intervalTypes finished (3)
05:48:43     INFO -  (xpcshell/head.js) | test run_next_test 2 finished (2)
05:48:43     INFO -  testing/marionette/test/unit/test_sync.js | Starting test_PollPromise_retvalTypes
05:48:43     INFO -  (xpcshell/head.js) | test test_PollPromise_retvalTypes pending (2)
05:48:43     INFO -  (xpcshell/head.js) | test run_next_test 3 finished (2)
05:48:43     INFO -  TEST-PASS | testing/marionette/test/unit/test_sync.js | test_PollPromise_retvalTypes - [test_PollPromise_retvalTypes : 49] true === true
05:48:43     INFO -  TEST-PASS | testing/marionette/test/unit/test_sync.js | test_PollPromise_retvalTypes - [test_PollPromise_retvalTypes : 49] false === false
05:48:43     INFO -  TEST-PASS | testing/marionette/test/unit/test_sync.js | test_PollPromise_retvalTypes - [test_PollPromise_retvalTypes : 49] "foo" === "foo"
05:48:43     INFO -  TEST-PASS | testing/marionette/test/unit/test_sync.js | test_PollPromise_retvalTypes - [test_PollPromise_retvalTypes : 49] 42 === 42
05:48:43     INFO -  TEST-PASS | testing/marionette/test/unit/test_sync.js | test_PollPromise_retvalTypes - [test_PollPromise_retvalTypes : 49] [] === []
05:48:43     INFO -  TEST-PASS | testing/marionette/test/unit/test_sync.js | test_PollPromise_retvalTypes - [test_PollPromise_retvalTypes : 49] {} === {}
05:48:43     INFO -  (xpcshell/head.js) | test run_next_test 4 pending (2)
05:48:43     INFO -  (xpcshell/head.js) | test test_PollPromise_retvalTypes finished (2)
05:48:43     INFO -  testing/marionette/test/unit/test_sync.js | Starting test_PollPromise_timeoutElapse
05:48:43     INFO -  (xpcshell/head.js) | test test_PollPromise_timeoutElapse pending (2)
05:48:43     INFO -  (xpcshell/head.js) | test run_next_test 4 finished (2)
05:48:43     INFO -  TEST-PASS | testing/marionette/test/unit/test_sync.js | test_PollPromise_timeoutElapse - [test_PollPromise_timeoutElapse : 61] 2001 >= 2000
05:48:43     INFO -  TEST-PASS | testing/marionette/test/unit/test_sync.js | test_PollPromise_timeoutElapse - [test_PollPromise_timeoutElapse : 62] 201 >= 15
05:48:43     INFO -  (xpcshell/head.js) | test run_next_test 5 pending (2)
05:48:43     INFO -  (xpcshell/head.js) | test test_PollPromise_timeoutElapse finished (2)
05:48:43     INFO -  testing/marionette/test/unit/test_sync.js | Starting test_PollPromise_rethrowError
05:48:43     INFO -  (xpcshell/head.js) | test test_PollPromise_rethrowError pending (2)
05:48:43     INFO -  (xpcshell/head.js) | test run_next_test 5 finished (2)
05:48:43     INFO -  TEST-PASS | testing/marionette/test/unit/test_sync.js | test_PollPromise_rethrowError - [test_PollPromise_rethrowError : 76] 1 == 1
05:48:43     INFO -  TEST-PASS | testing/marionette/test/unit/test_sync.js | test_PollPromise_rethrowError - [test_PollPromise_rethrowError : 77] true == true
05:48:43     INFO -  (xpcshell/head.js) | test run_next_test 6 pending (2)
05:48:43     INFO -  (xpcshell/head.js) | test test_PollPromise_rethrowError finished (2)
05:48:43     INFO -  testing/marionette/test/unit/test_sync.js | Starting test_PollPromise_noTimeout
05:48:43     INFO -  (xpcshell/head.js) | test test_PollPromise_noTimeout pending (2)
05:48:43     INFO -  (xpcshell/head.js) | test run_next_test 6 finished (2)
05:48:43     INFO -  TEST-PASS | testing/marionette/test/unit/test_sync.js | test_PollPromise_noTimeout - [test_PollPromise_noTimeout : 89] 1 == 1
05:48:43     INFO -  TEST-PASS | testing/marionette/test/unit/test_sync.js | test_PollPromise_noTimeout - [test_PollPromise_noTimeout : 90] 0 < 2000
05:48:43     INFO -  (xpcshell/head.js) | test run_next_test 7 pending (2)
05:48:43     INFO -  (xpcshell/head.js) | test test_PollPromise_noTimeout finished (2)
05:48:43     INFO -  testing/marionette/test/unit/test_sync.js | Starting test_PollPromise_timeout
05:48:43     INFO -  (xpcshell/head.js) | test test_PollPromise_timeout pending (2)
05:48:43     INFO -  (xpcshell/head.js) | test run_next_test 7 finished (2)
05:48:43     INFO -  TEST-PASS | testing/marionette/test/unit/test_sync.js | test_PollPromise_timeout - [test_PollPromise_timeout : 101] 11 > 1
05:48:43     INFO -  TEST-PASS | testing/marionette/test/unit/test_sync.js | test_PollPromise_timeout - [test_PollPromise_timeout : 102] 101 >= 100
05:48:43     INFO -  (xpcshell/head.js) | test run_next_test 8 pending (2)
05:48:43     INFO -  (xpcshell/head.js) | test test_PollPromise_timeout finished (2)
05:48:43     INFO -  testing/marionette/test/unit/test_sync.js | Starting test_PollPromise_interval
05:48:43     INFO -  (xpcshell/head.js) | test test_PollPromise_interval pending (2)
05:48:43     INFO -  (xpcshell/head.js) | test run_next_test 8 finished (2)
05:48:43  WARNING -  TEST-UNEXPECTED-FAIL | testing/marionette/test/unit/test_sync.js | test_PollPromise_interval - [test_PollPromise_interval : 111] 2 == 3
05:48:43     INFO -  Z:/task_1536902706/build/tests/xpcshell/tests/testing/marionette/test/unit/test_sync.js:test_PollPromise_interval:111
05:48:43     INFO -  exiting test
05:48:43     INFO -  Unexpected exception NS_ERROR_ABORT:
05:48:43     INFO -  _abort_failed_test@Z:\task_1536902706\build\tests\xpcshell\head.js:746:9
05:48:43     INFO -  do_report_result@Z:\task_1536902706\build\tests\xpcshell\head.js:853:5
05:48:43     INFO -  Assert<@Z:\task_1536902706\build\tests\xpcshell\head.js:55:5
05:48:43     INFO -  proto.report@resource://testing-common/Assert.jsm:214:5
05:48:43     INFO -  equal@resource://testing-common/Assert.jsm:246:3
05:48:43     INFO -  test_PollPromise_interval@Z:/task_1536902706/build/tests/xpcshell/tests/testing/marionette/test/unit/test_sync.js:111:3
05:48:43     INFO -  async*run_next_test/_run_next_test/<@Z:\task_1536902706\build\tests\xpcshell\head.js:1441:22
05:48:43     INFO -  async*_run_next_test@Z:\task_1536902706\build\tests\xpcshell\head.js:1441:10
05:48:43     INFO -  run@Z:\task_1536902706\build\tests\xpcshell\head.js:692:9
05:48:43     INFO -  _do_main@Z:\task_1536902706\build\tests\xpcshell\head.js:219:3
05:48:43     INFO -  _execute_test@Z:\task_1536902706\build\tests\xpcshell\head.js:533:5
05:48:43     INFO -  @-e:1:1
05:48:43     INFO -  exiting test
Summary: Intermittent testing/marionette/test/unit/test_sync.js | test_PollPromise_interval - [test_PollPromise_interval : 111] 2 == 3 → Intermittent [TV] testing/marionette/test/unit/test_sync.js | test_PollPromise_interval - [test_PollPromise_interval : 111] 2 == 3
Assignee: nobody → ato
Status: NEW → ASSIGNED
Priority: P5 → P1
A PollPromise with timeout of 100 ms and interval of 100 ms is
normally expected to fire twice: once immediately and once before
the timeout at 100 ms.

On slow systems, such as Windows PGO TV, the timeout timer may be
slow enough for a third evaluation of the PollPromise to occur.
This makes the test more lenient by allowing anywhere from 2 to 3
iterations to happen.
Attachment #9009063 - Flags: review?(hskupin)
Comment on attachment 9009063 [details] [diff] [review]
marionette: be more lenient in PollPromise interval test

Review of attachment 9009063 [details] [diff] [review]:
-----------------------------------------------------------------

::: testing/marionette/test/unit/test_sync.js
@@ +108,5 @@
>      ++nevals;
>      reject();
>    }, {timeout: 100, interval: 100});
> +  greaterOrEqual(nevals, 2);
> +  lessOrEqual(nevals, 3);

That doesn't sound ideal. So lets talk about a solution first.

As I can see we have a timer of type `TYPE_REPEATING_SLACK` which can be fired at any time. Even it is the preferred type for most situations, how should the processing of the callback count in here. Note that this also influences the timer period, which actually might lead to the above seen situation.

So wouldn't it be better to have a precise timer of type `TYPE_REPEATING_PRECISE_CAN_SKIP` instead?
Attachment #9009063 - Flags: review?(hskupin)
Precisely because we’re using TYPE_REPEATING_SLACK, permitting the
test some leeway here makes sense.  But I buy the argument for using
TYPE_REPEATING_PRECISE_CAN_SKIP too.

I think the reason I originally chose TYPE_REPEATING_SLACK for this
was to guarantee that the promise function was called as many times
as possible in a fashion that guaranteed that it was called at least
once.  Theoretically it would be possible for it never to be invoked
if the scheduler is busy when using TYPE_REPEATING_SLACK.  Since
then we changed PollPromise to explicitly call it once first anyway,
so that is no longer a concern.
A PollPromise with timeout of 100 ms and interval of 100 ms is
normally expected to fire twice: once immediately and once before
the timeout at 100 ms.

On slow systems, such as Windows PGO TV, the timeout timer may be
slow enough for a third evaluation of the PollPromise to occur.
By making the timer strategy more precise we can ensure that the
repeating timer has a constant period between firings.

This guarantees that it will not queue up new events to fire the
callback until the previous callback event finishes.  This means,
that if the callback takes a long time to evaluate, the next
evaluation is only scheduled after it returns.  This will prevent
firings to happen after the timeout duration has elapsed.
Attachment #9009080 - Flags: review?(hskupin)
Attachment #9009063 - Attachment is obsolete: true
Looking closer at this, changing PollPromise to
TYPE_REPEATING_PRECISE_CAN_SKIP makes a lot more sense.  Thanks for
the constructive review.
Comment on attachment 9009080 [details] [diff] [review]
marionette: make PollPromise more precise

Review of attachment 9009080 [details] [diff] [review]:
-----------------------------------------------------------------

That patch looks way better. If try is happy for a TV test job, then lets land it!
Attachment #9009080 - Flags: review?(hskupin) → review+
Pushed by ato@sny.no:
https://hg.mozilla.org/integration/mozilla-inbound/rev/433f1ab89061
marionette: make PollPromise more precise; r=whimboo
Backout by nbeleuzu@mozilla.com:
https://hg.mozilla.org/integration/mozilla-inbound/rev/b5050dd99c14
Backed out changeset 433f1ab89061 for xpcshell failures on test_sync.js. CLOSED TREE
My only theory at the moment is that Android 4.3 API16+ debug is
_so slow_ that it takes longer than 30 seconds to set up the test
and run it.  With Ci.nsITimer.TYPE_REPEATING_SLACK we were guaranteed
that some callbacks would fire, but with TYPE_REPEATING_PRECISE_CAN_SKIP
I suppose we’re not if the timeout duration is hit first.
Flags: needinfo?(ato)
From a recent test run on inbound I found that it on average takes
about ~11 seconds to run test_sync:

> task 2018-09-19T03:02:19.587Z] 03:02:19     INFO -  TEST-START | testing/marionette/test/unit/test_sync.js
> task 2018-09-19T03:02:31.219Z] 03:02:31     INFO -  TEST-PASS | testing/marionette/test/unit/test_sync.js | took 11632ms

The timeout we are seeing here is five minutes (300,002 ms), which
should be ample time for the test to complete.
https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
Status: ASSIGNED → RESOLVED
Closed: 1 year ago
Resolution: --- → INCOMPLETE
You need to log in before you can comment on or make changes to this bug.