Reflection much slower than normal

Question

I am currently working on a Java project in which I am trying to learn the ins and outs. In previous projects, I have used Java reflection in order to create a toString() by calling each getter in an object and parsing it to display the value. This method has been a helpful, clean, and dynamic way to display the data.

Below is a heavily simplified version of my code:

private static String objectToString(Object o) {
    LOGGER.debug("entering ObjectStringUtils::objectToString()");


    ....

    Class<?> oClass = o.getClass();
    String className = oClass.getName();
    Method[] methods = oClass.getMethods();

    for (Method m : methods) {
         if ([method is a getter]) {
               String methodName;
               Object value;
               try {
                   methodName= m.getName();
                   LOGGER.debug("Invoking " + className + "::" + methodName);
                   Object value = m.invoke(o);
                   LOGGER.debug("Invoked " + className + "::" + methodName);
               } catch (Exception e) {
                   e.printStackTrace();
                   value = null;
               }

               LOGGER.debug(methodName+ " -> " + value);
         }
    }
}

This produces logger output which looks like this:

14:47:49,478 [] DEBUG ObjectStringUtils:? - Invoking org.hibernate.impl.SessionImpl::isOpen
14:47:49,613 [] DEBUG ObjectStringUtils:? - Invoked org.hibernate.impl.SessionImpl::isOpen
14:47:49,613 [] DEBUG ObjectStringUtils:? - isOpen -> true

Notice that it took Java 139 milliseconds to call the function. It takes this long to perform the reflection in any method in any class, even if the method is only a standard getter which performs no logic other than to return a value. This means that it takes far too long to perform the operation when there are multiple nested values involved. When I used reflection previously on WebSphere 7, it took a tiny fraction of this long to perform the operation.

So my question is: why is it taking so long to process? I understand that reflection is slower, but it shouldn't be on the magnitude of 140 milliseconds to call a getter. Is this an artifact of the way it takes WebLogic a long time to call a function, or the fact that line numbers appear to be stripped from the .class files? So far, I don't have any idea.

Answer 1

When Methods are cached - e.g. used in a framework and oClass.getMethods() is called only once, reflective call to a method is only ~2-3 slower than a direct method call. I think that oClass.getMethods() must be the slowest part in your reflection, not the method invocation.

So may be it's SessionImpl::isOpen which is slow by itself? I.e. it checks if it's still connected, or does any slow interaction with the database? 139 ms is very slow even for a DB transaction, so this also could happen because of some errors occuring during this call.

Answer 2

When you benchmark a piece of code, you must time the same operation several times, otherwise the test is meaningless - it could have been caused by garbage collection or by another process running on the same computer.