GeezerVison

I'm not too fond of this way of doing things.

I suggest re-writing the test to be more like https://github.com/nodejs/node/blob/master/test/parallel/test-timers-unref-active-unenrolled-disposed.js

Particularly, it is more reliable to depend on the order of timer execution rather than arbitrary timeouts.

A master timeout is, however, necessary to keep the process open. That being said, the last unrefed timeout should be able to tell when it has succeed and cancel the master timeout.

i.e.

setTimeout(b, 2)
setTimeout(a, 1)

b will always be called last. You must register the longer timers first.

Actually, that exact order may not be correct for "regular" timers, in my test it applied to _unrefActive, which is... a little different. I'll look more in detail soon.

I made some changes to look more like https://github.com/nodejs/node/blob/master/test/parallel/test-timers-unref-active-unenrolled-disposed.js. Mainly so that the master timeout is cleared as soon as the last unrefd interval fires.

@mhdawson what are the sort of specs of an AIX machine? I am highly curious how 5 1ms timers could take more than 100ms.

I think I may have gotten it wrong and its zLinux. as opposed to AIX. I think the main issue is that we have a good number of VMs sharing the same hardware. Its not that it fails all the time only that we see intermittent failures. @thinkingdust can you talk to Joran and provide more details if you have them.

In terms of platform timeout I don't want to extend the length of all AIX tests because we see intermittent failures on a few tests.

The original failure was on zLinux so a platform specific change won't do.
With the updates, the test now clears the master timeout on success so its length will only matter when deciding that the test has failed.
I don't think the failure has repeated so I think we could keep the original 100ms.
/cc @joransiu

LGTM if common.platformTimeout(500); is 100 then.

I'd really like to know if @joransiu or anyone else has any insight as to how that could be happening though.

I think the failure was caused by other processes running on the CI machine. I can replicate the failure with the bash script below. The failure rate can be controlled by changing the number of background processes.

#!/bin/bash

NUM_PROCESSES=32
for j in `seq 1 $NUM_PROCESSES`;
do
  k=0
  while [ $k -lt 1000000 ]
  do
    ((k++))
  done &
done

pass=0
fail=0
output=""
for i in `seq 1 100`;
do
  output=$(./node test/parallel/test-timers-unrefd-interval-still-fires.js 2>&1)
  len=${#output}
  if [ $len -eq 0 ]; then
    ((pass++))
  else
    ((fail++))
  fi
  if [ $i -ne 1 ]; then
    echo -en "\e[1A"
  fi
  echo pass $pass : fail $fail
done
wait

@thinkingdust Any idea how many processor-level threads that machine has?

Like, are you literally just clogging everything up that much that the timer doesn't get run?

I had suggested a few experiments with @thinkingdust to get a better gauge on various timeout values for our Linux on Z configuration. The machine we are running on is a guest Linux system running with 8 CPs on zEC12 @ 5.5GHz => 8 processor level threads available.

With relative little load on the system, our very informal measurements:

Now, if we ran 8 instances in parallel... @ 100ms timeout, we observe a failure rate of about 1%. I'd say given these stats, 100ms is probably reasonable.

Keep open timeout has been changed back to 100ms.

8 CPs on zEC12 @ 5.5GHz => 8 processor level threads available.

That should never fail this.

Is it possible libuv isn't scheduling these efficiently on AIX?

LGTM minus the comment.

I made the change to throw the same error as https://github.com/nodejs/node/blob/master/test/parallel/test-timers-unref-active-unenrolled-disposed.js#L14

I think it was slightly useful to print nbIntervalFired to see if the interval callback ran at all. Is it a good idea to include that?

@thinkingdust sure.

@Fishrock123 Is this format okay?

Was going to land squashed as

    test: fix race condition in unrefd interval test

    The test now relies more on timers implementation rather than arbitrary
    timeouts, and will cancel a master timeout once complete.

    Refs: https://github.com/nodejs/node/issues/1781
    PR-URL: https://github.com/nodejs/node/pull/3550
    Reviewed-By: Michael Dawson <[email protected]>
    Reviewed-By: Jeremiah Senkpiel <[email protected]>

@thinkingdust But I think I actually missed something, sorry, we should harden the test a bit more.

@Fishrock123 Any more suggestions for this PR?

CI: https://ci.nodejs.org/job/node-test-pull-request/789/

Thanks, landed in 6de82c6

(Squashed and updated description)

I don't think I understand why 6de82c6 would fix the race condition and make the test fail less often in the situation described in the first comment of this PR. Am I missing something?

Ugh, guess I should have updated the description.

It doesn't fix it per se, but it does refactor the test to work in a more reliable fashion.

Ultimately if your 5 1ms timers aren't firing in under like 25ms you've probably got serious hardware problems, or armv6.

One way to fix the flakiness of this test would be to rely on the tests suite's per-test timeout (which is currently set to 60 seconds) and instead of adding a timer to hold the loop open (which would require us to hardcode this 60 seconds tests suite timeout somewhere else, or refactor the tests suite driver so that it can communicate that value to JS tests), we could add another type of handle that holds the loop open indefinitely, like a net.Server instance.

When the fifth timer's callback is called, we can close that handle and the test would exist asap in most cases, or the tests suite would make it time out in case it would fail. But we would get rid of almost all false positives.

When the fifth timer's callback is called, we can close that handle and the test would exist asap in most cases, or the tests suite would make it time out in case it would fail.

That's what happens now.

If 5 1ms timers fail within <100ms there are issues, this isn't just flakiness.

As it stands, this patch appears to have corrected the original issue.

When the fifth timer's callback is called, we can close that handle and the test would exist asap in most cases, or the tests suite would make it time out in case it would fail.

That's what happens now.

It seems that what happens now is that the test will fail if the 5 timers' callbacks haven't run within 100 ms. According to @mhdawson and @joransiu it is possible that on systems with high load, 5 timers' callbacks take longer than 100ms to run, which seems entirely plausible. That doesn't mean that unrefed timers are broken, but still it seems that this change would make the test fail in these situations. That would make the test flaky.

What I was describing is a way to give much more time for these timers to fire, not just 100ms, without making the best cases take longer, and without hardcoding the expiry delay for the handle that keeps the loop open. I believe that would make the test non flaky.

As it stands, this patch appears to have corrected the original issue.

Do you mean that it fixes #1781, or that it fixes the problems reported by @mhdawson, or both?

If I'm not missing anything, 6de82c6 has been pushed today, and #1781 was closed on July 28th, so I don't know how we can determine that this change fixed that issue.