Pourquoi mon System.nanoTime() est-il cassé?

Question

Moi-même et un autre développeur sur mon temps récemment déplacé d'une machine Core 2 Duo au travail à un nouveau Core 2 Quad 9505; les deux exécutant Windows XP SP3 32 bits avec JDK 1.6.0_18. Ce faisant, un couple de nos tests unitaires automatisés pour un code d'agrégation de synchronisation/statistiques/métriques a rapidement commencé à échouer, en raison de ce qui semble être des valeurs ridicules revenant de System.nanoTime().

Code d'essai qui montre ce comportement, de manière fiable, sur ma machine est:

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)); 
    } 

} 

sortie typique:

millisTaken=5001 
nanosTaken=2243785148 

Son exécution donne 100x nano résultats entre 33% et 60% du réel Temps de sommeil; habituellement autour de 40% cependant. Je comprends les faiblesses dans la précision des minuteurs dans Windows, et ai lu des threads apparentés comme Is System.nanoTime() consistent across threads?, cependant je crois comprendre que System.nanoTime() est exactement dans le but pour lequel nous l'utilisons: - mesurer le temps écoulé; plus précisément que currentTimeMillis().

Est-ce que quelqu'un sait pourquoi il rend des résultats aussi fous? Est-ce que cela risque d'être un problème d'architecture matérielle (la seule chose qui a changé est la CPU/carte mère sur cette machine)? Un problème avec Windows HAL avec mon matériel actuel? Un problème JDK? Dois-je abandonner nanoTime()? Dois-je enregistrer un bug quelque part, ou des suggestions sur la façon dont je pourrais enquêter plus loin?

MISE À JOUR 19/07 03:15 UTC: Après avoir essayé le cas de test de finnw ci-dessous je l'ai fait un peu plus googler, à venir à travers des entrées telles que bugid:6440250. Cela m'a aussi rappelé un autre comportement étrange que j'ai remarqué vendredi soir où les pings revenaient négatifs. J'ai donc ajouté /usepmtimer à mon boot.ini et maintenant tous les tests se comportent comme prévu., Et mes pings sont normaux aussi.

Je suis un peu confus au sujet de pourquoi c'était toujours un problème si; D'après mes lectures, je pensais que les problèmes TSC vs PMT étaient largement résolus dans Windows XP SP3. Serait-ce parce que ma machine était à l'origine SP2, et a été corrigé au SP3 plutôt qu'installé à l'origine en tant que SP3? Je me demande maintenant si je devrais installer des correctifs comme celui au MS KB896256. Peut-être que je devrais prendre cela avec l'équipe de création de bureau de l'entreprise?

Answer 1

Le problème a été résolu (avec quelques soupçons ouverts quant à la pertinence de NanoTime() sur les systèmes multi-core!) En ajoutant /usepmtimer à la fin de mon C: \ boot.ini chaîne; forcer Windows à utiliser le minuteur de gestion de l'alimentation plutôt que le TSC. C'est une question ouverte quant à la raison pour laquelle je devais le faire étant donné que je suis sur XP SP3, car j'ai compris que c'était la configuration par défaut, mais peut-être était-ce dû à la façon dont ma machine a été corrigée au SP3.

Answer 2

Vous souhaitez probablement lire les réponses à cette autre question de débordement de pile: Is System.nanoTime() completely useless?. En résumé, il semblerait que nanoTime repose sur des temporisateurs de système d'exploitation qui peuvent être affectés par la présence de plusieurs processeurs principaux. En tant que tel, nanoTime peut ne pas être très utile sur certaines combinaisons d'OS et de CPU, et il faut faire attention lors de son utilisation dans le code Java portable que vous avez l'intention d'exécuter sur plusieurs plates-formes cibles. Il semble y avoir beaucoup de plaintes sur le web à ce sujet, mais pas beaucoup de consensus sur une alternative significative.

Answer 3

Sur mon système (Windows 7 64 bits, Core i7 980X):

nanosTaken=4999902563 
millisTaken=5001 

System.nanoTime() utilise des appels spécifiques à l'OS, donc je pense que vous voyez un bogue dans Windows/combinaison de processeurs.

Answer 4

Il est difficile de dire s'il s'agit d'un bogue ou d'une variation de minuterie normale entre les cœurs.

Une expérience que vous pouvez essayer consiste à utiliser des appels natifs pour forcer le thread à s'exécuter sur un cœur spécifique.

De plus, pour exclure des effets de gestion de l'alimentation, essayez de tourner dans une boucle comme une alternative à 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); 
} 

Si vous obtenez des résultats très différents en fonction de la sélection de base (par exemple 5000ms sur le même noyau, mais 2200ms sur des noyaux différents) qui suggérerait que le problème est juste une variation de minuterie naturelle entre les noyaux.

Si vous obtenez des résultats très différents de sommeil par rapport au filage, il est plus probable que la gestion de l'alimentation ralentisse les horloges.

Si aucun des quatre résultats sont proches de 5000ms, alors il pourrait être un bug.