unexplained 10%+ performance boost from simply adding a method argument (slimmer jit code)

Question

(note: proper answer must go beyond reproduction).

After millions of invocations, quicksort1 is definitely faster than quicksort2, which have identical code aside from this 1 extra arg.

The code is at the end of the post. Spoiler: I also found the jit code is fatter by 224 bytes even if it should be actually simpler (like the byte code size tells; see very last update below).

Even after trying to factor out this effect with some microbenchmark harness (JMH), the performance difference is still there.

I'm asking: WHY is there a such a difference in native code generated and what is it doing?

By adding an argument to a method, it makes it faster...! I know about gc/jit/warmup/etc effects. You can run code as-is, or with larger/smaller iteration counts. Actually, you should even comment out one then the other perf test and run each in distinct jvm instance just to prove it's not an interference between each other.

The bytecode doesn't show much difference, aside the obvious getstatic for sleft/sright but also a strange 'iload 4' instead of "iload_3" (and istore 4/istore_3)

What the heck is going on? Is the iload_3/istore_3 really slower than iload 4/istore 4? And that much slower that even the added getstatic call is still not making it slower? I can guess that static fields are unused so the jit might just skip it.

Anyway, there is no ambiguity on my side as it is always reproducable, and I'm looking for the explanation as to why the javac/jit did what they did, and why the performance is affected so much. These are identical recursive algo with same data, same memory churn, etc... I couldn't make an more isolated change if I wanted to, to show a significant replicable runtime difference.

Env:

java version "1.8.0_161" 
Java(TM) SE Runtime Environment (build 1.8.0_161-b12)
Java HotSpot(TM) 64-Bit Server VM (build 25.161-b12, mixed mode)
(also tried and reproduced on java9)
on a 4 core i5 laptop 8GB ram.
windows 10 with the meltdown/specter patch.

With -verbose:gc -XX:+PrintCompilation, there is no gc and jit compilation has stabilised in C2 (tier 4).

With n=20000:

main]: qs1: 1561.3336199999999 ms (res=null)
main]: qs2: 1749.748416 ms (res=null)

main]: qs1: 1422.0767509999998 ms (res=null)
main]: qs2: 1700.4858689999999 ms (res=null)

main]: qs1: 1519.5280269999998 ms (res=null)
main]: qs2: 1786.2206899999999 ms (res=null)

main]: qs1: 1450.0802979999999 ms (res=null)
main]: qs2: 1675.223256 ms (res=null)

main]: qs1: 1452.373318 ms (res=null)
main]: qs2: 1634.581156 ms (res=null)

BTW, beautiful java9 seems to make both faster but still 10-15% off from each other.:

[0.039s][info][gc] Using G1
main]: qs1: 1287.062819 ms (res=null)
main]: qs2: 1451.041391 ms (res=null)

main]: qs1: 1240.800305 ms (res=null)
main]: qs2: 1391.2404299999998 ms (res=null)

main]: qs1: 1257.1707159999999 ms (res=null)
main]: qs2: 1433.84716 ms (res=null)

main]: qs1: 1233.7582109999998 ms (res=null)
main]: qs2: 1394.7195849999998 ms (res=null)

main]: qs1: 1250.885867 ms (res=null)
main]: qs2: 1413.88437 ms (res=null)

main]: qs1: 1261.5805739999998 ms (res=null)
main]: qs2: 1458.974334 ms (res=null)

main]: qs1: 1237.039902 ms (res=null)
main]: qs2: 1394.823751 ms (res=null)

main]: qs1: 1255.14672 ms (res=null)
main]: qs2: 1400.693295 ms (res=null)

main]: qs1: 1293.009808 ms (res=null)
main]: qs2: 1432.430952 ms (res=null)

main]: qs1: 1262.839628 ms (res=null)
main]: qs2: 1421.376644 ms (res=null)

CODE (INCLUDING TESTS):

(Please don't pay attention to how bad this quicksort is; it's beside the question).

import java.util.Random;
import java.util.concurrent.Callable;

public class QuicksortTrimmed {

    static void p(Object msg) {
        System.out.println(Thread.currentThread().getName()+"]: "+msg);
    }

    static void perf(int N, String msg, Callable c) throws Exception {
        Object res = null;
        long t = System.nanoTime();
        for(int i=0; i<N; i++) {
            res = c.call();
        }
        Double d = 1e-6*(System.nanoTime() - t);
        p(msg+": "+d+" ms (res="+res+")");
    }

    static String und = "__________";//10
    static {
        und += und;//20
        und += und;//40
        und += und;//80
        und += und;//160
    }

    static String sleft = "//////////";//10
    static {
        sleft += sleft;//20
        sleft += sleft;//40
        sleft += sleft;//80
        sleft += sleft;//160
    }

