11

我和我的另一位开发人员最近从工作中的 Core 2 Duo 机器转移到了新的 Core 2 Quad 9505；两者都运行带有 JDK 1.6.0_18 的 Windows XP SP3 32 位。

这样做后，我们对一些计时/统计/指标聚合代码的一些自动化单元测试立即开始失败，因为从 System.nanoTime() 返回的值似乎很荒谬。

在我的机器上可靠地显示这种行为的测试代码是：

import static org.junit.Assert.assertThat;

import org.hamcrest.Matchers;
import org.junit.Test;

public class NanoTest {

  @Test
  public void testNanoTime() throws InterruptedException {
    final long sleepMillis = 5000;

    long nanosBefore = System.nanoTime();
    long millisBefore = System.currentTimeMillis();

    Thread.sleep(sleepMillis);

    long nanosTaken = System.nanoTime() - nanosBefore;
    long millisTaken = System.currentTimeMillis() - millisBefore;

    System.out.println("nanosTaken="+nanosTaken);
    System.out.println("millisTaken="+millisTaken);

    // Check it slept within 10% of requested time
    assertThat((double)millisTaken, Matchers.closeTo(sleepMillis, sleepMillis * 0.1));
    assertThat((double)nanosTaken, Matchers.closeTo(sleepMillis * 1000000, sleepMillis * 1000000 * 0.1));
  }

}

典型输出：

millisTaken=5001
nanosTaken=2243785148

运行 100 倍会产生实际睡眠时间的 33% 到 60% 之间的纳米结果；不过通常在 40% 左右。

我了解 Windows 中计时器准确性的弱点，并已阅读相关线程，例如System.nanoTime() 跨线程是否一致？，但是我的理解是 System.nanoTime() 正是为了我们使用它的目的而设计的：-测量经过的时间；比 currentTimeMillis() 更准确。

有谁知道为什么它会返回如此疯狂的结果？这可能是硬件架构问题（唯一改变的主要是这台机器上的 CPU/主板）？我当前的硬件存在 Windows HAL 问题？JDK问题？我应该放弃 nanoTime() 吗？我应该在某处记录错误，还是对如何进一步调查提出任何建议？

更新 19/07 03:15 UTC：在尝试了下面 finnw 的测试用例后，我做了一些谷歌搜索，遇到了诸如bugid:6440250 之类的条目。这也让我想起了周五晚些时候我注意到的其他一些奇怪的行为，其中 ping 恢复为负数。所以我将/usepmtimer添加到我的 boot.ini 中，现在所有测试都按预期运行。我的 ping 也正常。

不过，我对为什么这仍然是一个问题感到有些困惑；根据我的阅读，我认为 TSC 与 PMT 的问题在 Windows XP SP3 中得到了很大的解决。可能是因为我的机器原本是 SP2 的，并且被修补到 SP3 而不是最初安装为 SP3 吗？我现在也想知道我是否应该安装像MS KB896256这样的补丁。也许我应该与公司桌面构建团队一起讨论这个问题？

4

4 回答 4

7

通过将/usepmtimer添加到我的C:\boot.ini字符串的末尾，问题得到了解决（对 nanoTime() 在多核系统上的适用性存在一些公开的怀疑！） ；强制 Windows 使用电源管理计时器而不是 TSC。鉴于我使用的是 XP SP3，为什么我需要这样做是一个悬而未决的问题，因为我知道这是默认设置，但也许是由于我的机器被修补到 SP3 的方式。

于 2010-07-23T06:36:58.820 回答
2

在我的系统上（Windows 7 64 位，Core i7 980X）：

nanosTaken=4999902563
millisTaken=5001

System.nanoTime() 使用特定于操作系统的调用，因此我希望您在 Windows/处理器组合中看到错误。

于 2010-07-18T10:15:10.117 回答
1

您可能想阅读另一个堆栈溢出问题的答案：System.nanoTime() 完全没用吗？.

总之，nanoTime 似乎依赖于可能受到多核 CPU 存在影响的操作系统计时器。因此，nanoTime 在操作系统和 CPU 的某些组合上可能没有那么有用，在您打算在多个目标平台上运行的可移植 Java 代码中使用它时应该小心。网络上似乎有很多关于这个主题的抱怨，但对于有意义的替代方案却没有太多共识。

于 2010-07-18T09:10:52.567 回答
1

很难判断这是一个错误还是只是内核之间的正常计时器变化。

您可以尝试的一个实验是使用本机调用来强制线程在特定内核上运行。

此外，要排除电源管理影响，请尝试循环旋转以替代sleep()：

import com.sun.jna.Native;
import com.sun.jna.NativeLong;
import com.sun.jna.platform.win32.Kernel32;
import com.sun.jna.platform.win32.W32API;

public class AffinityTest {

    private static void testNanoTime(boolean sameCore, boolean spin)
    throws InterruptedException {
        W32API.HANDLE hThread = kernel.GetCurrentThread();
        final long sleepMillis = 5000;

        kernel.SetThreadAffinityMask(hThread, new NativeLong(1L));
        Thread.yield();
        long nanosBefore = System.nanoTime();
        long millisBefore = System.currentTimeMillis();

        kernel.SetThreadAffinityMask(hThread, new NativeLong(sameCore? 1L: 2L));
        if (spin) {
            Thread.yield();
            while (System.currentTimeMillis() - millisBefore < sleepMillis)
                ;
        } else {
            Thread.sleep(sleepMillis);
        }

        long nanosTaken = System.nanoTime() - nanosBefore;
        long millisTaken = System.currentTimeMillis() - millisBefore;

        System.out.println("nanosTaken="+nanosTaken);
        System.out.println("millisTaken="+millisTaken);
    }

    public static void main(String[] args) throws InterruptedException {
        System.out.println("Sleeping, different cores");
        testNanoTime(false, false);
        System.out.println("\nSleeping, same core");
        testNanoTime(true, false);
        System.out.println("\nSpinning, different cores");
        testNanoTime(false, true);
        System.out.println("\nSpinning, same core");
        testNanoTime(true, true);
    }

    private static final Kernel32Ex kernel =
        (Kernel32Ex) Native.loadLibrary(Kernel32Ex.class);

}

interface Kernel32Ex extends Kernel32 {
    NativeLong SetThreadAffinityMask(HANDLE hThread, NativeLong dwAffinityMask);
}

如果您根据内核选择得到非常不同的结果（例如，在同一内核上为 5000 毫秒，但在不同内核上为 2200 毫秒），这表明问题只是内核之间的自然计时器变化。

如果您从睡眠与旋转中得到非常不同的结果，则更有可能是由于电源管理减慢了时钟。

如果四个结果都没有接近 5000ms，那么它可能是一个错误。

于 2010-07-18T11:54:19.940 回答