Java Reflection Performance Issue

I know there's a lot of topics talking about Reflection performance.

Even official Java docs says that Reflection is slower, but I have this code:

  public class ReflectionTest {
   public static void main(String[] args) throws Exception {
       Object object = new Object();
       Class<Object> c = Object.class;

       int loops = 100000;

       long start = System.currentTimeMillis();
       Object s;
       for (int i = 0; i < loops; i++) {
           s = object.toString();
           System.out.println(s);
       }
       long regularCalls = System.currentTimeMillis() - start;
       java.lang.reflect.Method method = c.getMethod("toString");

       start = System.currentTimeMillis();
       for (int i = 0; i < loops; i++) {
           s = method.invoke(object);
           System.out.println(s);
       }

       long reflectiveCalls = System.currentTimeMillis() - start;

       start = System.currentTimeMillis();
       for (int i = 0; i < loops; i++) {
           method = c.getMethod("toString");
           s = method.invoke(object);
           System.out.println(s);
       }

       long reflectiveLookup = System.currentTimeMillis() - start;

       System.out.println(loops + " regular method calls:" + regularCalls
               + " milliseconds.");

       System.out.println(loops + " reflective method calls without lookup:"
               + reflectiveCalls+ " milliseconds.");

       System.out.println(loops + " reflective method calls with lookup:"
               + reflectiveLookup + " milliseconds.");

   }

}

That I don't think is a valid benchmark, but at least should show some difference. I executed it waiting to see the reflection normal calls being a bit slower than regular ones.

But this prints this:

100000 regular method calls:1129 milliseconds.
100000 reflective method calls without lookup:910 milliseconds.
100000 reflective method calls with lookup:994 milliseconds.

Just for note, first I executed it without that bunch of sysouts, and then I realized that some JVM optimization are just making it goes faster, so I added these printls to see if reflection was still faster.

The result without sysouts are:

100000 regular method calls:68 milliseconds.
100000 reflective metho开发者_如何学运维d calls without lookup:48 milliseconds.
100000 reflective method calls with lookup:168 milliseconds.

I saw over internet that the same test executed on old JVMs make the reflective without lookup are two times slower than regular calls, and that speed falls over new updates. If anyone can execute it and say me I'm wrong, or at least show me if there's something different than the past that make it faster.

Following instructions, I ran every loop separated and the result are (without sysouts)

100000 regular method calls:70 milliseconds.
100000 reflective method calls without lookup:120 milliseconds.
100000 reflective method calls with lookup:129 milliseconds.

Never performance test different bits of code in the same "run". The JVM has various optimisations that mean it though the end result is the same, how the internals are performed may differ. In more concrete terms, during your test the JVM may have noticed you are calling Object.toString a lot and have started to inline the method calls to Object.toString. It may have started to perform loop unfolding. Or there could have been a garbage collection in the first loop but not the second or third loops.

To get a more meaningful, but still not totally accurate picture you should separate your test into three separate programs.

The results on my computer (with no printing and 1,000,000 runs each)

All three loops run in same program

1000000 regular method calls: 490 milliseconds.

1000000 reflective method calls without lookup: 393 milliseconds.

1000000 reflective method calls with loopup: 978 milliseconds.

Loops run in separate programs

1000000 regular method calls: 475 milliseconds.

1000000 reflective method calls without lookup: 555 milliseconds.

1000000 reflective method calls with loopup: 1160 milliseconds.

There's an article by Brian Goetz on microbenchmarks that's worth reading. It looks like you're not doing anything to warm up the JVM (meaning give it a chance to do whatever inlining or other optimizations it's going to do) before doing your measurements, so it's likely the non-reflective test is still not warmed-up yet, and that could skew your numbers.

When you have multiple long running loops, the first loop can trigger the method to compile resulting in the later loops being optimised from the start. However the optimisation can be sub-optimal as it has no runtime information for those loops. The toString is relatively expensive and couple be taking longer than the reflections calls.

You don't need separate programs to avoid loop being optimised due to an earlier loop. You can run them in different methods.

The results I get are

Average regular method calls:2 ns.
Average reflective method calls without lookup:10 ns.
Average reflective method calls with lookup:240 ns.

The code

import java.lang.reflect.Method;

public class ReflectionTest {
    public static void main(String[] args) throws Exception {
        int loops = 1000 * 1000;

        Object object = new Object();
        long start = System.nanoTime();
        Object s;
        testMethodCall(object, loops);
        long regularCalls = System.nanoTime() - start;
        java.lang.reflect.Method method = Object.class.getMethod("getClass");
        method.setAccessible(true);

        start = System.nanoTime();
        testInvoke(object, loops, method);

        long reflectiveCalls = System.nanoTime() - start;

        start = System.nanoTime();
        testGetMethodInvoke(object, loops);

        long reflectiveLookup = System.nanoTime() - start;

        System.out.println("Average regular method calls:"
                + regularCalls / loops + " ns.");

        System.out.println("Average reflective method calls without lookup:"
                + reflectiveCalls / loops + " ns.");

        System.out.println("Average reflective method calls with lookup:"
                + reflectiveLookup / loops + " ns.");

    }