    static String sright= "\\\\\\\\\\\\\\\\\\\\";//10
    static {
        sright += sright;//20
        sright += sright;//40
        sright += sright;//80
        sright += sright;//160
    }

    //============

    public static void main(String[] args) throws Exception {
        int N = 20000;
        int n = 1000;
        int bound = 10000;
        Random r = new Random(1);
        for(int i=0; i<5; i++) {
            testperf(N, r, n, bound);
            //System.gc();
        }
    }

    static void testperf(int N, Random r, int n, int bound) throws Exception {
        final int[] orig = r.ints(n, 0, bound).toArray();
        final int[] a = orig.clone();

        perf(N, "qs1", () -> {
            System.arraycopy(orig, 0, a, 0, orig.length);
            quicksort1(a, 0, a.length-1, und);
            return null;
        });

        perf(N, "qs2", () -> {
            System.arraycopy(orig, 0, a, 0, orig.length);
            quicksort2(a, 0, a.length-1);
            return null;
        });
        System.out.println();
    }


    private static void quicksort1(int[] a, final int _from, final int _to, String mode) {
        int len = _to - _from + 1;
        if(len==2) {
            if(a[_from] > a[_to]) {
                int tmp = a[_from];
                a[_from] = a[_to];
                a[_to] = tmp;
            }
        } else { //len>2
            int mid = _from+len/2;
            final int pivot = a[mid];
            a[mid] = a[_to];
            a[_to] = pivot; //the pivot value is the 1st high value

            int i = _from;
            int j = _to;

            while(i < j) {
                if(a[i] < pivot)
                    i++;
                else if(i < --j) { //j is the index of the leftmost high value 
                    int tmp = a[i];
                    a[i] = a[j];  //THIS IS HARMFUL: maybe a[j] was a high value too.
                    a[j] = tmp;
                }
            }

            //swap pivot in _to with other high value in j
            int tmp = a[j];
            a[j] = a[_to];
            a[_to] = tmp;

            if(_from < j-1)
                quicksort1(a, _from, j-1, sleft);
            if(j+1 < _to)
                quicksort1(a, j+1, _to, sright);
        }
    }

    private static void quicksort2(int[] a, final int _from, final int _to) {
        int len = _to - _from + 1;
        if(len==2) {
            if(a[_from] > a[_to]) {
                int tmp = a[_from];
                a[_from] = a[_to];
                a[_to] = tmp;
            }
        } else { //len>2
            int mid = _from+len/2;
            final int pivot = a[mid];
            a[mid] = a[_to];
            a[_to] = pivot; //the pivot value is the 1st high value

            int i = _from;
            int j = _to;

            while(i < j) {
                if(a[i] < pivot)
                    i++;
                else if(i < --j) { //j is the index of the leftmost high value 
                    int tmp = a[i];
                    a[i] = a[j];  //THIS IS HARMFUL: maybe a[j] was a high value too.
                    a[j] = tmp;
                }
            }

            //swap pivot in _to with other high value in j
            int tmp = a[j];
            a[j] = a[_to];
            a[_to] = tmp;

            if(_from < j-1)
                quicksort2(a, _from, j-1);
            if(j+1 < _to)
                quicksort2(a, j+1, _to);
        }
    }

}

UPDATE:

I made the JMH test and it still proves quicksort1 is faster than quicksort2.

# Run complete. Total time: 00:13:38

Benchmark                    Mode  Cnt      Score    Error  Units
MyBenchmark.testQuickSort1  thrpt  200  14861.437 ± 86.707  ops/s
MyBenchmark.testQuickSort2  thrpt  200  13097.209 ± 46.178  ops/s

Here is the JMH benchmark:

package org.sample;

import java.util.Random;

import org.openjdk.jmh.annotations.Benchmark;
import org.openjdk.jmh.annotations.Level;
import org.openjdk.jmh.annotations.Scope;
import org.openjdk.jmh.annotations.Setup;
import org.openjdk.jmh.annotations.State;
import org.openjdk.jmh.infra.Blackhole;

public class MyBenchmark {
    static String und = "__________";//10
    static {
        und += und;//20
        und += und;//40
        und += und;//80
        und += und;//160
    }

    static String sleft = "//////////";//10
    static {
        sleft += sleft;//20
        sleft += sleft;//40
        sleft += sleft;//80
        sleft += sleft;//160
    }

    static String sright= "\\\\\\\\\\\\\\\\\\\\";//10
    static {
        sright += sright;//20
        sright += sright;//40
        sright += sright;//80
        sright += sright;//160
    }

    static final int n = 1000;
    static final int bound = 10000;
    static Random r = new Random(1);
    static final int[] orig = r.ints(n, 0, bound).toArray();

