Why slowdown in this identical code?

Question

I was trying to measure the time to execute this loop :

for (boolean t : test) {
    if (!t)
        ++count;
}

And was getting inconsistent results. Eventually I have managed to get consistent results with the following code :

public class Test {
    public static void main(String[] args) {
        int size = 100;
        boolean[] test = new boolean[10_000_000];
        java.util.Random r = new java.util.Random();
        for (int n = 0; n < 10_000_000; ++n)
            test[n] = !r.nextBoolean();

        int expected = 0;
        long acumulated = 0;
        for (int repeat = -1; repeat < size; ++repeat) {
            int count = 0;
            long start = System.currentTimeMillis();
            for (boolean t : test) {
                if (!t)
                    ++count;
            }
            long end = System.currentTimeMillis();
            if (repeat != -1)  // First run does not count, VM warming up
                acumulated += end - start;
            else                  // Use count to avoid compiler or JVM
                expected = count; //optimization of inner loop
            if ( count!=expected )
                throw new Error("Tests don't run same ammount of times");
        }
        float average = (float) acumulated / size;
        System.out.println("1st test : " + average);

        int expectedBis = 0;
        acumulated = 0;
        if ( "reassign".equals(args[0])) {
            for (int n = 0; n < 10_000_000; ++n)
                test[n] = test[n];
        }
        for (int repeat = -1; repeat < size; ++repeat) {
            int count = 0;
            long start = System.currentTimeMillis();
            for (boolean t : test) {
                if (!t)
                    ++count;
            }
            long end = System.currentTimeMillis();
            if (repeat != -1)  // First run does not count, VM warming up
                acumulated += end - start;
            else                     // Use count to avoid compiler or JVM
                expectedBis = count; //optimization of inner loop
            if ( count!=expected || count!=expectedBis)
                throw new Error("Tests don't run same ammount of times");
        }
        average = (float) acumulated / size;
        System.out.println("2nd test : " + average);
    }

}

The results I get are :

$ java -jar Test.jar noreassign
1st test : 23.98
2nd test : 23.97
$ java -jar Test.jar reassign
1st test : 23.98
2nd test : 40.86
$ java -version
java version "1.7.0_79"
OpenJDK Runtime Environment (IcedTea 2.5.5) (Gentoo package icedtea-7.2.5.5)
OpenJDK 64-Bit Server VM (build 24.79-b02, mixed mode)

The difference is in executing or not this loop before the 2nd test.

for (int n = 0; n < 10_000_000; ++n)
    test[n] = test[n];

Why? Why does doing that reassignation cause those loops after it to take twice the time?
Getting profiling right is hard...

Better start studying JIT-compiled code of your program because that's the only place you have a chance of finding the answer. — Marko Topolnik, Aug 31 '15 at 21:06
Your extra loop may be pulling some or all of the test[] array into fast memory, so it executes more consistently. It may also allow the JIT compiler to do some optimisation. In general, if you want an accurate timing, run the process a few hundred/thousand times before starting the timing loop. That way any startup effects are avoided, and the system is in a steady state. — rossum, Aug 31 '15 at 21:11
@rossum If the reassign loop pulls test[] into fast memory I would expect the 2nd test to run faster. Same for JIT optimisations. But I get the opposite result. I've also tried increasing the warming up non measuring loops from 1 to 1000 but still get the same result. But yes, this is likely a JIT compiler issue. — Anonymous Coward, Aug 31 '15 at 21:26

score 3 · Answer 1 · answered Aug 31 '15 at 21:27

3

I would add this as a comment, but my reputation is too low, so it must be added as an answer.

I've created a jar with your exact code, and ran it several times. I also copied the code to C# and ran it in the .NET runtime as well.

Both Java and C# show the same exact time, with and without the 'reassign' loop.

What timing are you getting if you change the loop to

 if ( "reassign".equals(args[0])) {
        for (int n = 0; n < 5_000_000; ++n)
            test[n] = test[n];
    }

?

answered Aug 31 '15 at 21:27

Marius Dornean

131
4

I get 1st test : 24.01 2nd test : 38.06 with "reassign" and I get 1st test : 24.0 2nd test : 23.97 with "noreassign". So the same results. Must be something specific to my JVM, OS and/or machine. – Anonymous Coward Aug 31 '15 at 21:31
I predict that it would make no difference. – Stephen C Sep 01 '15 at 01:38

score 3 · Answer 2 · answered Aug 31 '15 at 21:43

Marko Topolniks's and rossum's comments got me on the right direction.
It is a JIT compiler issue.
If I disable the JIT compiler I get these results :

$ java -jar Test.jar -Djava.compiler=NONE noreassign  
1st test : 19.23  
2nd test : 19.33  
$ java -jar Test.jar -Djava.compiler=NONE reassign  
1st test : 19.23  
2nd test : 19.32

The strange slowdown dissapears once the JIT compiler is deactivated.
As for why the JIT compiler causes such behaviour... that is beyond my skill and knowledge.
But it does not happen in all JVMs as Marius Dornean's tests show.

score 3 · Accepted Answer · edited May 23 '17 at 12:24

"As for why the JIT compiler causes such behaviour... that is beyond my skill and knowledge."

Three basic facts:

Code runs faster after JIT compilation.
JIT compilation is triggered after a chunk of code has run for a bit. (How long "a bit" is is influenced the JVM platform and command line options.)
JIT compilation takes time.

In your case, when you insert the big assignment loop between test 1 and test 2, you are most likely moving the time point at which JIT compilation is triggered ... from during test 2 to between the 2 tests.

The simple way address this in this case is to put the body of main into a loop and run it repeatedly. Then discard the anomalous results in the first few runs.

(Turning off JIT compilation is not a good answer. Normally, it is the performance characteristics of code after JIT compilation that is going to be indicative of how a real application performs ...)

By setting the compiler to NONE, you are disabling JIT compilation, taking it out of the equation.

This kind of anomaly is common when people attempt to write micro-benchmarks by hand. Read this Q&A:

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

Why slowdown in this identical code?

3 Answers3