Почему мой System.nanoTime() сломан?

Question

Самостоятельно и еще один разработчик моего времени недавно переехал с машины Core 2 Duo на работу на новый Core 2 Quad 9505; оба работают под управлением Windows XP SP3 32-бит с JDK 1.6.0_18.

После этого несколько наших автоматических модульных тестов для некоторого кода агрегации времени/статистики/показателей быстро начали сбой, из-за того, что кажется смешными значениями, возвращающимися из 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() consistent across threads?, однако я понимаю, что System.nanoTime() предназначен именно для того, чтобы мы его использовали: - измерение прошедшего времени; точнее, чем currentTimeMillis().

Кто-нибудь знает, почему он возвращает такие сумасшедшие результаты? Возможно, это проблема аппаратной архитектуры (единственная важная вещь, которая изменилась, - это процессор/материнская плата на этой машине)? Проблема с Windows HAL с моим текущим оборудованием? Проблема JDK? Должен ли я отказаться от nanoTime()? Должен ли я где-нибудь регистрировать ошибку или какие-либо предложения о том, как я могу продолжить исследование?

UPDATE 19/07 03:15 UTC: После проверки тестового примера в Finnw ниже я сделал еще несколько поисковых запросов, попадающих в такие записи, как bugid:6440250. Это также напомнило мне о каком-то другом странном поведении, которое я заметил в конце пятницы, когда пинги возвращались отрицательно. Поэтому я добавил /usepmtimer в мой boot.ini, и теперь все тесты ведут себя так, как ожидалось., И мои пинги тоже нормальные.

Я немного смущен, почему это все еще проблема; из моего чтения я думал, что проблемы TSC и PMT были в основном решены в Windows XP SP3. Может быть, из-за того, что моя машина была первоначально SP2, и была исправлена ​​до SP3, а не изначально установлена ​​как SP3? Теперь я также задаюсь вопросом, следует ли устанавливать патчи, например, на MS KB896256. Может быть, я должен взять это с командой разработчиков настольных компьютеров?

Answer 1

Проблема была решена (с некоторыми открытыми подозрениями о пригодности nanoTime() на многоядерных системах!), Добавив /usepmtimer к концу моей C : \ boot.ini строки; заставляя Windows использовать таймер управления питанием, а не TSC. Это открытый вопрос о том, зачем мне это нужно, учитывая, что я нахожусь на XP SP3, поскольку я понял, что это было по умолчанию, однако, возможно, это было связано с тем, как моя машина была исправлена ​​до SP3.

Answer 2

Возможно, вы захотите прочитать ответы на этот вопрос переполнения стека: Is System.nanoTime() completely useless?.

Таким образом, похоже, что nanoTime полагается на таймеры операционной системы, на которые может влиять наличие нескольких основных ЦП. Таким образом, nanoTime может быть не столь полезным при определенных комбинациях ОС и ЦП, и при использовании его в переносимом Java-коде необходимо соблюдать осторожность, которую вы намереваетесь запускать на нескольких целевых платформах. По всей видимости, в Интернете есть много жалоб на эту тему, но не так много консенсуса относительно значимой альтернативы.

Answer 3

В моей системе (Windows 7 64-бит, Core i7 980X):

nanosTaken=4999902563 
millisTaken=5001 

System.nanoTime() использует ОС-специфические вызовы, поэтому я ожидаю, что вы видите ошибку в вашей Windows/процессор.

Answer 4

Трудно сказать, является ли это ошибкой или просто нормальным изменением таймера между ядрами.

Эксперимент, который вы можете попробовать, это использовать собственные вызовы, чтобы заставить поток работать на определенном ядре.

Кроме того, чтобы исключить эффекты управления питанием, попробуйте спиннинг в цикле в качестве альтернативы 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 мс на том же ядре, но 2200ms на разных ядрах), которые предполагают, что проблема заключается в естественном изменении таймера между ядрами.

Если вы получаете совсем другие результаты от сна и спиннинга, это, скорее всего, связано с тем, что управление питанием замедляет работу часов.

Если нет из четырех результатов близко к 5000 мс, то это может быть ошибка.