    @State(Scope.Thread)
    public static class ThrState {
        int[] a;

        @Setup(Level.Invocation)
        public void setup() {
            a = orig.clone();
        }
    }

    //============

    @Benchmark
    public void testQuickSort1(Blackhole bh, ThrState state) {
        int[] a = state.a;
        quicksort1(a, 0, a.length-1, und);
        bh.consume(a);
    }

    @Benchmark
    public void testQuickSort2(Blackhole bh, ThrState state) {
        int[] a = state.a;
        quicksort2(a, 0, a.length-1);
        bh.consume(a);
    }


    private static void quicksort1(int[] a, final int _from, final int _to, String mode) {
        int len = _to - _from + 1;
        if(len==2) {
            if(a[_from] > a[_to]) {
                int tmp = a[_from];
                a[_from] = a[_to];
                a[_to] = tmp;
            }
        } else { //len>2
            int mid = _from+len/2;
            final int pivot = a[mid];
            a[mid] = a[_to];
            a[_to] = pivot; //the pivot value is the 1st high value

            int i = _from;
            int j = _to;

            while(i < j) {
                if(a[i] < pivot)
                    i++;
                else if(i < --j) { //j is the index of the leftmost high value 
                    int tmp = a[i];
                    a[i] = a[j];  //THIS IS HARMFUL: maybe a[j] was a high value too.
                    a[j] = tmp;
                }
            }

            //swap pivot in _to with other high value in j
            int tmp = a[j];
            a[j] = a[_to];
            a[_to] = tmp;

            if(_from < j-1)
                quicksort1(a, _from, j-1, sleft);
            if(j+1 < _to)
                quicksort1(a, j+1, _to, sright);
        }
    }

    private static void quicksort2(int[] a, final int _from, final int _to) {
        int len = _to - _from + 1;
        if(len==2) {
            if(a[_from] > a[_to]) {
                int tmp = a[_from];
                a[_from] = a[_to];
                a[_to] = tmp;
            }
        } else { //len>2
            int mid = _from+len/2;
            final int pivot = a[mid];
            a[mid] = a[_to];
            a[_to] = pivot; //the pivot value is the 1st high value

            int i = _from;
            int j = _to;

            while(i < j) {
                if(a[i] < pivot)
                    i++;
                else if(i < --j) { //j is the index of the leftmost high value 
                    int tmp = a[i];
                    a[i] = a[j];  //THIS IS HARMFUL: maybe a[j] was a high value too.
                    a[j] = tmp;
                }
            }

            //swap pivot in _to with other high value in j
            int tmp = a[j];
            a[j] = a[_to];
            a[_to] = tmp;

            if(_from < j-1)
                quicksort2(a, _from, j-1);
            if(j+1 < _to)
                quicksort2(a, j+1, _to);
        }
    }

}

UPDATE:

