Java optimization: speed of inner loops inconsistent?

Question

My friend and I are stumped. In these two blocks of code, why is the first inner loop faster than the second inner loop? Is this some sort of JVM optimization?

public class Test {
   public static void main(String[] args) {
      int[] arr = new int[100000000];
      arr[99999999] = 1;
      long t1, t2, t3;
      for (int ndx = 0; ndx < 10; ndx++) {
         t1 = System.currentTimeMillis();
         for (int i = 0; i < arr.length; i++)
            if (0 < arr[i])
               System.out.print("");

         t2 = System.currentTimeMillis();
         for (int i = 0; i < arr.length; i++)
            if (arr[i] > 0)
               System.out.print("");

         t3 = System.currentTimeMillis();
         System.out.println(t2 - t1 +" "+(t3 - t2));
      }
   }
}

And the results:

me@myhost ~ $ java Test
57 80
154 211
150 209
149 209
150 209
150 209
151 209
150 210
150 210
149 209

Swapped the orderings of inequalities:

public class Test {
   public static void main(String[] args) {
      int[] arr = new int[100000000];
      arr[99999999] = 1;
      long t1, t2, t3;
      for (int ndx = 0; ndx < 10; ndx++) {
         t1 = System.currentTimeMillis();
         for (int i = 0; i < arr.length; i++)
            if (arr[i] > 0)
               System.out.print("");

         t2 = System.currentTimeMillis();
         for (int i = 0; i < arr.length; i++)
            if (0 < arr[i])
               System.out.print("");

         t3 = System.currentTimeMillis();
         System.out.println((t2 - t1) +" "+(t3 - t2));
      }
   }
}

And the results:

me@myhost ~ $ java Test
56 80
155 210
150 209
149 209
151 210
149 209
150 209
149 208
149 209
149 208

Insanity: doing the same thing over and over again and getting different results.

Answer 1

Short answer: To avoid this problem, put the code you are testing in a separate method. Warm up the method by calling it 11,000 times before you time it. These 2 will allow the JIT compiler to swap the method with a compiled version. Run with -server, it's just better tuned. Use System.nanoTime() to time stuff. With the following code you'll get consistent measurements.

public class AlphaTest
{
public static void processA(int[] arr)
{
    for (int i = 0; i < arr.length; i++)
        if (arr[i] > 0)
            System.out.print("");
}

public static void processB(int[] arr)
{
    for (int i = 0; i < arr.length; i++)
        if (0 < arr[i])
            System.out.print("");
}

public static void main(String[] args)
{
    int[] smallArr = new int[10];
    for (int i = 0; i < smallArr.length; i++)
    {
        smallArr[i] = 1;
    }
    //warmup
    for (int i = 0; i < 11000; i++)
    {
        processA(smallArr);
        processB(smallArr);
    }

    int[] arr = new int[100000000];
    arr[99999999] = 1;
    long t1, t2, t3;
    for (int ndx = 0; ndx < 10; ndx++)
    {
        t1 = System.nanoTime();
        processA(arr);

        t2 = System.nanoTime();
        processB(arr);

        t3 = System.nanoTime();
        System.out.println(((t2 - t1)/1000000L) + " " + ((t3 - t2)/1000000L));
    }
}
}

Long Answer: This is definitely a problem of "microbenchmarking" as noted by Matt in the comments. Please see Azul Blog. To support this point of view I am getting the following results depending on how I run the program: as -client as -server and with JIT disabled only 2 result lines per setup, the rest are similar.

java -client -Xms1024m -Xmx1024m Test
272 262
263 252
...
java -server -Xms1024m -Xmx1024m Test
513 173
483 201
...
java -client -Djava.compiler=NONE -Xms1024m -Xmx1024m AlphaTest
2062 1929
2042 2034
...
java -server -Djava.compiler=NONE -Xms1024m -Xmx1024m AlphaTest
1844 1864
1843 1931