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

http://stackoverflow.com/questions/860231/first-time-a-java-loop-is-run-slow-why-sun-hotspot-1-5-sparc Refer this question, it may help. — Sneh, Aug 06 '15 at 14:27
optimisation/prediction maybe ? + static "test" initialisation for the first time — Hacketo, Aug 06 '15 at 14:28
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. — Peter Paul Kiefer, Aug 06 '15 at 14:30

Marko Topolnik · Accepted Answer · 2015-08-06T19:16:54.460

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.

score 17 · Answer 2 · edited May 23 '17 at 12:08

17

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?.

edited May 23 '17 at 12:08

Community

1
1

answered Aug 06 '15 at 14:29

Maroun

94,125
30
188
241

2

@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. – Am_I_Helpful Aug 06 '15 at 14:40
3

`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. – Marko Topolnik Aug 06 '15 at 14:41
2

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. – Maroun Aug 06 '15 at 20:22
1

Yes thanks a lot, in my opinion there are several correct answers – Jürgen K. Aug 12 '15 at 10:25

darijan · Answer 3 · 2015-08-06T14:31:42.667

4

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

edited Aug 06 '15 at 14:31

answered Aug 06 '15 at 14:26

darijan

9,725
25
38

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. – darijan Aug 06 '15 at 14:29
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. – Am_I_Helpful Aug 06 '15 at 14:31
2

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... – darijan Aug 06 '15 at 14:32
1

Or runs the JIT compiler. ;-) – Peter Paul Kiefer Aug 06 '15 at 14:34
@PeterPaulKiefer exactly! Can be annnyyyything. – darijan Aug 06 '15 at 14:34
@PeterPaulKiefer JIT will hardly get involved on the 9th iteration. Let's stay realistic. – Marko Topolnik Aug 06 '15 at 14:34
@MarkoTopolnik The question was: Why differ the first two meassures? I'm realistic. That's because of the JIT compiler. Really ;-) – Peter Paul Kiefer Aug 06 '15 at 14:38
1

@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? – Marko Topolnik Aug 06 '15 at 14:44
@MarkoTopolnik E.g. one of thousands http://stackoverflow.com/questions/95635/what-does-a-just-in-time-jit-compiler-do. (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 ;-) ) – Peter Paul Kiefer Aug 06 '15 at 14:52
1

@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. – Marko Topolnik Aug 06 '15 at 14:57
@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 ;-) – Peter Paul Kiefer Aug 06 '15 at 15:41
1

@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. – Marko Topolnik Aug 06 '15 at 16:00
@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 https://kenai.com/projects/base-hsdis/downloads/download/linux-hsdis-amd64.so 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. – Peter Paul Kiefer Aug 06 '15 at 17:03
@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. – Marko Topolnik Aug 06 '15 at 19:11

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

3 Answers3