At this moment, I ran and captured a jit log for jitwatch (I used the 1.3.0 tag and built from https://github.com/AdoptOpenJDK/jitwatch/tree/1.3.0)

-verbose:gc
-XX:+PrintGCDateStamps
-XX:+PrintGCDetails
-Xloggc:"./gc.log"
-XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=10 -XX:GCLogFileSize=1M
-XX:+PrintGCApplicationStoppedTime
-XX:+PrintCompilation
-XX:+PrintSafepointStatistics
-XX:PrintSafepointStatisticsCount=1
-XX:+UnlockDiagnosticVMOptions  -XX:+LogCompilation -XX:+PrintInlining

There are no obvious "suggestions" from jitwatch, just the rgular too big to inline or too deep, for both quicksort1 and quicksort2 anyway.

The one important discovery is the bytecode and native code difference:

With extra method argument (quicksort1): byte code = 187 bytes native code = 1872 bytes

Without extra method argument (quicksort2): byte code = 178 bytes (smaller by 9 bytes) native code = 2096 bytes (bigger by 224 bytes!!!)

This is a strong evidence that the jit code is fatter and slower in quicksort2.

So the question remains: what was the C2 jit compiler thinking? what rule made it create faster native code when I add a method argument and 2 static reference to load and pass?

I finally got my hand on the assembly code, but as I expected, it's nearly impossible to diff and understand what's happening. I followed the most recent instruction I could find from https://stackoverflow.com/a/24524285/2023577 . I have 7MB xml log file (compressed to 675kB) you can get it and see for 7 days (expire ~may 4th 2018) at https://wetransfer.com/downloads/65fe0e94ab409d57cba1b95459064dd420180427150905/612dc9 in case you can make sense of it (in jitwatch of course!).

The added string param leads to more compact assembly code. The questions (still unanswered) is why? what is different in the assembly code? what is the rule or optimization that isn't used in the slower code?

Answer 1

Reproduction and Analysis

I was able to reproduce your results. Machine data:

Linux #143-Ubuntu x86_64 GNU/Linux
java version "1.8.0_171"
Java(TM) SE Runtime Environment (build 1.8.0_171-b11)
Java HotSpot(TM) 64-Bit Server VM (build 25.171-b11, mixed mode)

I rewrote your code a bit and I have done some additional testing. Your test time includes the System.arraycopy() call. I created a 400Mb array structure and saved it:

int[][][] data = new int[iterations][testCases][];
for (int iteration = 0; iteration < data.length; iteration++) {
    for (int testcase = 0; testcase < data[iteration].length; testcase++) {
        data[iteration][testcase] = random.ints(numberCount, 0, bound).toArray();
    }
}

FileOutputStream fos = new FileOutputStream("test_array.dat");
ObjectOutputStream oos = new ObjectOutputStream(fos);
oos.writeObject(data);

After that I have run this tests (warmup, teardown run as well):

{
    FileInputStream fis = new FileInputStream(fileName);
    ObjectInputStream iis = new ObjectInputStream(fis);
    int[][][] data = (int[][][]) iis.readObject();


    perf("qs2", () -> {
        for (int iteration = 0; iteration < data.length; iteration++) {
            for (int testCase = 0; testCase < data[iteration].length; testCase++) {
                quicksort2(data[iteration][testCase], 0, data[iteration][testCase].length - 1);
            }
        }
        return null;
    });
}
{
    FileInputStream fis = new FileInputStream(fileName);
    ObjectInputStream iis = new ObjectInputStream(fis);
    int[][][] data = (int[][][]) iis.readObject();


    perf("qs1", () -> {
        for (int iteration = 0; iteration < data.length; iteration++) {
            for (int testCase = 0; testCase < data[iteration].length; testCase++) {
                quicksort1(data[iteration][testCase], 0, data[iteration][testCase].length - 1, und);
            }
        }
        return null;
    });
}

In case I run the qs1 and qs2 together:

main]: qs1: 6646.219874 ms (res=null)
main]: qs2: 7418.376646 ms (res=null)

The result is not execution order dependent:

main]: qs2: 7526.215395 ms (res=null)
main]: qs1: 6624.261529 ms (res=null)

I have run the code in new JVM instances as well:

Instance one:

main]: qs1: 6592.699738 ms (res=null)

Instance two:

main]: qs2: 7456.326028 ms (res=null)

If you try it without the JIT:

-Djava.compiler=NONE

The results are as "expected" (the smaller bytecode is faster):

main]: qs1: 56547.589942 ms (res=null)
main]: qs2: 53585.909246 ms (res=null)

For better analysis I extracted the codes to two different classes.

I was using jclasslib for bytecode inspection. The method lengths for me:

Q1: 505
Q2: 480

This makes sense for the execution without the JIT:

53585.909246×505÷480 = 56376.842019229

Which is really close to 56547.589942.

Reason

For me in the compilation output (using -XX:+PrintCompilation) I have these lines

1940  257       2       QS1::sort (185 bytes)
1953  258 %     4       QS1::sort @ 73 (185 bytes)
1980  259       4       QS1::sort (185 bytes)
1991  257       2       QS1::sort (185 bytes)   made not entrant
9640  271       3       QS2::sort (178 bytes)
9641  272       4       QS2::sort (178 bytes)
9654  271       3       QS2::sort (178 bytes)   made not entrant

Where the % means on stack replacement (where the compiled code is running). According to this log the call with the extra String parameter gets optimized and the second is not. I was thinking on better branch prediction, but this should not be the case here (tried to add randomli generated Strings as parameters). The sample sizes (400Mb) mostly rule out caching. I thought on optimization treshold, but when I use these options -Xcomp -XX:+PrintCompilation -Xbatch the output is the following:

 6408 3254    b  3       QS1::sort (185 bytes)
 6409 3255    b  4       QS1::sort (185 bytes)
 6413 3254       3       QS1::sort (185 bytes)   made not entrant
14580 3269    b  3       QS2::sort (178 bytes)
14580 3270    b  4       QS2::sort (178 bytes)
14584 3269       3       QS2::sort (178 bytes)   made not entrant

This means that the metods are fored blocking compiled before called but the times remain the same:

main]: qs1: 6982.721328 ms (res=null)
main]: qs2: 7606.077812 ms (res=null)

The key to this I think is the String. In case I change the extra (unused) parameter to int it is consistently processed slightly slower (running with the previous optimization parameters):

main]: qs1: 7925.472909 ms (res=null)
main]: qs2: 7727.628422 ms (res=null)

My conclusion is that the optimization may be influenced by the extra parameters object type. Probably there is less eager optimization in case of primitives which makes sense to me, but I could not find exact source for that claim.

An additional interesting read.