Reactor-core: Flaky tests on Windows when using Mono.timeout

[wilkinsona]

Expected Behavior

Mono.timeout works consistently.

Actual Behavior

I’m seeing a test failure in Boot’s CI on Windows where it looks as if a Mono.timeout(timeout, fallback) is falling back before the timeout has elapsed. The timeout in the test is 100ms so it should take at least 100ms to run and it does on my Mac. When it failed on Windows, the test completed in 79ms, hence my suspicion that the timeout popped too soon. I’ve only seen it fail on Windows.

Steps to Reproduce

This is the test that's failing and you can see some example failures here.

I've attempted to reproduce the problem with something minimal, and this fails in a quite similar way a few times in 100 in a Windows VM:

@Test
@RepeatedTest(100)
void timeoutWorksAsExpected() {
    Mono<StringBuffer> result = Flux.fromIterable(Arrays.asList("a", "b"))
            .flatMap((entry) -> Mono.delay(Duration.ofMillis((entry.equals("a") ? 10000 : 10))).map((l) -> entry)
                    .transformDeferred((mono) -> mono.timeout(Duration.ofMillis(100), Mono.just("z"))))
            .collect(StringBuffer::new, (buffer, string) -> buffer.append(string));
    StepVerifier.create(result).consumeNextWith((builder) -> {
        assertThat(builder.toString()).isEqualTo("bz");
    }).verifyComplete();
}

Your Environment

The CI failures are on Windows Server 2016 10.0 with Reactor 3.3.8.RELEASE running on AdoptOpenJDK 1.8.0_212-b03.

[wilkinsona]

We're also seeing the failure with Reactor 3.4.0.M1. Here's the build scan.

[simonbasle]

Mono.timeout and Mono.delay are fairly straightforward, so I doubt this is an issue with Reactor itself, but probably the ScheduledExecutorService and underlying System.nanoTime()/System.currentTimeMillis() implementations on Windows (maybe combined with the VM hypervisor?)

That said, just to be sure it is linked to the delay or timeout, the test above can be further simplified with a removal of the transformDeferred (you can directly apply the .timeout to the Mono.delay(Duration.ofMillis((entry.equals("a") ? 10000 : 10))).map((l) -> entry). Can you test with that simplification?

[wilkinsona]

It's hard to say if it's made a difference, unfortunately. I originally discussed the problem with @bsideup in March. I've moved to a new laptop and a new Windows VM since then. I've seen the test as shown above fail once in several runs. I haven't seen it fail at all without transformDeferred but the failure rate with it isn't high enough to be sure that means anything.

[wilkinsona]

The test on CI fails fairly often. It might be worth you asking Trevor if you can get remote desktop access to the worker and run some experiments there.

[wilkinsona]

The test in Boot failed again today.

[bsideup]

I was able to reproduce the issue. While debugging I also figured that, on Windows, under heavy load, the timers have a very low precision. e.g. this test fails when I run it and some CPU stress test:

@RepeatedTest(1000)
void windowsTimersPrecision() throws Exception {
    Scheduler scheduler = Schedulers.parallel();

    long nanoTime = System.nanoTime();
    FutureTask<Long> task = new FutureTask<>(System::nanoTime);

    scheduler.schedule(task, 50, TimeUnit.MILLISECONDS);
    Long resolvedAt = task.get();

    assertThat(resolvedAt - nanoTime).isLessThan(TimeUnit.MILLISECONDS.toNanos(150));
}

Since we don't have our own timers logic and delegate everything to JVM (via ScheduledExecutorService#schedule), I am not really sure we can do anything here.

What I allso noticed is that the windowsTimersPrecision test was passing if I use "isLessThan 200ms" assertion.
@wilkinsona you may consider playing with the timeout values you use, given this knowledge.

[wilkinsona]

I made the suggested changes to the test in Boot on 26 August. At the time of writing it has passed 5 times since then and has yet to fail. That's pretty good compared to its recent behaviour. We'll keep an eye on it, but the initial signs are looking hopeful.

[bsideup]

@wilkinsona do you think we can close this issue now? :)

[wilkinsona]

Thanks for the nudge. I'd forgotten to check the test results. I've just done that now and it's certainly better, but there has still been two flakey failures since 26 August. Perhaps I should further widen the timeout? It's 250ms now.