Application de minutage multithread avec gigue importante et erreurs?

Question

EDIT: Bien que je sois d'accord que la clé de ce problème dépend de la précision de Thread.sleep(), j'ai été amené à croire que Thread.sleep() est biaisé pour dormir plus longtemps que demandé. Pourquoi le thread reprend-il avant que sa durée de sommeil ait expiré? Je peux comprendre que le planificateur de système d'exploitation ne revienne pas sur le thread à temps pour le réveiller, mais pourquoi y arriver plus tôt? Quel serait le point de fil de couchage si le système d'exploitation pouvait simplement les réveiller tôt?

J'essaye d'écrire une classe pour faire la synchronisation modulaire dans mes projets. L'idée est de faire une classe capable de mesurer le temps d'exécution de n'importe quel code particulier qui m'intéresse. Je veux faire cette mesure sans avoir à écrire un code de timing spécifique sur place et me fournir une interface modulaire propre.

Le concept est construit autour d'un entraîneur ayant plusieurs chronomètres pour chacun de ses coureurs. Je peux appeler une classe avec différents identifiants de chronomètre pour créer des discussions qui mesurent leurs temps d'exécution respectifs. En outre, il existe une fonctionnalité de recouvrement pour mesurer les sous-intervalles de l'horloge de la montre. L'implémentation est centrée sur l'utilisation d'une HashMap par la classe Stopwatch (coach) et la classe Watch (runner).

Voici mon implémentation:

import java.util.HashMap; 
import java.util.Map; 
import java.util.Map.Entry; 

public class Stopwatch { 
    private static Map<String, Watch> watchMap = new HashMap<>(); 

    public static boolean start(String watchID) { 
     if(!watchMap.containsKey(watchID)) { 
      watchMap.put(watchID, new Watch()); 
      return true; 
     } else { 
      return false; 
     } 
    } 

    public static void stop(String watchID) { 
     if(watchMap.containsKey(watchID)) { 
      watchMap.get(watchID).stop(); 
     } 
    } 

    public static void startLap(String watchID, String lapID) { 
     if(watchMap.containsKey(watchID)) { 
      watchMap.get(watchID).startLap(lapID); 
     } 
    } 

    public static void endLap(String watchID, String lapID) { 
     if(watchMap.containsKey(watchID)) { 
      watchMap.get(watchID).stopLap(lapID); 
     } 
    } 

    public static void stopAndSystemPrint(String watchID) { 
     if(watchMap.containsKey(watchID)) { 
      Watch watch = watchMap.get(watchID); 
      if(watch.isRunning()) { 
       watch.stop(); 
      } 
      Map<String, Long> lapMap = watch.getLapMap(); 

      System.out.println("/****************** " + watchID 
          + " *******************\\"); 
      System.out.println("Watch started at: " + watch.getStartTime() 
          + " nanosec"); 
      for(Entry<String, Long> lap : lapMap.entrySet()) { 
       System.out.println("\t" + lap.getKey() + ": " 
           + ((double)lap.getValue()/1000000.0) 
           + " msec"); 
      } 
      System.out.println("Watch ended at: " + watch.getEndTime() 
          + " nanosec"); 
      System.out.println("Watch total duration: " 
          + (double)(watch.getDuration()/1000000.0) 
          + " msec"); 
      System.out.println("\\****************** " + watchID 
          + " *******************/\n\n"); 
     } 
    } 

    private static class Watch implements Runnable { 

     private Thread timingThread; 
     private long startTime; 
     private long currentTime; 
     private long endTime; 

     private volatile boolean running; 
     private Map<String, Long> lapMap; 

     public Watch() { 
      startTime = System.nanoTime(); 
      lapMap = new HashMap<>(); 

      running = true; 
      timingThread = new Thread(this); 
      timingThread.start(); 
     } 

     @Override 
     public void run() { 
      while(isRunning()) { 
       currentTime = System.nanoTime(); 
       // 0.5 Microsecond resolution 
       try { 
        Thread.sleep(0, 500); 
       } catch (InterruptedException e) { 
        e.printStackTrace(); 
       } 
      } 
     } 

     public void stop() { 
      running = false; 
      endTime = System.nanoTime(); 
     } 

     public void startLap(String lapID) { 
      lapMap.put(lapID, currentTime); 
     } 

     public void stopLap(String lapID) { 
      if(lapMap.containsKey(lapID)) { 
       lapMap.put(lapID, currentTime - lapMap.get(lapID)); 
      } 
     } 

     public Map<String, Long> getLapMap() { 
      return this.lapMap; 
     } 

     public boolean isRunning() { 
      return this.running; 
     } 

     public long getStartTime() { 
      return this.startTime; 
     } 

     public long getEndTime() { 
      return this.endTime; 
     } 

     public long getDuration() { 
      if(isRunning()) { 
       return currentTime - startTime; 
      } else { 
       return endTime - startTime; 
      } 
     } 
    } 
} 

