Java scheduler executor timing issues on virtual windows server

Question

We have a Java application that needs to run, among other environments, on a Virtual (Hyper-V) Windows 2012 R2 Server. When executed on this virtual Windows server, it seems to experience weird timing issues. We've traced the issue to erratic scheduling in a Java scheduled executor:

public static class TimeRunnable implements Runnable {

    private long lastRunAt;

    @Override
    public void run() {
        long now = System.nanoTime();
        System.out.println(TimeUnit.NANOSECONDS.toMillis(now - lastRunAt));
        lastRunAt = now;
    }

}

public static void main(String[] args) {
    ScheduledExecutorService exec = Executors.newScheduledThreadPool(1);
    exec.scheduleAtFixedRate(new TimeRunnable(), 0, 10, TimeUnit.MILLISECONDS);
}

This code, which should run the TimeRunnable every 10ms, produces results such as these on the server:

12
15
2
12
15
0
14
16
2
12
140
0
0
0
0
0
0
0
0
0
0
0
0
1
0
7
15
0
14
16
2
12
15
2
12
1
123
0
0
0

While on other machines, including heavily loaded virtual Linux boxes, as well as some windows desktops, a typical run looks like this:

9
9
10
9
10
9
10
10
9
10
9
9
10
10
9
9
9
9
10
10
9
9
10
10
9
9
10
9
10
10
10
11
8
9
10
9
10
9
10
10
9
9
9
10
9
9
10
10
10
9
10

We don't have a lot of experience with Windows Server and Hyper-V, so can anyone offer an explanation for this phenomena? It it a Windows Server issue? Hyper-V? A Java bug on these platforms? Is there a solution?

EDIT: A colleague has written a C# version of the same program:

private static Stopwatch stopwatch = new Stopwatch();

public static void Main()
{
    stopwatch.Start();
    Timer timer = new Timer(callback, null, TimeSpan.FromMilliseconds(10), TimeSpan.FromMilliseconds(10));
}

private static void callback(object state)
{
    stopwatch.Stop();
    TimeSpan span = stopwatch.Elapsed;
    Console.WriteLine((int)span.TotalMilliseconds);
    stopwatch.Restart();
}

Here's an updated (partial) screenshot of both applications working side by side on the virtual windows server:

EDIT: A few other variants of the Java program all produce (pretty much) the same output:

1. A variant in which System.nanoTime() was replaced with System.currentTimeMillis()
2. A variant in which System.out.println() was replaced with a periodically printed StringBuilder
3. A variant in which the scheduling mechanism was replaced with a single thread that times itself through Thread.sleep()
4. A variant in which the lastRunAt is volatile

Answer 1

This is caused by the System.currentTimeMillis() granularity. Note the comment there:

Note that while the unit of time of the return value is a millisecond, the granularity of the value depends on the underlying operating system and may be larger.

I recorded a granularity of about 15ms on one machine a while back. This would explain all of the 0 values you are seeing but not the big values.

Running an enhanced version of your test:

static final TreeMap<Long, AtomicInteger> counts = new TreeMap<>();

public static final AtomicInteger inc(AtomicInteger i) {
    i.incrementAndGet();
    return i;
}

public static class TimeRunnable implements Runnable {

    private long lastRunAt;

    @Override
    public void run() {
        long now = System.nanoTime();
        long took = TimeUnit.NANOSECONDS.toMillis(now - lastRunAt);
        counts.compute(took, (k, v) -> (v == null) ? new AtomicInteger(1) : inc(v));
        //System.out.println(TimeUnit.NANOSECONDS.toMillis(now - lastRunAt));
        lastRunAt = now;
    }

}

public void test() throws InterruptedException {
    System.out.println("Hello");
    ScheduledExecutorService exec = Executors.newScheduledThreadPool(1);
    exec.scheduleAtFixedRate(new TimeRunnable(), 0, 10, TimeUnit.MILLISECONDS);
    // Wait a bit.
    Thread.sleep(10000);
    // Shut down.
    exec.shutdown();
    while (!exec.awaitTermination(60, TimeUnit.SECONDS)) {
        System.out.println("Waiting");
    }
    System.out.println("counts - " + counts);
}

I get the output:

counts - {0=361, 2=1, 8=2, 13=2, 14=18, 15=585, 16=25, 17=1, 18=1, 22=1, 27=1, 62=1, 9295535=1}

The huge outlier is the first hit - when lastRunAt is zero. The 0=361 was when you were called 10ms later but System.currentTimeMillis() had not kicked over one of it's ticks. Note the peak at 15=585 showing a clear peak at 15ms as I suggested.

I have no explanation for the 62=1.

Answer 2

I also don't know why it is happening. However, it is unlikely to be Java's fault. Java uses native threads, which means that thread scheduling is handled by "the operating system".

I think the real problem here is that you have built an application based on a false premise. If you read the Java documentation (for a normal / non-real-time JVM) you won't find anything that says that Java thread scheduling is accurate. Even scheduling priorities are "best effort".

The fact that you have observed scheduling to be reasonably accurate on a heavily loaded Linux VM is interesting ... but not necessarily instructive. Scheduling accuracy will depend on the nature of the load on the system. And probably one whether there is significant "overcommit" of memory, VCPUs, and I/O bandwidth in the platform.

---

Is there a solution?

Maybe you could figure a way to make scheduling more "accurate" on your platform (on a good day with a following wind). However, you won't get any guarantees of accuracy unless you switch to real-time OS and a real-time Java release. You won't find any real-time Java implementations for a virtualized platform. So the real solution is to avoid relying on accurate scheduling.

Answer 3

I think you need to increase priority of the java application process and worker thread inside java application both. Its easy to increase priority of worker thread inside java application. But its tricky to set java application to get higher cpu than what you are getting. Probably this might help in getting higher cpu for your program

How to change the priority of a running java process?

https://blogs.msdn.microsoft.com/oldnewthing/20100610-00/?p=13753

You can also give a look to get real time cpu but please note that it can delay your other kernel activities including mouse and keyboard events

The delay is definitely due to task couldn't start at the specified time and hence the next task got triggered before the period time to adjust the fixed rate as mentioned here: Java Timer

Answer 4

1. Most of modern HW provides multiple timer sources. Additionally, most of operation systems provide several APIs to access these timer counters with different precision (For example System timer and RTC). Knowing Microsoft, .NET platform (as well as most of MS products) utilizes intimate knowledge of Win32 API and kernel APIs. My intuition says that Timer class in C# uses different API than Java (Hotspot VM implementation described here, though it's correct for Java 5).

2. There is generic problem with timer precision in virtual environments. I found very interesting test results http://www.ncbi.nlm.nih.gov/pmc/articles/PMC4503740/ describing similar issues with different hypervisors. The funny thing that Hyper-V not mentioned there, but the problem looks like not unique for the particular setup. Microsoft has an issue regarding timers correctness provided by Hyper-V running on Windows 2008 R2. god knows what's running in cloud for different cloud providers. I personally was able to reproduce the issue on AWS cloud.

3. So the answer to "What's this effect is" - It's hypervisors bug combined with Java implementation "features". To be sure, you can try running this test with OpenJDK where you can see the code and play with different timer sources.

4. But for practical reasons I suggest to avoid running timer-sensitive Java code on Windows VM. In case this is very hard requirement, I would try use Win32 timer and call JVM code from there (using JNI) or implement any other timer source (using named pipe or any other platform-specific patch). You can try using Quartz as timer and scheduler, but it's probably suffering from the same problem as well.