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 =)

Viscometer

#860731 Refer this question, it may help. – Savill

optimisation/prediction maybe ? + static "test" initialisation for the first time – Perth

The JVM uses a JIT Compiler which compiles the jvm byte code into real machine code. The time for compiling is contained in the first interval. – Tablespoon

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.

Gaynellegayner

Answer 2

Many things can affect your calculations.

What about other processes on your machines? Did you consider the JVM warming up? Maybe the garbage collection? All these factors and more leads to this behavior.

If you want to get "better" results you should run it for much more times, and take the average.

That's why you should know how to benchmark things in Java, see How do I write a correct micro-benchmark in Java?.

Satisfy

@MarkoTopolnik -I should consider this question not only for the 1st call, but also for the 9th call. And, then I believe this is the only answer which correctly depicts all the things which may be in action. I won't consider only the first case. You should give answers for all the observation. – Montanez

If you want to get "better" results you should run it for much more times, and take the average.---you mean, run the same program many times? OP actually did that and noticed that, every time, the first call takes longer. The only thing this question has to do with microbenchmarking is that it asks about one particular pitfall and its cause. – Gaynellegayner

OP accepted it.. So it seems to be an answer. These questions are not to be answered, they are hints to OP, and I think he understood them. – Satisfy

Yes thanks a lot, in my opinion there are several correct answers – Briefs

Answer 3

JVM spent some time initializing all needed objects, access to the system time, system output stream, etc... You have two methods that happen in between:

System.nanoTime() 
System.out.println() 

Each of those could have executed a lot of init code).

Every consecutive call is much faster because this is all already set up. So when one is benchmarking an application for performance, usually warm up and cool down phase are discarded (e.g. first and last 15 minutes).

Revers

Dude, this is the reason. Learn Java or not learn it. 9th call could've been slower because, ummmm... maybe some other process used CPU time (maybe he's downloading porn). And his question was clear, he asked why such a different between 1 and two. – Revers

This isn't true, how could you know if OP is downloading porn OR doing something else OR ****. But, you should add a better reason. BTW, I am somewhat convinced that's why I removed my downvote. – Montanez

Only God knows why the 9th call was a bit slower. And that's not the question. Why the first call is slow is because Java lazily initializes stuff, acquire OS handles, etc... – Revers

Or runs the JIT compiler. ;-) – Tablespoon

@PeterPaulKiefer exactly! Can be annnyyyything. – Revers

@PeterPaulKiefer JIT will hardly get involved on the 9th iteration. Let's stay realistic. – Gaynellegayner

@MarkoTopolnik The question was: Why differ the first two meassures? I'm realistic. That's because of the JIT compiler. Really ;-) – Tablespoon

@PeterPaulKiefer Since I have information to the opposite, can you provide any reliable source which states that the JIT compiler kicks in on the first iteration through the code, with the default JVM settings? – Gaynellegayner

@MarkoTopolnik E.g. one of thousands #96135. (The focus lies on the inlining functions!) You ask me to prove my statement, and did not add a link to your information of the opposite. But I'd like to learn, if I'm wrong. (which I doubt ;-) ) – Tablespoon

@PeterPaulKiefer You linked to a Q&A about the general purpose of the JIT compiler. My question to you is much more specific: provide reference to support the assertion that JIT compilation happens on the very first iteration through code. It is otherwise a generally known fact that code has to be "warmed up" by executing it many times in order to trigger JIT compilation (specifically, 10,000 iterations is the default value for the threshold). I am truly surprised this fact has not yet reached you. Even with tiered compilation, C1 is not used on the very first run. – Gaynellegayner

@MarkoTopolnik Sorry, I doubt you know what reached me or not. And speeking of a generally known fact is not a validatable reference. The JVM warms up for functions that do not contain iterations. But if e.g. for-loops are in a function, the JVM can dicide very early to use the HotSpot Compiler. That's a generally known fact too; which this time might not has reached you ;-) – Tablespoon

@PeterPaulKiefer the JVM can decide very early---here you admit you do not know for a fact that it actually happens in this particular case. Considering that the System.out.println() call is a very special case and has very specific support from the JVM (starting with out being a final null-valued field---a clear sign of magical, extralinguistic lazy initialization), there is really no weight to your assertion. Your claim that the extra latency is about JIT compilation to the exclusion of everything else is especially baseless. – Gaynellegayner

@MarkoTopolnik I ran the code from the question in a java 8 JRE with the options -XX:+UnlockDiagnosticVMOptions -XX:+PrintAssembly. Before that, I had to download the dissasembler plugin from kenai kenai.com/projects/base-hsdis/downloads/download/… and copied it to the usr/lib path. (I work on a mint 17 machine). The JIT compiler started with the first iteration. But you are right too. It has no affect on the performance of the first iteration. If I switch off the HotSpot compiler, it has no remakable affect. – Tablespoon

@PeterPaulKiefer You didn't have to go through the trouble of installing hsdis, just -XX:+PrintCompilation would have worked well enough :) Every JVM startup involves massive amounts of code and many common functions are entered many times, triggering JIT compilation. You must take care to isolate JIT activity happening just during the call of interest. I addded a sleep command before println and found out that one method is indeed JIT-compiled: Buffer.limit, emitting just 5 bytes. That particular function call contributes negligibly to the latency of a println call. – Gaynellegayner