为什么我的 System.nanoTime() 坏了?
我自己和另一位开发人员最近从工作中的 Core 2 Duo 机器转移到了新的 Core 2 Quad 9505;都运行带有 JDK 1.6.0_18 的 Windows XP SP3 32 位.
Myself and another developer on my time recently moved from a Core 2 Duo machine at work to a new Core 2 Quad 9505; both running Windows XP SP3 32-bit with JDK 1.6.0_18.
这样做后,我们对一些计时/统计/指标聚合代码的一些自动化单元测试立即开始失败,因为 System.nanoTime() 返回的值似乎很荒谬.
Upon doing so, a couple of our automated unit tests for some timing/statistics/metrics aggregation code promptly started failing, due to what appear to be ridiculous values coming back from System.nanoTime().
在我的机器上可靠地显示这种行为的测试代码是:
Test code that shows this behaviour, reliably, on my machine is:
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% 左右.
Running it 100x yields nano results between 33% and 60% of the actual sleep time; usually around 40% though.
我了解 Windows 中计时器准确性的弱点,并已阅读相关主题,例如 System.nanoTime() 跨线程是否一致?,但是我的理解是 System.nanoTime() 正是为了我们使用它的目的而设计的:- 测量经过的时间;比 currentTimeMillis() 更准确.
I understand the weaknesses in accuracy of timers in Windows, and have read related threads like Is System.nanoTime() consistent across threads?, however my understanding is that System.nanoTime() is intended for exactly the purpose we're using it :- measuring elapsed time; more accurately than currentTimeMillis().
有谁知道为什么它会返回如此疯狂的结果?这可能是硬件架构问题(唯一改变的主要是这台机器上的 CPU/主板)?我当前的硬件存在 Windows HAL 问题?JDK问题?我应该放弃 nanoTime() 吗?我应该在某处记录错误,还是对如何进一步调查有任何建议?
Does anyone know why it's returning such crazy results? Is this likely to be a hardware architecture problem (the only major thing that has changed is the CPU/Motherboard on this machine)? A problem with the Windows HAL with my current hardware? A JDK problem? Should I abandon nanoTime()? Should I log a bug somewhere, or any suggestions on how I could investigate further?
UPDATE 19/07 03:15 UTC:在尝试了下面 finnw 的测试用例之后,我又在 Google 上进行了一些搜索,遇到了诸如 bugid:6440250.这也让我想起了周五晚些时候我注意到的其他一些奇怪的行为,其中 ping 恢复为负数.所以我将 /usepmtimer 添加到我的 boot.ini 中,现在所有测试都按预期运行.我的 ping 也正常.
UPDATE 19/07 03:15 UTC: After trying finnw's test case below I did some more Googling, coming across entries such as bugid:6440250. It also reminded me of some other strange behaviour I noticed late Friday where pings were coming back negative. So I added /usepmtimer to my boot.ini and now all the tests behave as expected., and my pings are normal too.
我有点困惑为什么这仍然是一个问题;根据我的阅读,我认为 TSC 与 PMT 的问题在 Windows XP SP3 中得到了很大的解决.可能是因为我的机器原本是 SP2 的,并且被修补到 SP3 而不是最初安装为 SP3 吗?我现在也想知道是否应该安装像 MS KB896256 中的补丁.也许我应该与公司桌面构建团队一起讨论这个问题?
I'm a bit confused about why this was still an issue though; from my reading I thought TSC vs PMT issues were largely resolved in Windows XP SP3. Could it be because my machine was originally SP2, and was patched to SP3 rather than installed originally as SP3? I now also wonder whether I should be installing patches like the one at MS KB896256. Maybe I should take this up with the corporate desktop build team?
推荐答案
通过添加 /usepmtimer 到我的 C:oot.ini 字符串的末尾;强制 Windows 使用电源管理计时器而不是 TSC.鉴于我在 XP SP3 上,为什么我需要这样做,这是一个悬而未决的问题,因为我知道这是默认设置,但可能是由于我的机器被修补到 SP3 的方式.
The problem was resolved (with some open suspicions about the suitability of nanoTime() on multi-core systems!) by adding /usepmtimer to the end of my C:oot.ini string; forcing Windows to use the Power Management timer rather than the TSC. It's an open question as to why I needed to do this given I'm on XP SP3, as I understood that this was the default, however perhaps it was due to the manner in which my machine was patched to SP3.
相关文章