First time a Java loop is run SLOW, why? [Sun HotSpot 1.5, sparc]

Question

In benchmarking some Java code on a Solaris SPARC box, I noticed that the first time I call the benchmarked function it runs EXTREMELY slowly (10x difference):

• First | 1 | 25295.979 ms
• Second | 1 | 2256.990 ms
• Third | 1 | 2250.575 ms

Why is this? I suspect the JIT compiler, is there any way to verify this?

Edit: In light of some answers I wanted to clarify that this code is the simplest possible test-case I could find exhibiting this behavior. So my goal isn't to get it to run fast, but to understand what's going on so I can avoid it in my real benchmarks.

Solved: Tom Hawtin correctly pointed out that my "SLOW" time was actually reasonable. Following this observation, I attached a debugger to the Java process. During the first, the inner loop looks like this:

0xf9037218:     cmp      %l0, 100
0xf903721c:     bge,pn   %icc,0xf90371f4        ! 0xf90371f4
0xf9037220:     nop
0xf9037224:     ld       [%l3 + 92], %l2
0xf9037228:     ld       [%l2 + 8], %l6
0xf903722c:     add      %l6, 1, %l5
0xf9037230:     st       %l5, [%l2 + 8]
0xf9037234:     inc      %l0
0xf9037238:     ld       [%l1], %g0
0xf903723c:     ba,pt    %icc,0xf9037218        ! 0xf9037218

On the following iterations, the loop looks like this:

0xf90377d4:     sub      %l2, %l0, %l3
0xf90377d8:     add      %l3, %l0, %l2
0xf90377dc:     add      %l2, 1, %l4
0xf90377e0:     inc      %l0
0xf90377e4:     cmp      %l0, 100
0xf90377e8:     bl,pn    %icc,0xf90377d8        ! 0xf90377d8

So HotSpot removed memory accesses from the inner loop, speeding it up by an order of magnitude.

Lesson: Do the math! I should have done Tom's calculation myself.

Benchmark Java code:

    private int counter;
    private int nThreads;

    private void measure(String tag) throws Exception {
            MyThread threads[] = new MyThread[nThreads];
            int i;

            counter = 0;

            for (i = 0; i < nThreads; i++)
                    threads[i] = new MyThread();

            long start = System.nanoTime();

            for (i = 0; i < nThreads; i++)
                    threads[i].start();

            for (i = 0; i < nThreads; i++)
                    threads[i].join();

            if (tag != null)
                    System.out.format("%-20s | %-2d | %.3f ms \n", tag, nThreads,
                                     new Double((System.nanoTime() - start) / 1000000.0));
    }
    public MyBench() {
            try {
                    this.nThreads = 1;
                    measure("First");
                    measure("Second");
                    measure("Third");
            } catch (Exception e) {
                    System.out.println("Error: " + e);
            }
    }

    private class MyThread extends Thread {
            public void run() {
                    while (counter < 10000000) {
                            // work
                            for (int j = 0; j < 100; j++)
                                    counter++;
                            counter -= 99;
                    }
            }
    }

Answer 1

That's an interesting question. I'd suspect the JIT compiler, but these are my numbers:

First                | 1  | 2399.233 ms 
Second               | 1  | 2322.359 ms 
Third                | 1  | 2408.342 ms 

Possibly Solaris is doing something funny with threads; have you tried with nThreads = 10 or so?

Answer 2

It's the hotspot compiler at work. AFAIK, the first time it runs the function, runs "interpreted" and the execution path is analyzed, then the JIT compiler can optimize the subsequent function calls.

Answer 3

Add class loading in as a suspect. Classes are loaded lazily on first reference. So the first time the code runs, you're probably referencing some classes for the first time.

Answer 4

I suggest you make nThread = Runtime.getRuntime().availableProcessors() This will give you the optimal number of threads to use all the cores in your system.

You can try turning off the JIT to see what difference it makes.

Answer 5

It's most certainly the hotspot compiler. If you're running on 64 bit solaris it defaults to the server VM and hotspot just start optimizing on first execution. On the client VM the code may need to run a few times before hotspot kicks in. (i believe solaris only has the server vm but I may be wrong)

Answer 6

You can get the VM to log information about classloading and compilation, try the following VM args: -XX:+PrintCompilation -XX:+TraceClassLoading This might give some further clues as to what's happening under the hood.

EDIT: I'm not sure those options work in java 1.5 (I've used them in 1.6). I'll try to check... EDIT again: It works in java 1.5 (note you need +, not -, or you turn the option off...)

Answer 7

See http://java.sun.com/javase/6/docs/technotes/guides/vm/server-class.html for how the launcher selects between client and server VM, and what is supported on the different processors and OSes.

Answer 8

The best way to verify if the JIT compiler is the reason for the speedup in later iterations is to run the benchmark with the JIT compiler turned off. To do this, specify the system property java.compiler=NONE (the word "none" must be in upper case).

Time spent doing class loading can also cause the benchmarked code to run slower the first time. Finally, there is a nondeterministic delay between calling Thread.start() and the Thread's run() method being called.

You might want to consider finding a benchmark framework. A good framework will "warm up" the code by running several iterations, then do multiple timings with a different number of iterations. See Java theory and practice: Anatomy of a flawed microbenchmark.

Answer 9

I believe you can also use the non-standard option for the java command of -Xint to disable HotSpot and have your code interpreted only. This could at least take HotSpot out of the equation for interpreting your timing.

Answer 10

Some ugly, unrealistic code (the stuff of microbenchmarks):

                while (counter < 10000000) {
                        // work
                        for (int j = 0; j < 100; j++)
                                counter++;
                        counter -= 99;
                }

So what is this doing and how fast should it run.

The inner loop increments counter 100 times, then the counter is decremented by 99. So an increment of 1. Note counter is a member variable of an outer class, so some overhead there. This is then run 10,000,000 times. So the inner loop is run 1,000,000,000 times.

A loop using to accessor methods, call it 25 cycles. 1,000,000,000 times at 1 GHz, gives 25s.

Hey, we predicted the SLOW time. The slow time is fast. The fast times are after the benchmark has been broken in some way - 2.5 cycles an iteration? Use -server and you might find it gets even more silly.