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

Question

我们有一个Java应用程序需要在虚拟(Hyper-V)Windows 2012 R2 Server上运行,以及其他环境.在此虚拟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);
}

此代码应每10ms运行一次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问题？Hyper-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()粒度引起的。请注意那里的评论：

请注意，虽然返回值的时间单位是毫秒，但该值的粒度取决于底层操作系统，并且可能会更大。

15不久前我在一台机器上记录了大约ms的粒度。这可以解释您看到的所有值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被叫到但还没有踢掉其中的一个蜱虫时。请注意，正如我所建议的，在 处显示出清晰的峰值。10msSystem.currentTimeMillis()15=58515ms

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