为什么我的System.nanoTime()坏了?

我自己和我这个时代的另一位开发人员最近从工作中的Core 2 Duo机器搬到了新的Core 2 Quad 9505; 两者都使用JDK 1.6.0_18运行Windows XP SP3 32位。

在这样做的时候,我们对一些时序/统计/度量聚合代码的自动unit testing很快就会失败,因为看起来似乎是从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 

100x运行产生纳米结果,占实际睡眠时间的33%至60%; 通常约为40%。

我理解Windows中计时器准确性的弱点,并且读过线程之间的相关线程如Is 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那样的补丁。 也许我应该与企业桌面构建团队一起解决这个问题?

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

在我的系统上(Windows 7 64位,Core i7 980X):

 nanosTaken=4999902563 millisTaken=5001 

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

您可能想要阅读其他堆栈溢出问题的答案: System.nanoTime()完全没用吗? 。

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

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

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

另外,为了排除电源管理效果,尝试在循环中旋转以替代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); } 

如果根据核心选择得到非常不同的结果(例如,在同一核心上为5000ms但在不同核心上为2200ms),这表明问题只是核心之间的自然定时器变化。

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

如果四个结果中没有一个接近5000毫秒,那么它可能是一个错误。