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?

As for the `System.gc()` part of the question, `System.gc()` doesn't wait for the GC to run, it immediately returns after setting a flag that GC should be run at the nearest opportunity, which happens to be while your method is running. Of course there's precious little to collect and on a multi-core system GC can run in parallel to your code, but in every GC algorithm there are stop-the-world steps. The extra delay is likely to come from this. — biziclop, Jul 09 '15 at 10:11
*Is it practical [...]* - ask yourself this: do a few extra nanoseconds matter if it's only called once? — the8472, Jul 09 '15 at 10:11
@the8472 It exaggerates the lag to about 1 sec in my program. — K ., Jul 09 '15 at 10:15
If that "one second lag" is your actual concern, can you update your question to reflect that problem, how you measured that/how you arrived at the conclusion etc. etc. — the8472, Jul 09 '15 at 10:19
@the8472 actually, regarding that question, I'm just curious about why there is no programmers done that before. — K ., Jul 09 '15 at 10:25
I really don't understand your last question. What do you mean by "run through all methods"? Why would run a method more than once if you only need it once? — Manu, Jul 09 '15 at 10:29
@JerrellFang It is being done, but usually only for [micro-benchmarks](https://wiki.openjdk.java.net/display/HotSpot/MicroBenchmarks). — biziclop, Jul 09 '15 at 10:30

the8472 · Accepted Answer · 2015-07-09T15:25:51.223

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.

I did run the test on my server(CentOS), and it was the same. — K ., Jul 09 '15 at 10:36
I tried JMH and updated the question. If the JMH program has some problems, please tell me — K ., Jul 09 '15 at 14:56

score 0 · Answer 2 · edited May 23 '17 at 12:24

0

This kind of behaviour is often caused by the compiler or RE. It starts to optimize the execution after the first iteration. Additionally class loading can have an effect (I guess this is not the case in your example code as all classes are loaded in the first loop latest).

See this thread for a similar problem.

Please keep in mind this kind of behaviour is often dependent on the environment/OS it's running on.

edited May 23 '17 at 12:24

Community

1
1

answered Jul 09 '15 at 10:52

mad_manny

1,081
16
28

JIT does not start after the first iteration. Generally a method must have been executed several hundred times before the compiler kicks in. Try running the test case with JIT disabled (`-Xint`) and you'll observe the same results. – apangin Jul 09 '15 at 11:54

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

2 Answers2