Я и еще один разработчик в свое время недавно перешли с машины 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 дает результаты nano между 33% и 60% фактического времени сна; обычно около 40%.
Я понимаю недостатки в точности таймеров в Windows и читаю связанные потоки, такие как Является ли System.nanoTime() согласованным по потокам?, однако я понимаю, что System.nanoTime() предназначен именно для этой цели: - измерение прошедшего времени; точнее, чем currentTimeMillis().
Кто-нибудь знает, почему он возвращает такие сумасшедшие результаты? Возможно, это проблема аппаратной архитектуры (единственная важная вещь, которая изменилась, - это процессор/материнская плата на этой машине)? Проблема с Windows HAL с моим текущим оборудованием? Проблема JDK? Должен ли я отказаться от nanoTime()? Должен ли я где-нибудь регистрировать ошибку или какие-либо предложения о том, как я могу продолжить исследование?
ОБНОВЛЕНИЕ 19/07 03:15 UTC: после того, как я попытался ответить на тестовый пример ниже, я сделал еще несколько Googling, набрав такие записи, как BUGID: 6440250. Это также напомнило мне о каком-то другом странном поведении, которое я заметил в конце пятницы, когда пинги возвращались отрицательно. Поэтому я добавил /usepmtimer в мой boot.ini, и теперь все тесты ведут себя так, как ожидалось, и мои пинги тоже нормальные.
Я немного смущен, почему это все еще проблема; из моего чтения я думал, что проблемы TSC и PMT были в основном решены в Windows XP SP3. Может быть, из-за того, что моя машина была первоначально SP2, и была исправлена до SP3, а не изначально установлена как SP3? Теперь я также задаюсь вопросом, следует ли устанавливать патчи, такие как MS KB896256. Может быть, я должен взять это с командой разработчиков настольных компьютеров?
Проблема была решена (с некоторыми открытыми подозрениями о пригодности nanoTime() для многоядерных систем!), добавив /usepmtimer в конец моей C:\boot. ini; заставляя Windows использовать таймер управления питанием, а не TSC. Непонятный вопрос о том, зачем мне это нужно, учитывая, что я нахожусь на XP SP3, поскольку я понял, что это было по умолчанию, однако, возможно, это было связано с тем, как моя машина была исправлена до SP3.
В моей системе (Windows 7 64-бит, Core i7 980X):
nanosTaken=4999902563
millisTaken=5001
System.nanoTime() использует вызовы, специфичные для ОС, поэтому я ожидаю, что вы увидите ошибку в комбинации с Windows/процессором.
Вероятно, вы захотите прочитать ответы на этот другой вопрос: Неужели System.nanoTime() полностью бесполезен?.
В целом, похоже, что nanoTime полагается на таймеры операционной системы, на которые может влиять наличие нескольких основных ЦП. Таким образом, nanoTime может быть не столь полезным при определенных комбинациях ОС и ЦП, и при использовании его в переносимом 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);
}
Если вы получаете очень разные результаты в зависимости от выбора ядра (например, 5000 мс на одном и том же ядре, но 2200 мс на разных ядрах), это может предполагать, что проблема заключается только в изменении естественного таймера между ядрами.
Если вы получаете очень разные результаты от спального и спиннинга, это, скорее всего, связано с тем, что управление энергопотреблением замедляет работу часов.
Если ни один из четырех результатов не близок к 5000 мс, это может быть ошибка.