虚拟 Windows 服务器上的 Java 调度程序执行程序计时问题

Question

我们有一个 Java 应用程序需要在虚拟 (Hyper-V) Windows 2012 R2 服务器上以及其他环境中运行。在这个虚拟 Windows 服务器上执行时，它似乎遇到了奇怪的计时问题。我们已将问题追溯到 Java 调度执行程序中的不稳定调度:

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);
}

此代码应每 10 毫秒运行一次 TimeRunnable，在服务器上产生如下结果:

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

而在其他机器上，包括负载很重的虚拟 Linux 机器，以及一些 Windows 桌面，典型的运行看起来像这样:

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

我们在 Windows Server 和 Hyper-V 方面经验不多，所以有人可以解释一下这种现象吗？它是 Windows Server 问题吗？ super V？这些平台上的 Java 错误？有解决办法吗？

编辑:一位同事编写了同一程序的 C# 版本:

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();
}

这是在虚拟 Windows 服务器上并行工作的两个应用程序的更新(部分)屏幕截图:

编辑:Java 程序的其他一些变体都产生(几乎)相同的输出:

1. 一种变体，其中 System.nanoTime() 被替换为 System.currentTimeMillis()
2. 一种变体，其中 System.out.println() 被定期打印的 StringBuilder 替换
3. 一种变体，其中调度机制被替换为单个线程，该线程通过 Thread.sleep()
为自身计时
4. lastRunAt 可变的变体

Answer 1

这是由 System.currentTimeMillis() 引起的粒度。请注意那里的评论:

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.

我前阵子在一台机器上记录了大约15ms的粒度。这可以解释您看到的所有 0 值，但不能解释大值。

运行测试的增强版本:

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);
}

我得到输出:

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}

巨大的异常值是第一个命中 - 当 lastRunAt 为零时。 0=361 是当您在 10ms 之后被调用但 System.currentTimeMillis() 没有跳过它的一个滴答声时。请注意 15=585 处的峰值，正如我建议的那样，在 15ms 处显示出清晰的峰值。

我对 62=1 没有任何解释。