test: microtask-queue-run(-domain) should be made non-flaky

[joaocgreis]

test-microtask-queue-run and test-microtask-queue-run-domain appear to be flaky (PR: #25606), failing very rarely. Testing 10k runs on the platforms I have available, I got failure rates as high as:

• Linux x64: OK: 9964 NOT OK: 36
• Windows 7 x64: OK: 9843 NOT OK: 157
• SmartOS x86 (gcc 4.7): OK: 9904 NOT OK: 96

The results appear to be influenced by the machine load, I got much lower results on an otherwise idle machine.

Quick test:

time (OK=0; NOK=0; for i in `seq 10000`; do ./out/Release/node test/simple/test-microtask-queue-run.js && OK=$(($OK+1)) || NOK=$(($NOK+1)); echo "$i   OK: $OK   NOT OK: $NOK"; done)

Other tests from test-microtask-queue-* seem okay.

[joaocgreis]

/cc @joyent/node-collaborators

[tunniclm]

It looks like the callbacks are executing in a different order sometimes.
I reduced that order difference to this test:

var assert = require('assert');

setTimeout(function() { /* A */
        var called = false;
        process.nextTick(function() { called = true; }); /* B */
        setTimeout(function() { assert(called) }, 0); /* C */
}, 0);

This fails sometimes because the callback on line (C) fires before the callback on line (B). This looks to be the same thing that causes the microtask-queue-run.js test to sometimes fail.

Interestingly, this variant does not fail for me:

var assert = require('assert');

var called = false;
process.nextTick(function() { called = true; });
setTimeout(function() { assert(called) }, 0);

[tunniclm]

Looking at the API doc it seems like process.nextTick() callbacks will run at the head of the event loop, setTimeout() callbacks will happen in the middle (with the other IO) and setImmediate() callbacks (from setImmediate) will run at the end. [EDIT: this was wrong, see a couple of comments down]

This test also doesn't fail for me:

var assert = require('assert');

setTimeout(function() {
        var called = false;
        process.nextTick(function() { called = true; });
        setImmediate(function() { assert(called) });
}, 0);

[tunniclm]

Finally, this test does fail sometimes:

var assert = require('assert');

setTimeout(function() {
        var called = false;
        setImmediate(function() { called = true; });
        setTimeout(function() { assert(called) },0);
}, 0);

So it looks like setTimeout() can run on the same event loop iteration on which it was enqueued and that can cause it to occur first (before process.nextTick() or setImmediate() callbacks enqueued within the same loop iteration).

[tunniclm]

Looks like I got the ordering slightly wrong. The setImmediate() API doc implies it's this:

1. process.nextTick() callbacks
2. IO callbacks
3. setImmediate() callbacks
4. setTimeout() / setInterval() callbacks

Also, note that setImmediate() callbacks will execute on the iteration after they were enqueued. (EDIT: This explains why changing the process.nextTick() to a setImmediate() had no effect on the failure behaviour).

[tunniclm]

So, I'm not 100% sure of the intention of the original test, but it looks like it would be appropriate to change the setTimeout() on test/simple/test-microtask-queue-run.js:53 to be a setImmediate() instead.

[mhdawson]

This test seems to fail quite regularly in our internal IBM builds, @tunniclm you may be able to validate your changes there.

[misterdjules]

@tunniclm @mhdawson Although I'm not the original author of the test, its intention seems to make sure that microtasks run at the appropriate time compared to timers' and process.nextTick's callbacks.

The reason why this test is flaky is described in one comment of the PR that fixes it.

[tunniclm]

@misterdjules I looked through that thread on Friday (and the original commit that added the test) as I started to get back to looking at issues (I was unavailable for a few weeks).

From that, my understanding is that the tests are there to ensure that the V8 microtask queue used to process the "built-in" Promises were being executed at the right time in comparison to setImmediate(), setTimeout() and process.nextTick(). Particularly when there were nested callbacks.

What I found in my exploration of nested setTimeout() calls is that it is possible to add a timeout in a timeout callback such that it fires on the same iteration of the event loop in which it was added. I didn't see a note in the documentation to say whether this should be allowed or not (whereas there is such a note for setImmediate()), but perhaps I missed it?

The above PR assumes that this scenario should not be allowed and if that is correct, then it looks like a good fix for this issue. And in that case I think we should update the doc to describe this contract under https://nodejs.org/api/timers.html#timers_settimeout_callback_delay_arg .

[misterdjules]

@tunniclm Continued this discussion in the PR that fixes this issue itself, so that it's easier to see the actual changes along the comments: #25763 (comment).