5

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.

Corey Farwell
  • 1,856
  • 3
  • 14
  • 19
  • 2
    It's also interesting that the first pass through the outer loop is _substantially_ faster than subsequent passes (but the ratios between the two are the same). In any case, I'm going to guess that it has to do with what `System.out.print("")` does based on what's already been printed. – Brooks Moses Feb 02 '12 at 07:48
  • the joy of microbenchmarking... you probably want to read this blog - http://www.azulsystems.com/blog/cliff/2011-11-22-what-the-heck-is-osr-and-why-is-it-bad-or-good – Matt Feb 02 '12 at 12:12
  • About the insanity note: Shouldn't it be "...and _hoping_ to get different results"? Because as it stands, if you really are getting different results each time, it's non-deterministic and it's actually quite reasonable to do the same thing over and over again. – Poindexter Feb 02 '12 at 16:30

2 Answers2

4

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
hidralisk
  • 706
  • 6
  • 18
  • Also: Run several (and several does not mean twice, usually more like 30) times in different JVMs (ie not just another loop in the program, but start the JVM several times) and print out mean and standard deviation. – Voo Feb 02 '12 at 16:22
0

I get different results. I'm using Java 1.7.0_02 and the second loop is slightly faster than the first one.

Try using "javap -l -c Test" command to disassemble the class file and check the differences. With the compiler I'm using the first loop contains ifle (branch if value <= 0) whereas the second loop contains if_icmpge (branch if value2 >= value1) and iconst_0 before it to load 0 to the stack.

msell
  • 2,168
  • 13
  • 30