Why does the first method call always take the longest?

Question

After reading about similar topics on Stack Overflow, I wrote the following code to get an idea about how consistent System.nanoTime() is.

It simply calls System.nanoTime() before and after a method call to an empty void function, recording the elapsed time in the process. As you can see in the results, however, the first call always take the longest. What is the reason for this?

public class Test {
    public static void main(String[] args) {
        for(int i = 0; i < 10; i++) {
            double start = System.nanoTime();
            foo();
            double end = System.nanoTime();
            double diff = end - start;
            System.out.println("Diff: " + diff);
        }
    }

    public static void foo() {

    }
}

Results:

Diff: 2765.0
Diff: 509.0
Diff: 236.0
Diff: 238.0
Diff: 230.0
Diff: 539.0
Diff: 359.0
Diff: 356.0
Diff: 380.0
Diff: 353.0

Note that I did read this question: Why does first call to java.io.File.createTempFile(String,String,File) take 5 seconds on Citrix?

Also, this link is helpful for future reference, but doesn't necessarily answer my specific question: How do I write a correct micro-benchmark in Java?

In a word: "caches" (on all kinds of layers). As soon as a cache is involved, doing the same thing is much faster the second time around. Also, a 2 microsecond difference is really nothing to get worked up about, and why do you convert `nanoTime` to a floating point number? — Thilo, Feb 11 '17 at 01:33
Is that method really empty? Maybe the JVM figures that out and optimizes it away altogether? Please do two followups: a) measure nanoTime diff without any code or method call in between at all b) put some small calculation in that `foo` method. — Thilo, Feb 11 '17 at 01:38
Microbenchmarking on the JVM is hard, because the [JIT compiler](http://stackoverflow.com/questions/95635/what-does-a-just-in-time-jit-compiler-do) can subtly change how your code works after the code has been running for a while. The proper way to do these would be to use a real benchmarking framework like [jmh](http://openjdk.java.net/projects/code-tools/jmh/) — Mick Mnemonic, Feb 11 '17 at 01:39
it not always that. I recover your experiment and sometimes it is not the first that take longest. my jdk1.8 and os win10. — nail fei, Feb 11 '17 at 02:03
Possible duplicate of [How do I write a correct micro-benchmark in Java?](http://stackoverflow.com/questions/504103/how-do-i-write-a-correct-micro-benchmark-in-java) — the8472, Feb 11 '17 at 12:18
Run the code much longer e.g. `20_000` times and it will inline the method and it will drop the time it takes to call System.nanoTime() — Peter Lawrey, Feb 11 '17 at 13:25

score 3 · Accepted Answer · answered Feb 11 '17 at 15:55

JVM performs Class Resolution (see JVMS 5.4.3) lazily. In your case the symbolic reference to foo in the constant pool is resolved on the first execution of invokestatic bytecode, i.e. on the first invocation of the method. Obviously, it takes more time than just executing an already resolved bytecode.

Why does the first method call always take the longest?

1 Answers1