Why is there such a big difference on time between first nanoTime() call and the successive calls?

Question

So my question is more general. I've the following simple code:

for(int i=0;i<10;i++){
    long starttime=System.nanoTime();
    System.out.println("test");
    long runtime=System.nanoTime()-starttime;
    System.out.println(i + ":" +"runtime="+runtime);
}

i receive the following output:

test
0:runtime=153956
test
1:runtime=15396
test
2:runtime=22860
test
3:runtime=11197
test
4:runtime=11197
test
5:runtime=12129
test
6:runtime=11663
test
7:runtime=11664
test
8:runtime=53185
test
9:runtime=12130

What is the reason for the difference between the first and the second runtime?Thanks in advance =)

Answer 1

A lot of things, both in the JVM and in the standard library, are lazily initialized to improve the JVM startup time. So the first time you execute the line

System.out.println("test");

a heavyweight initialization process happens. The time to complete it is included in your first measurement. Subsequent calls proceed down the fast path where the state is already initialized.

You can observe the same effect on a great many API calls in Java.

Naturally, there are many more factors which can influence the time it takes to complete any given method call, especially if it includes system calls on its path. However, the outlier in the latency of the first call is special in that it has deterministic causes underlying it and is therefore reliably reproducible.