    private static Object testMethodCall(Object object, int loops) {
        Object s = null;
        for (int i = 0; i < loops; i++) {
            s = object.getClass();
        }
        return s;
    }

    private static Object testInvoke(Object object, int loops, Method method) throws Exception {
        Object s = null;
        for (int i = 0; i < loops; i++) {
            s = method.invoke(object);
        }
        return s;
    }

    private static Object testGetMethodInvoke(Object object, int loops) throws Exception {
        Method method;
        Object s = null;
        for (int i = 0; i < loops; i++) {
            method = Object.class.getMethod("getClass");
            s = method.invoke(object);
        }
        return s;
    }
}

Micro-benchmarks like this are never going to be accurate at all - as the VM "warms up" it'll inline bits of code and optimise bits of code as it goes along, so the same thing executed 2 minutes into a program could vastly outperform it right at the start.

In terms of what's happening here, my guess is that the first "normal" method call block warms it up, so the reflective blocks (and indeed all subsequent calls) would be faster. The only overhead added through reflectively calling a method that I can see is looking up the pointer to that method, which is a nanosecond-scale operation anyway and would be easily cached by the JVM. The rest would be on how the VM is warmed up, which it is by the time you reach the reflective calls.

There is no inherent reason why reflective call should be slower than a normal call. JVM can optimize them into the same thing.

Practically, human resources are limited, and they had to optimize normal calls first. As time passes by they can work on optimizing reflective calls; especially when reflection becomes more and more popular.

I have been writing my own micro-benchmark, without loops, and with System.nanoTime():

public static void main(String[] args) throws NoSuchMethodException, IllegalArgumentException, IllegalAccessException, InvocationTargetException
{
  Object obj = new Object();
  Class<Object> objClass = Object.class;
  String s;

  long start = System.nanoTime();
  s = obj.toString();
  long directInvokeEnd = System.nanoTime();
  System.out.println(s);
  long methodLookupStart = System.nanoTime();
  java.lang.reflect.Method method = objClass.getMethod("toString");
  long methodLookupEnd = System.nanoTime();
  s = (String) (method.invoke(obj));
  long reflectInvokeEnd = System.nanoTime();
  System.out.println(s);
  System.out.println(directInvokeEnd - start);
  System.out.println(methodLookupEnd - methodLookupStart);
  System.out.println(reflectInvokeEnd - methodLookupEnd);
}

I have been executing that in Eclipse on my machine a dozen times, and the results vary quite a bit, but here is what I typically get:

• the direct method invocation clocks at 40-50 microseconds
• method lookup clocks at 150-200 microseconds
• reflective invocation with the method variable clocks at 250-310 microseconds.

Now, do not forget the caveats on microbenchmarks described in Nathan's reply - there are certainly a lot of flaws in that micro benchmark - and trust the documentation if they say that reflection is a LOT slower than direct invocation.

It strikes me that you have placed a "System.out.println(s)" call inside your inner benchmark loop. Since performing IO is bound to be slow, it actually "swallows up" your benchmark and the overhead of the invoke becomes negligible.

Try removing the "println()" call and running code like this, I'm sure you'd be surprised by the result (some of the silly calculations are needed to avoid the compiler optimizing away the calls altogether):

public class Experius
{

    public static void main(String[] args) throws Exception
    {
        Experius a = new Experius();
        int count = 10000000;
        int v = 0;

        long tm = System.currentTimeMillis();
        for ( int i = 0; i < count; ++i )
        {
            v = a.something(i + v);
            ++v;
        }
        tm = System.currentTimeMillis() - tm;

        System.out.println("Time: " + tm);


        tm = System.currentTimeMillis();
        Method method = Experius.class.getMethod("something", Integer.TYPE);
        for ( int i = 0; i < count; ++i )
        {
            Object o = method.invoke(a, i + v);
            ++v;
        }
        tm = System.currentTimeMillis() - tm;

        System.out.println("Time: " + tm);
    }

    public int something(int n)
    {
        return n + 5;
    }

}

-- TR

Even if you look up the method in both cases (i.e. before 2nd and 3rd loop), the first lookup takes way less time than the second lookup, which should have been the other way around and less than a regular method call on my machine.

Neverthless, if you use the 2nd loop with method lookup, and System.out.println statement, I get this:

regular call        : 740 ms
look up(2nd loop)   : 640 ms
look up ( 3rd loop) : 800 ms

Without System.out.println statement, I get:

regular call    : 78 ms
look up (2nd)   : 37 ms
look up (3rd )  : 112 ms