Java: Why is calling a method for the first time slower?

Question

Recently, I was writing a plugin using Java and found that retrieving an element(using get()) from a HashMap for the first time is very slow. Originally, I wanted to ask a question on that and found this (No answers though). With further experiments, however, I notice that this phenomenon happens on ArrayList and then all the methods.

Here is the code:

public class Test {
    public static void main(String[] args) {
        long startTime, stopTime;

        // Method 1
        System.out.println("Test 1:");
        for (int i = 0; i < 20; ++i) {
            startTime = System.nanoTime();
            testMethod1();
            stopTime = System.nanoTime();
            System.out.println((stopTime - startTime) + "ns");
        }

        // Method 2
        System.out.println("Test 2:");
        for (int i = 0; i < 20; ++i) {
            startTime = System.nanoTime();
            testMethod2();
            stopTime = System.nanoTime();
            System.out.println((stopTime - startTime) + "ns");
        }
    }

    public static void testMethod1() {
        // Do nothing
    }

    public static void testMethod2() {
        // Do nothing
    }
}

Snippet: Test Snippet

The output would be like this:

Test 1:
2485ns
505ns
453ns
603ns
362ns
414ns
424ns
488ns
325ns
426ns
618ns
794ns
389ns
686ns
464ns
375ns
354ns
442ns
404ns
450ns
Test 2:
3248ns
700ns
538ns
531ns
351ns
444ns
321ns
424ns
523ns
488ns
487ns
491ns
551ns
497ns
480ns
465ns
477ns
453ns
727ns
504ns

I ran the code for a few times and the results are about the same. The first call would be even longer(>8000 ns) on my computer(Windows 8.1, Oracle Java 8u25).

Apparently, the first calls is usually slower than the following calls(Some calls may be longer in random cases).

---

Update:

I tried to learn some JMH, and write a test program

Code w/ sample output: Code

I don't know whether it's a proper benchmark(If the program has some problems, tell me), but I found that the first warm-up iterations spend more time(I use two warm-up iterations in case the warm-ups affect the results). And I think that the first warm-up should be the first call and is slower. So this phenomenon exists, if the test is proper.

---

So why does it happen?

Answer 1

You're calling System.nanoTime() inside a loop. Those calls are not free, so in addition to the time taken for an empty method you're actually measuring the time it takes to exit from nanotime call #1 and to enter nanotime call #2.

To make things worse, you're doing that on windows where nanotime performs worse compared to other platforms.

---

Regarding JMH: I don't think it's much help in this situation. It's designed to measure by averaging many iterations, to avoid dead code elimination, account for JIT warmup, avoid ordering dependence, ... and afaik it simply uses nanotime under the hood too.

Its design goals pretty much aim for the opposite of what you're trying to measure.

You are measuring something. But that something might be several cache misses, nanotime call overhead, some JVM internals (class loading? some kind of lazy initialization in the interpreter?), ... probably a combination thereof.

The point is that your measurement can't really be taken at face value. Even if there is a certain cost for calling a method for the first time, the time you're measuring only provides an upper bound for that.