Timing change in Vertx.setTimer

[ianstewart-bls]

Version

5.0.5

Context

I have used Vertx to write a loop where the looping mechanism uses Vertx.runOnContext(Handler). The loop's condition uses an AtomicBoolean which is updated externally to the loop with Vertx.setTimer(long, Handler). The delay for vertx.setTimer is 100 ms. On Vertx 4.5.15, the timer triggers after 100ms as expected. On 5.0.5, it consistently triggers after 1s. I have attached a JUnit test to reproduce it.

Steps to reproduce

Run the following with JUnit on version 4.5.15 (passes) and 5.0.5 (fails). On 4.5.15, "final delay" is 106 on my machine, as expected.

package x;

import io.vertx.core.Promise;
import io.vertx.core.Vertx;
import io.vertx.junit5.VertxExtension;
import io.vertx.junit5.VertxTestContext;
import org.junit.jupiter.api.Test;
import org.junit.jupiter.api.extension.ExtendWith;

import java.util.concurrent.atomic.AtomicBoolean;

import static org.assertj.core.api.AssertionsForClassTypes.assertThat;

@ExtendWith(VertxExtension.class)
class VertxTest {
    private final AtomicBoolean closed = new AtomicBoolean(false);
    private Vertx vertx;
    private Promise<Void> promise;

    private void loop() {
        if (closed.get()) {
            System.out.println("Stopping loop");
            promise.complete();
            return;
        }
        vertx.runOnContext(v -> this.loop());
    }

    @Test
    void test(Vertx vertx, VertxTestContext context) {
        this.vertx = vertx;
        this.promise = Promise.promise();
        loop();
        long start = System.currentTimeMillis();
        vertx.setTimer(100, l -> {
            System.out.println("setTimer delay: " + (System.currentTimeMillis() - start));
            closed.set(true);
        });

        promise.future().onComplete(context.succeeding(v -> {
            long finalDelay = System.currentTimeMillis() - start;
            System.out.println("Final delay: " + finalDelay);
            assertThat(finalDelay).isLessThan(1000L);
            context.completeNow();
        }));
    }
}

Do you have a reproducer?

No response

[vietj]

@ianstewart-bls the behavior change stems from Netty tasks scheduling differences between 4.1 and 4.2 and the way your test is written.

Basically your test does not count the number of tasks it schedules on the event-loop (there is no budget, e.g. which could be execute at most X tasks per milliseconds, instead it is : execute as much as you can).

Netty 4.1 will allow to queue at most 64 tasks before timers are checked.
Netty 4.2 executes as many tasks possible for a duration of 1 second (which is configurable).

From there there are two possibilities:

1. we consider the test relies on an intrinsic behavior of Netty and we modify it to use a budget (which is more robust)
2. we configure Netty to check more often with the system property io.netty.eventLoop.maxTaskProcessingQuantumMs and we set it to 100 milliseconds, that will schedule the timer that the test accepts

Eventually if you need an aggressive way of schedule tasks, you perhaps should instead dedicate a thread for this purpose using something like a pacer (https://github.com/vietj/http2-bench/blob/0c54b25dfa033a1f1e37f21d81856c0e88f180a1/src/main/java/http2/bench/client/Pacer.java#L5)

For now, I will consider this is not a regression but instead a behavior change.