Performance Differences + Around advice

[RameshMandaleeka]

I am trying an example to understand around advice. I have written to classes Test and Main there is a lot of variation in execution times. Can any one tell me if I am missing anything. Why the performance differences happening.

// the business interface
package com.jteam.springdemos.aspects.around;

public interface Worker {
    void doSomeWork(int numOfTimes);
}

The implementation class

package com.jteam.springdemos.aspects.around;

public class WorkerBean implements Worker {

    public void doSomeWork(int numOfTimes) {
        for &#40;int i = 0; i < numOfTimes; i++&#41; &#123;
            System.out.print&#40;""&#41;;
        &#125;
    &#125;
&#125;

The around advice

package com.jteam.springdemos.aspects.around;

import java.lang.reflect.Method;

import org.aopalliance.intercept.MethodInterceptor;
import org.aopalliance.intercept.MethodInvocation;
import org.springframework.util.StopWatch;

public class AroundAdvice implements MethodInterceptor {

    public Object invoke(MethodInvocation invocation) throws Throwable {

        StopWatch sw = new StopWatch();
        sw.start(invocation.getMethod().getName());
        // invoking...
        Object returnValue = invocation.proceed();

        // stopping watch after invocation
        sw.stop();


        Method m = invocation.getMethod();
        Object target = invocation.getThis();
        Object[] args = invocation.getArguments();
        System.out.println("Executed method: " + m.getName());
        System.out.println("On object of type: " + target.getClass().getName());
        System.out.println("With arguments:");
        for (Object arg : args) {
            System.out.println("---->" + arg);
        }
        System.out.println();
        System.out.println("TOOK: " + sw.getTotalTimeMillis() + "ms!");

        return returnValue;
    }
}

The beand definitions

<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE beans PUBLIC  "-//SPRING//DTD BEAN//EN" "http&#58;//www.springframework.org/dtd/spring-beans.dtd">
<beans>

    <!-- Bean configuration -->
    <bean id="businesslogicbean" class="org.springframework.aop.framework.ProxyFactoryBean">
         <property name="proxyTargetClass"><value>true</value></property>
        <property name="singleton">
            <value>false</value>
        </property>
        <property name="exposeProxy">
            <value>true</value>
        </property>
        <property name="proxyInterfaces">
            <value>com.jteam.springdemos.aspects.around.Worker</value>
        </property>
        <property name="target">
            <ref local="beanTarget"/>
        </property>
        <property name="interceptorNames">
            <list>
                <value>theAroundAdvisor</value>
            </list>
        </property>
    </bean>
    <!-- Bean Classes -->
    <bean id="beanTarget" class="com.jteam.springdemos.aspects.around.WorkerBean"/>

    <!-- Advisor pointcut definition for around advice -->
    <bean id="theAroundAdvisor" class="org.springframework.aop.support.RegexpMethodPointcutAdvisor">
        <property name="advice">
            <ref local="theAroundAdvice"/>
        </property>
        <property name="pattern">
            <value>.*</value>
        </property>
    </bean>

    <!-- Advice classes -->
    <bean id="theAroundAdvice" class="com.jteam.springdemos.aspects.around.AroundAdvice"/>
</beans>

I have written to test classes as below:

package com.jteam.springdemos.aspects.around;

import org.springframework.aop.framework.ProxyFactory;

public class Test {
    public static void main(String[] args) {
        WorkerBean bean = getWorkerBean();
        bean.doSomeWork(100000000);
    }

    private static WorkerBean getWorkerBean() {
        WorkerBean target = new WorkerBean();
        ProxyFactory pf = new ProxyFactory();
        pf.setTarget(target);
        pf.addAdvice(new AroundAdvice());
        return (WorkerBean) pf.getProxy();
    }
}

and

package com.jteam.springdemos.aspects.around;

import org.springframework.core.io.Resource;
import org.springframework.core.io.ClassPathResource;
import org.springframework.beans.factory.support.AbstractBeanFactory;
import org.springframework.beans.factory.xml.XmlBeanFactory;

public class Main {
    public static void main(String[] args) {

        // Read the configuration file
        Resource res = new ClassPathResource("com/jteam/springdemos/aspects/around/beandef.xml");
        AbstractBeanFactory ft = new XmlBeanFactory(res);

        //Instantiate an object
        Worker testObject = (Worker) ft.getBean("businesslogicbean");

        // Execute the public method of the bean
        testObject.doSomeWork(1000000);
    }
}

What I see is the Test class is giving 11438ms and Main class is giving just 125ms.

Test class log:

Sep 6, 2005 8:00:28 PM org.springframework.aop.framework.DefaultAopProxyF actory <clinit>
INFO: CGLIB2 available: proxyTargetClass feature enabled
Sep 6, 2005 8:00:28 PM org.springframework.core.CollectionFactory <clinit>
INFO: JDK 1.4+ collections available
Executed method: doSomeWork
On object of type: com.jteam.springdemos.aspects.around.WorkerBean
With arguments:
---->100000000

TOOK: 11438ms!

and Main class log

org.springframework.beans.factory.xml.XmlBeanDefin itionReader loadBeanDefinitions
INFO: Loading XML bean definitions from class path resource [com/jteam/springdemos/aspects/around/beandef.xml]
Sep 6, 2005 7:58:49 PM org.springframework.beans.factory.support.Abstract BeanFactory getBean
INFO: Creating shared instance of singleton bean 'businesslogicbean'
Sep 6, 2005 7:58:49 PM org.springframework.aop.framework.DefaultAopProxyF actory <clinit>
INFO: CGLIB2 available: proxyTargetClass feature enabled
Sep 6, 2005 7:58:49 PM org.springframework.core.CollectionFactory <clinit>
INFO: JDK 1.4+ collections available
Sep 6, 2005 7:58:49 PM org.springframework.beans.factory.support.Abstract BeanFactory getBean
INFO: Creating shared instance of singleton bean 'beanTarget'
Sep 6, 2005 7:58:50 PM org.springframework.beans.factory.support.Abstract BeanFactory getBean
INFO: Creating shared instance of singleton bean 'theAroundAdvisor'
Sep 6, 2005 7:58:50 PM org.springframework.beans.factory.support.Abstract BeanFactory getBean
INFO: Creating shared instance of singleton bean 'theAroundAdvice'
Executed method: doSomeWork
On object of type: com.jteam.springdemos.aspects.around.WorkerBean
With arguments:
---->1000000

TOOK: 125ms!

[Costin Leau]

First remove the System.out.println - they ruin performance because of IO operations.

[Colin Yates]

How long does it take *without* the advice?

[RameshMandaleeka]

With advice it is 125ms and with out 11438ms

Why this much huge difference?

Ramesh

[Costin Leau]

With advice it is 125ms and with out 11438ms

To rephrase what yatesco said, how much does it take if you don't enable the advice? This is important to see if the delay is actually inside the advice or in your code. Have you also removed the System.out?

[RameshMandaleeka]

Hello Costin,

Sorry the test value I entered is not same. For one test 100000000 and another test 1000000. Sorry for taking up your time.

Thanks & Regards
Ramesh

[ErikFK]

Hi,

Sorry the test value I entered is not same. For one test 100000000 and another test 1000000. Sorry for taking up your time.

Now you know why they always say: define constants instead of using hard coded numbers (or strings etc.)

& :wink:

Erik