Nanosecond timer giving odd results

Question

All laps are expected to take about the same time, so why the outliers on the first and second lap?

Output:

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

They will never be equal. Probably the SO scheduler is in action. The program doesn't get exclusive access to the processor. — acdcjunior, Jun 12 '13 at 21:33
Sure, if the first lap was an outlier. But why the second even more so? And that might average them out but it would mean the class is flawed as you'd have to warm it up each time. — rtheunissen, Jun 12 '13 at 21:33
What else was happening on your computer at the time? Other processes may have been taking CPU away from this one. — lreeder, Jun 12 '13 at 21:34
@assylias Why not? Of course with some appropriate standard deviation. — rtheunissen, Jun 12 '13 at 21:34
Looks a little bit like the interpreter doing its job for the first couple of loops. After that its's up to the OS. — Serdalis, Jun 12 '13 at 21:36
@paranoid-android was that *"Sure, if the first lap was an outlier. (...)"* a reply to me? I don't understand it. — acdcjunior, Jun 12 '13 at 21:37
@acdcjunior I think a comment was deleted. It said something like "maybe needs to warm up first". — rtheunissen, Jun 12 '13 at 21:38

score 6 · Accepted Answer · edited May 23 '17 at 12:21

Here are a few things that could make it go wrong.

The main method will be compiled by the JIT several times during that run

If you use the -XX:+PrintCompilation flag, you will get this output:

 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

So the first few runs are clearly impacted by the compilation.

The JVM has some "stuff" to do when it starts which will also impact the first few runs.

Essential read: How do I write a correct micro-benchmark in Java?

@paranoid-android Also note that it is likely that, after a few compilations, the whole inner loop is optimised away since it does not have any side effects. — assylias, Jun 12 '13 at 21:42

score 1 · Answer 2 · answered Jun 12 '13 at 21:35

1

Plenty of things could happen. Your list of Laps could be getting initialized, it could be getting resized, or allocated. The code could be hitting the jvm for the first time and takes additional time to run. The jvm might also figure out that nothing happens in the loop and get rid of it entirely. Other processes could be getting priority, countless things.

answered Jun 12 '13 at 21:35

Jean-Bernard Pellerin

12,556
10
57
79

It's a LinkedList, so there's no difference between adding the first and the 1000th element. If the JVM removes the loop, wouldn't it do so for all the laps? – rtheunissen Jun 12 '13 at 21:36

Nanosecond timer giving odd results

2 Answers2