Почему мой System.nanoTime () не работает?

Я и еще один разработчик в свое время недавно перешли с компьютера Core 2 Duo на работе на новый Core 2 Quad 9505; оба работают под управлением 32-разрядной версии Windows XP SP3 с 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 () согласован между потоками?, однако я понимаю, что System.nanoTime () предназначен именно для той цели, которую мы используем: - измерение прошедшего времени; точнее, чем currentTimeMillis ().

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

ОБНОВЛЕНИЕ 19/07, 03:15 UTC: попробовав приведенный ниже тестовый пример finnw, я еще раз погуглил, наткнувшись на такие записи, как bugid: 6440250. Это также напомнило мне о другом странном поведении, которое я заметил поздно в пятницу, когда пинги возвращались отрицательно. Итак, я добавил / usepmtimer в свой boot.ini, и теперь все тесты работают, как ожидалось, и мои пинги тоже нормальные.

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


person Chad    schedule 18.07.2010    source источник
comment
Вы приобрели совершенно новую машину или ваша текущая машина была обновлена ​​с сохранением старой установки Windows?   -  person Thorbjørn Ravn Andersen    schedule 18.07.2010
comment
Совершенно новая машина; перестроен по корпоративной стандартной сборке.   -  person Chad    schedule 18.07.2010
comment
отлично работает для меня под Windows 7 64 бит последней версии JDK 6.   -  person TofuBeer    schedule 18.07.2010
comment
возможный дубликат Является ли System.nanoTime () полностью бесполезным?   -  person Shaggy Frog    schedule 18.07.2010
comment
Если кто-то столкнется с этим вопросом в 2019 году или позже: это не должно быть проблемой для любой ОС, начиная с OpenJDK 8u25 или в любых версиях, выпущенных позже до февраля 2019 года, по модулю неизвестных ошибок, которые все еще могут где-то прятаться. См. Bugs.openjdk.java.net/browse/JDK-8045438.   -  person leventov    schedule 04.02.2019


Ответы (4)


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

person Chad    schedule 23.07.2010
comment
Вау - я рад, что нашел этот пост - был один сайт клиента, на котором ScheduledExecutorService полностью сходила с конвейера (время, оставшееся до следующей запланированной задачи, случайно пошло бы в неправильном направлении). - person Kevin Day; 22.05.2014
comment
Рад, что это кому-то помогло! Я потерял на это много времени :) Я также предполагаю, что, поскольку XP становится все реже и реже используемой теперь, когда она должным образом EOLed (особенно самими разработчиками), способность быстро диагностировать такие неясные проблемы на старом клиентском комплекте будет постепенно уменьшаться .... - person Chad; 27.06.2014

В моей системе (64-разрядная Windows 7, Core i7 980X):

nanosTaken=4999902563
millisTaken=5001

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

person mikera    schedule 18.07.2010
comment
Спасибо mikera, похоже, что Windows использовала стиль таймера, который некорректно работает на моем Core 2 Quad. Принудительное использование таймера управления питанием заставило его снова вести себя нормально; но я не совсем понимаю, зачем мне пришлось это делать! - person Chad; 19.07.2010

Вероятно, вы захотите прочитать ответы на этот другой вопрос о переполнении стека: Совершенно бесполезен System.nanoTime () ?.

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

person Tom    schedule 18.07.2010
comment
Это не совсем точное резюме. System.nanoTime зависит от таймеров, специфичных для ОС. Ранее были обнаружены одна или две ошибки, например на процессорах Athlon 64 в Windows, однако в большинстве систем вы можете положиться на работу nanoTime. Я использую его для анимации и тайминга в многоядерных играх, и у меня никогда не было проблем. - person mikera; 18.07.2010
comment
Спасибо за разъяснение mikera. Я обновил свой ответ, чтобы (надеюсь) повысить точность. - person Tom; 18.07.2010
comment
Спасибо, Том. Как я уже упоминал в обновленном вопросе выше, мне удалось вернуться к нормальному поведению, заставив использовать PMT. Я думаю, у меня все еще есть небольшие опасения по поводу того, будет ли это вести себя так, как мы ожидаем, для нескольких ядер. И да, без значимой альтернативы (за исключением возврата к currentTimeMillis) трудно понять, как лучше всего действовать! - person Chad; 19.07.2010

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

Вы можете попробовать использовать собственные вызовы для принудительного запуска потока на определенном ядре.

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

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

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

person finnw    schedule 18.07.2010
comment
Спасибо, finnw, это интересно. Мои результаты: Спящий, разные ядра, nanosTaken = 2049217124 millisTaken = 4985 Sleeping, одинаковые core nanosTaken = 1808868148 millisTaken = 4985 Вращение, разные ядра, nanosTaken = 5015172794 миллисекунд = 5000 Spinning, то же ядро ​​nanosTaken = 5015295288 миллисекунд, вы делаете это = 5000 сломана система управления питанием на моей машине? - person Chad; 19.07.2010
comment
Прочитав еще раз, вызванный вашим тестом, я попытался перезагрузить компьютер с помощью / usepmtimer в boot.ini. Теперь ваш тест (и мои оригинальные тесты) работают нормально. Я соответствующим образом отредактировал свой вопрос. Должен ли я это сделать? - person Chad; 19.07.2010
comment
Он не обязательно сломан, но ясно, что TSC не подходит для высокоточного отсчета времени на вашем компьютере, а использование таймера PM дает лучшие результаты. Я думал, что / usepmtimer используется по умолчанию в XP SP3, но ваши результаты говорят об обратном. - person finnw; 19.07.2010
comment
Да, ну, на самом деле моя машина была машиной с пакетом обновления 2 (SP2), недавно обновленной до пакета обновления 3 (SP3) посредством какого-то корпоративного процесса установки исправлений, который мог или не мог фальсифицировать стандартный дистрибутив MS SP3; или, возможно, когда SP3 применяется как патч, boot.ini не изменяется. Точно сказать не могу. - person Chad; 23.07.2010