纳秒定时器给出奇怪的结果

Question

预计所有圈数大约需要同一时间,那么为什么第一圈和第二圈的异常值呢？

输出:

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

Answer 1

以下是一些可能导致错误的事情.

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在启动时有一些"东西"要做,这也会影响前几次运行.

基本阅读:如何在Java中编写正确的微基准测试？