2013-06-12 2 views
0

Ожидается, что все кружки пройдут примерно в одно и то же время, так почему же выбросы на первом и втором кругах?Наносекундный таймер, дающий нечетные результаты

Выход:

6.695178 ms : Lap #0 
18.698311 ms : Lap #1 
0.143568 ms : Lap #2 
0.043931 ms : Lap #3 
0.061594 ms : Lap #4 
0.038496 ms : Lap #5 
0.038043 ms : Lap #6 
0.043478 ms : Lap #7 
0.038949 ms : Lap #8 
0.061141 ms : Lap #9 

SSCCE:

import java.util.LinkedList; 

public class StopwatchSSCCE { 

    public static void main(String [] args){ 
     // ten laps of 2 billion iterations each 
     int laps = 10; 
     int iterationsEach = 2000000000; 

     Stopwatch stopwatch = new Stopwatch(); 

     for(int lap = 0; lap < laps; lap++){ 
      // empty loop 
      for(int i = 0; i < iterationsEach; i++); 

      // add lap 
      stopwatch.lap("Lap #" + lap); 
     } 

     stopwatch.printLaps(); 
    } 

    private static class Stopwatch { 

     private long startTime, lastLap; 

     private LinkedList<String> laps = new LinkedList<>(); 

     public Stopwatch(){ 
      reset(); 
     } 

     public void clearLaps(){ 
      laps.clear(); 
     } 

     public void reset(){ 
      startTime = lastLap = System.nanoTime(); 
     } 

     public long timeSinceLastLap(){ 
      return System.nanoTime() - lastLap; 
     } 

     public void lap(String title) { 
      double split = timeSinceLastLap()/1000000.0; 
      lastLap = System.nanoTime(); 
      laps.add(split + " ms :\t" + title); 
     } 

     public void printLaps(){ 
      for(String lap : laps) System.out.println(lap); 
     } 
    } 
} 
+2

Они никогда не будут равными. Вероятно, SO-планировщик работает. Программа не получает эксклюзивный доступ к процессору. – acdcjunior

+0

Конечно, если первый круг был нарушением. Но почему второй еще больше? И это может усреднить их, но это будет означать, что класс испорчен, так как вам придется каждый раз его нагревать. – rtheunissen

+2

"* Ожидается, что все кружки пройдут примерно в то же время *" => no – assylias

ответ

6

Вот несколько вещей, которые могут заставить его пойти не так.

Метод main будет составлен несколько раз JIT во время этого запуска

Если вы используете -XX:+PrintCompilation флаг, вы получите этот результат:

86 1 %   javaapplication4.Test1::main @ 26 (73 bytes) 
90 1 %   javaapplication4.Test1::main @ -2 (73 bytes) made not entrant 
91 2 %   javaapplication4.Test1::main @ 26 (73 bytes) 
4.090457 ms : Lap #0 
6.412305 ms : Lap #1 
0.040696 ms : Lap #2 

Таким образом, первые несколько спусков явно повлияли по компиляции.

В JVM есть несколько вещей, которые нужно выполнить, когда они начнутся, что также повлияет на первые несколько пробегов.

Основные данные: How do I write a correct micro-benchmark in Java?

+0

Это ответ, который я получил после - спасибо. – rtheunissen

+0

@ paranoid-android Также обратите внимание на то, что после нескольких компиляций весь внутренний цикл оптимизирован, так как он не имеет никаких побочных эффектов. – assylias

1

Много вещей может произойти. Ваш список кругов может быть инициализирован, он может быть изменен или выделен. Код может попасть в jvm в первый раз и требует дополнительного времени для запуска. Jvm также может понять, что в цикле ничего не происходит и полностью избавиться от него. Другие процессы могут приобретать приоритет, бесчисленные вещи.

+0

Это LinkedList, поэтому нет никакой разницы между добавлением первого и 1000-го элементов. Если JVM удаляет цикл, не так ли это для всех кругов? – rtheunissen

Смежные вопросы