¿Por qué se rompe mi System.nanoTime()?

Question

Yo y otro desarrollador recientemente pasé de una máquina Core 2 Duo en el trabajo a una nueva Core 2 Quad 9505; ambos ejecutando Windows XP SP3 de 32 bits con JDK 1.6.0_18.

Al hacerlo, un par de nuestras pruebas unitarias automatizadas para algún código de agregación de temporización/estadísticas/métricas comenzaron a fallar rápidamente, debido a lo que parecen ser valores ridículos que vuelven de System.nanoTime().

Código de ensayo que muestra este comportamiento, de forma fiable, en mi máquina es:

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

} 

salida típica:

millisTaken=5001 
nanosTaken=2243785148 

Ejecutarlo rendimientos 100x resultados nano entre 33% y 60% de la actual hora de dormir; generalmente alrededor del 40% sin embargo.

Entiendo las debilidades en la precisión de los temporizadores en Windows, y he leído hilos relacionados como Is System.nanoTime() consistent across threads?, sin embargo entiendo que System.nanoTime() está destinado exactamente para el propósito que lo estamos usando: - medir el tiempo transcurrido; más exactamente que currentTimeMillis().

¿Alguien sabe por qué está devolviendo resultados tan locos? ¿Es probable que esto sea un problema de arquitectura de hardware (la única cosa importante que ha cambiado es la CPU/placa base en esta máquina)? ¿Un problema con Windows HAL con mi hardware actual? Un problema JDK? ¿Debo abandonar nanoTime()? ¿Debo registrar un error en algún lugar, o alguna sugerencia sobre cómo puedo investigar más?

ACTUALIZACIÓN 19/07 03:15 UTC: Después de intentar caso de prueba de finnw continuación he hecho un poco más buscando en Google, al encontrarse con entradas como bugid:6440250. También me recordó a algún otro comportamiento extraño que noté la noche del viernes, donde los pings regresaban negativos. Así que agregué /usepmtimer a mi boot.ini y ahora todas las pruebas se comportan como se esperaba. Y mis pings también son normales.

Estoy un poco confundido acerca de por qué esto todavía era un problema; de mi lectura pensé que los problemas de TSC vs PMT se resolvieron en gran medida en Windows XP SP3. ¿Podría ser porque mi máquina era originalmente SP2 y se parchó en SP3 en lugar de instalarse originalmente como SP3? Ahora también me pregunto si debería instalar parches como el del MS KB896256. ¿Quizás debería abordar esto con el equipo corporativo de construcción de escritorios?

Answer 1

se resolvió el problema (con algunas sospechas abiertas acerca de la idoneidad de nanoTime() en sistemas multi-núcleo!) Mediante la adición de /usepmtimer hasta el final de mi C: \ boot.ini cadena; obligando a Windows a usar el temporizador de administración de energía en lugar del TSC. Es una pregunta abierta sobre por qué tenía que hacer esto dado que estoy en el SP3 de XP, ya que entendí que este era el valor predeterminado, sin embargo, tal vez se debió a la forma en que mi máquina fue parchada al SP3.

Answer 2

Probablemente quiera leer las respuestas a esta otra pregunta de desbordamiento de pila: Is System.nanoTime() completely useless?.

En resumen, parece que nanoTime depende de los temporizadores del sistema operativo que pueden verse afectados por la presencia de múltiples CPU centrales. Como tal, nanoTime puede no ser tan útil en ciertas combinaciones de sistema operativo y CPU, y se debe tener cuidado al usarlo en el código portátil de Java que tiene la intención de ejecutar en múltiples plataformas de destino. Parece que hay muchas quejas en la web sobre este tema, pero no hay mucho consenso sobre una alternativa significativa.

Answer 3

En mi sistema (Windows 7 64-Bit, Core i7 980X):

nanosTaken=4999902563 
millisTaken=5001 

System.nanoTime() utiliza las llamadas OS-específicas, así que espero que usted está viendo un error en su Windows/combinación de procesador

Answer 4

Es difícil determinar si esto es un error o simplemente la variación normal del temporizador entre los núcleos.

Un experimento que podría intentar es usar llamadas nativas para forzar la ejecución del subproceso en un núcleo específico.

Además, para descartar los efectos de administración de energía, trate de girar en un bucle como una alternativa a 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 obtiene resultados muy diferentes dependiendo de la selección del núcleo (por ejemplo, 5000 ms en el mismo núcleo, pero 2200ms en diferentes núcleos) que sugeriría que el problema es simplemente la variación natural del temporizador entre los núcleos.

Si obtiene resultados muy diferentes de dormir frente a la rotación, es más probable debido a la administración de energía que ralentiza los relojes.

Si ninguno de los cuatro resultados son cerca de 5000ms, entonces podría ser un error.