Почему мой System.nanoTime () сломан? - PullRequest
Новая
       7

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

10 голосов
/ 18 июля 2010

Я и еще один мой разработчик недавно перешли с работающего на Core 2 Duo компьютера на новый Core 2 Quad 9505;оба работают под управлением Windows XP SP3 32-bit с 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

Запуск в 100 раз дает нано результаты от 33% до 60% фактического времени сна;хотя обычно около 40%.

Я понимаю недостатки точности таймеров в Windows, и я прочитал связанные темы, такие как Является ли System.nanoTime () согласованным между потоками? , однако мое пониманиечто System.nanoTime () предназначен именно для той цели, которую мы используем: - измерение прошедшего времени;точнее, чем currentTimeMillis ().

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

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

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

Ответы [ 4 ]

6 голосов
/ 23 июля 2010

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

2 голосов
/ 18 июля 2010

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

nanosTaken=4999902563
millisTaken=5001

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

1 голос
/ 18 июля 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 мс, то это может быть ошибка.

1 голос
/ 18 июля 2010

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

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

...