CODEWITHSUNDEEP
java
Anonymous Coward
Anonymous Coward

Reputation: 3200

Why slowdown in this identical code?

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

Upvotes: 4

Views: 131

Answers (3)

Stephen C
Stephen C

Reputation: 718698

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

Three basic facts:

  1. Code runs faster after JIT compilation.

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

  3. 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:

Upvotes: 3

Anonymous Coward
Anonymous Coward

Reputation: 3200

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.

Upvotes: 3

Marius Dornean
Marius Dornean

Reputation: 131

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];
    }

?

Upvotes: 3

Related Questions