[Thread][System.nano] Différentes mesures

Version imprimable

Code:

1
2
3
4
5
6
7
8
9
 
code A:
         while(true){
 
             long a = System.nanoTime();
             long b = System.nanoTime();
 
             System.out.println(b-a);
         }

Result :

30
30
....

Code:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
 
Code B
:
         while(true){
 
             long a = System.nanoTime();
             long b = System.nanoTime();
 
             System.out.println(b-a);
 
           try {
                 Thread.sleep(10);
             } catch (InterruptedException ex) {
 
Logger.getLogger(Main.class.getName()).log(Level.SEVERE, null, ex);
             }
 
         }

Result :

350
280
283
283
375
283
Une idée de la raison?

27/01/2011, 20h08
tchize_

il peut y avoir tout un tas de raison. La première étant que la vitesse d'exécution d'un code n'est pas prédictible, que ce soit en java ou dans d'autres languages. La seconde étant que System.nano ne donne pas de garantie de précision.

Maintenant, concernant le code en question, la différence de vitesse se trouve à plusieurs niveaux:

L'introduction d'exception à traiter dans le code, l'augmentation de la complexité de la méthode sont aussi un frein à l'optimisation par le compilateur JIT et la complexification de ses choix. Le GC aussi se comportera aussi différement puisqu'il aura plus d'objets à traiter.

J'ai teste le code avec differentes options :

En utilisant un Kernel avec ACPI desactive.
En utilisant l'argument Xcomp pour forcer la compilation.

Les deux precedentes modifications ne changeant rien aux resultats, j'ai voulu verifier l'hypothese de l'introduction d'exception.

J'ai donc cree le code suivant :
Code:

1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 public class Main { /** * @param args the command line arguments */ public static void main(String[] args) { // TODO code application logic here Random r = new Random(); while(true){ try { int a = r.nextInt(10); if(a%6==0) throw new RuntimeException(); } catch (Exception ex) { System.out.println("exception"); } // long a = System.nanoTime(); long b = System.nanoTime(); System.out.println(b-a); } } }
resultats :

31
30
30
30
exception
30
32
30
exception
29
30
exception
37
30
30
31
31
30
exception
30
exception
30
exception
31
24
31
exception
30

Il ne semble pas que le try catch qui precede les deux appels a System.nano() ait une influence sur le resultat dans ce cas.

Un vrai probleme interessant :)

28/01/2011, 17h45
tchize_

un problème dont vous n'avez pas vraiment à vous soucier. La différence est marginale, les résultat seront différent si vous appelez exactement la même méthode dans une grosse application, ils seront différents d'un jvm à l'autre, etc.
Autre chose qui influence: vous faites un sleep. Le thread rend donc la main dans le système. Il y a donc changement de contexte (un autre thread OS prend le CPU) et vidage des caches des premier niveaux, caches qu'il faudra reremplir, perte de l'optimisation et des prédictions de branchement dans le CPU et tout le tointoin et donc ça peut ralentir les appels. Avec le sleep, vous passez dans votre boucle au maximum 100 fois par secondes. Hors si vous mesurez, vous bouclez en +-100 nano secondes sans le sleep, ce qui correspond 10⁸ passage par secondes, c'est pas du tout le même travail d'optimisation pour le cpu et les caches ;)

J'ai fais un autre test et j'ai change le temps de pause de 10 ms a 1 ms.
Code:

1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 Code B : while(true){ long a = System.nanoTime(); long b = System.nanoTime(); System.out.println(b-a); try { Thread.sleep(1); // Thread.sleep(10); } catch (InterruptedException ex) { Logger.getLogger(Main.class.getName()).log(Level.SEVERE, null, ex); } }
Ayant remarque une amelioration des performances ( de 300 a 70 nanosecondes. ), j'ai active l'option -XX:+PrintCompilation.

Avec thread.sleep(10) aucune compilation n'est effectue.

Il reste donc a comprendre la difference de 40 nanoseconde entre les deux codes. Cela peut etre du au context switching.

J'ai utilise taskset pour assigner le processus a mon seul premier core. Mais aucune amelioration n'as ete detecte.
strace ne renvoit aucune difference
le bytecode rapporte par javap est identique pour les deux code ( dans leurs partie similaire ).

Je continue a favorise l'option du context switching.

Savez-vous comment je pourrais verifier cela ?

Mon systeme d'exploitation est un suze linux.
Code:

1 2 3 #uname -a Linux 2.6.34.7-0.7-desktop #1 SMP PREEMPT 2010-12-13 11:13:53 +0100 x86_64 x86_64 x86_64 GNU/Linux

29/01/2011, 12h09
tchize_

je ne vois pas "pourquoi" vous avez besoin de le faire? Vous vous cassez la tête à essayez de trouver une information qui dépend fortement de votre machine. Et vosu comparez toujours, de toutes facons, un code qui s'exécute 10.000.000 plus souvent à un autre! Toute informations que vous trouverez, de toutes facons, ne sera pas applicable à un autre code et probablement pas à un autre CPU.