Et, voici le code que je utilise pour tester cette mise en œuvre:

public class StopwatchTest { 

    public static void main(String[] args) throws InterruptedException { 
     String watch1 = "watch1"; 
     Stopwatch.start(watch1); 

     String watch2 = "watch2"; 
     Stopwatch.start(watch2); 

     String watch3 = "watch3"; 
     Stopwatch.start(watch3); 

     String lap1 = "lap1"; 
     Stopwatch.startLap(watch1, lap1); 
     Stopwatch.startLap(watch2, lap1); 

     Thread.sleep(13); 

     Stopwatch.endLap(watch1, lap1); 
     String lap2 = "lap2"; 
     Stopwatch.startLap(watch1, lap2); 

     Thread.sleep(500); 

     Stopwatch.endLap(watch1, lap2); 

     Stopwatch.endLap(watch2, lap1); 

     Stopwatch.stop(watch3); 

     String lap3 = "lap3"; 
     Stopwatch.startLap(watch1, lap3); 

     Thread.sleep(5000); 

     Stopwatch.endLap(watch1, lap3); 

     Stopwatch.stop(watch1); 
     Stopwatch.stop(watch2); 
     Stopwatch.stop(watch3); 

     Stopwatch.stopAndSystemPrint(watch1); 
     Stopwatch.stopAndSystemPrint(watch2); 
     Stopwatch.stopAndSystemPrint(watch3); 
    } 
} 

Enfin, une sortie que ce test peut produire:

/****************** watch1 *******************\ 
Watch started at: 45843652013177 nanosec 
    lap1: 12.461469 msec 
    lap2: 498.615724 msec 
    lap3: 4999.242803 msec 
Watch ended at: 45849165709934 nanosec 
Watch total duration: 5513.696757 msec 
\****************** watch1 *******************/ 


/****************** watch2 *******************\ 
Watch started at: 45843652251560 nanosec 
    lap1: 4.5844165436787E7 msec 
Watch ended at: 45849165711920 nanosec 
Watch total duration: 5513.46036 msec 
\****************** watch2 *******************/ 


/****************** watch3 *******************\ 
Watch started at: 45843652306520 nanosec 
Watch ended at: 45849165713576 nanosec 
Watch total duration: 5513.407056 msec 
\****************** watch3 *******************/ 

Il y a quelques résultats intéressants (pour moi, au moins) de ce code. Un, c'est que les montres finissent tôt ou tard de l'ordre de 1 milliseconde. J'aurais pensé que, même avec une horloge nanoseconde quelque peu inexacte, je pourrais obtenir une meilleure précision que 1 ms. Peut-être que j'oublie quelque chose sur les chiffres significatifs et la précision.

Une autre est que, dans ce résultat de test, watch2 termine avec ce résultat pour son tour:

Watch started at: 45843652251560 nanosec 
    lap1: 4.5844165436787E7 msec 
Watch ended at: 45849165711920 nanosec 

J'ai vérifié la façon dont je manipulais la valeur dans ma méthode stopAndSystemPrint, mais cela ne semble pas avoir un effet sur l'erreur. Je ne peux que conclure que les maths que je suis en train de faire sont solides, et que parfois quelque chose est cassé. Le peu parfois m'inquiète parce que - je pense - il me dit que je fais quelque chose de mal avec mon fil dans la classe Watch. Il semble que la durée du tour est interrompue et qu'il en résulte une certaine valeur entre mon heure de début et celle de fin.

Je ne suis pas sûr que ces problèmes soient exclusifs, mais si je devais en choisir un à résoudre, ce serait la gigue.

Quelqu'un peut-il faire la tête ou la queue de pourquoi il y aurait une gigue de l'ordre de 1ms?

Bonus: Pourquoi les montres sont-elles gâchées de temps en temps?

Answer 1

Les montres sont parfois endommagées car vous effectuez les calculs dans un thread qui indique currentTime qui est différent du thread qui écrit currentTime.Par conséquent, la valeur lue est parfois non initialisée, c'est-à-dire zéro. Dans le cas spécifique que vous mentionnez impliquant watch2, une heure de début de temps zéro a été enregistrée car la valeur initiale currentTime n'était pas disponible pour le thread enregistrant l'heure de début du tour. Pour résoudre ce problème, déclarez currentTime comme volatile. Vous devrez peut-être ajouter un délai ou un rendement pour permettre au watch d'effectuer une mise à jour unique avant de commencer les tours. En ce qui concerne la gigue, le fait que currentTime ne soit pas volatile peut être une partie ou la totalité du problème puisque le thread appelant pour les démarrages et les arrêts peut traiter des données périmées. De plus, Thread.sleep() n'est précis que dans la mesure où l'horloge du système est précise, ce qui, dans la plupart des systèmes, n'est pas d'une précision de l'ordre de la nanoseconde. Plus d'informations sur ce dernier devrait être disponible à la duplication possible des mentions de Basilevs dans le commentaire.