Strange code timing behavior in Java

Question

In the following code:

long startingTime = System.nanoTime();
int max = (int) Math.pow(2, 19);
for(int i = 0; i < max; ){
    i++;
}
long timePass = System.nanoTime() - startingTime;
System.out.println("Time pass " + timePass / 1000000F);

I am trying to calculate how much time it take to perform simple actions on my machine.

All the calculations up to the power of 19 increase the time it takes to run this code, but when I went above 19(up to max int value 31) I was amazed to discover that it have no effect on the time it takes. It always shows 5 milliseconds on my machine!!!

How can this be?

Math.pow is not only expensive but can have rounding errors. Try `1 << 19` which is the same as `(int) Math.pow(2, 19)` except more efficient. — Peter Lawrey, Jul 09 '12 at 08:29

score 12 · Accepted Answer · answered Jul 09 '12 at 07:59

12

You have just witnessed HotSpot optimizing your entire loop to oblivion. It's smart. You need to do some real action inside the loop. I recommend introducing an int accumulator var and doing some bitwise operations on it, and finally printing the result to ensure it's needed after the loop.

answered Jul 09 '12 at 07:59

Marko Topolnik

195,646
29
319
436

1

related question: http://stackoverflow.com/questions/504103/how-do-i-write-a-correct-micro-benchmark-in-java – Joachim Sauer Jul 09 '12 at 08:01
Very nice find, @JoachimSauer. – Marko Topolnik Jul 09 '12 at 08:02
Making the counter `static` can prevent some optimisation and stop the loop being reduced to nothing. – Peter Lawrey Jul 09 '12 at 08:28
@PeterLawrey I think I already saw HotSpot being smart enough to just **add** `N` directly to the counter, instead of incrementing it `N` times! – Marko Topolnik Jul 09 '12 at 08:30
It can do that, but in this case it may detect that `i` is not used after the loop and discard it. – Peter Lawrey Jul 09 '12 at 08:32
@PeterLawrey My comment is in response to your suggestion with `static`. It won't discard `i` in that case, but it may still assign the end result directly to it. – Marko Topolnik Jul 09 '12 at 08:36
Good point, I have just tested it and it appears it does exactly that. – Peter Lawrey Jul 09 '12 at 08:44

Peter Lawrey · Answer 2 · 2012-07-09T08:44:35.837

2

On the HotSpot JVM, -XX:CompileThreshold=10000 by default. This means a loop which iterates 10K times can trigger the whole method to be optimised. In your case you are timing how long it take to detect and compile (in the background) your method.

edited Jul 09 '12 at 08:44

answered Jul 09 '12 at 08:31

Peter Lawrey

525,659
79
751
1,130

2

It is fun to notice also that, if we can assume OP is running the whole thing in a single method. HotSpot actually replaces the method's code in the middle of its execution, transfering the complete state from the interpreted to the compiled version! – Marko Topolnik Jul 09 '12 at 08:47
Something JRocket doesn't do btw. This means that your first main() will never be optimised in JRocket. – Peter Lawrey Jul 09 '12 at 08:51
1

@MarkoTopolnik: when I read up on some HotSpot teachniques I came accross "deoptimization" which actually does the reverse! That's even more fun. (That's necessary if a assumption made about the code later gets invalidated, such as the VM "knowing" that there's only a single class involved and later a second class in the same hierarchy gets loaded). – Joachim Sauer Jul 09 '12 at 10:07
I believe it will also deoptimise if it assume a condition is always false and it later becomes true (visa-versa) e.g. turning assertions on. – Peter Lawrey Jul 09 '12 at 10:51

score 0 · Answer 3 · answered Jul 09 '12 at 08:47

0

use another System.nanoTime() in the loop. no one can optimize this.

for(int i = 0; i < max; ){
i++;
dummy+=System.nanoTime();
}

dont forget to do:

System.out.println(dummy);

after the loop. ensures non-optimization

answered Jul 09 '12 at 08:47

huseyin tugrul buyukisik

11,469
4
45
97

Isn't the `nanoTime()` call quite costly compared to, say, `acc |= i`? You'll basically be measuring the performance of `nanoTime()` this way. – Marko Topolnik Jul 09 '12 at 08:48
if you add 40 or 200 lines of i++;i++;i++; you can dwarf System.nanoTime() – huseyin tugrul buyukisik Jul 09 '12 at 15:33
also if you get the time of nanotimed-loop, you can use this as an offset value to subtract from other test which include nanotime. you will need lots of samplings to get a proper result – huseyin tugrul buyukisik Jul 09 '12 at 15:37

Strange code timing behavior in Java

3 Answers3