Announcement Announcement Module
Collapse
No announcement yet.
Issues with DefaultAdvisorAutoProxyCreator ... Page Title Module
Move Remove Collapse
X
Conversation Detail Module
Collapse
  • Filter
  • Time
  • Show
Clear All
new posts

  • Issues with DefaultAdvisorAutoProxyCreator ...

    Hi !
    Here is my problem, i'm using a DefaultAdvisorAutoProxyCreator and an RegexpMethodPointcutAdvisor to monitor the performance of all the methods of all classes in one of my package.
    It's kinda working ... But i got twice the log of my advice class. The trouble is it seems that all method are now called twice since i proxified the classes ... So when a method which persist data is called , i got a unique constraint violation, seems it wants to insert twice object with same id, etc, etc ...
    By the way, i'm using struts/spring/hibernate ... and my spring version is 1.2.
    I'm also using a TransactionManager (org.springframework.transaction.interceptor.Trans actionProxyFactoryBean), i doubt there can be a conflict between both ...
    When i unplug the proxy, i got everything working fine ... But, i do need to monitor execution time ! and i want to do it also on classes that manipulate database.

    Here is the my appContext file :
    Code:
    <bean id="aop.performanceInterceptor" class="com.test.core.aop.PerformanceInterceptor">
    		<constructor-arg><value>300</value></constructor-arg>
    	</bean>
    
    
    	<bean id="advisor" class="org.springframework.aop.support.RegexpMethodPointcutAdvisor">
    		<property name="advice"><ref bean="aop.performanceInterceptor"/></property>
    		<property name="patterns">
    		<list>
    		<value>^com\.test\.core\.dao\..*</value>
    		</list>
    		</property>
    	</bean>
    	
       <bean id="autoProxyCreator" class="org.springframework.aop.framework.autoproxy.DefaultAdvisorAutoProxyCreator" />
    here is the invoke method of my class that monitors time :
    Code:
    	public final Object invoke(final MethodInvocation methodInvocation)
    		throws Throwable {
    		StopWatch sw = new StopWatch();
    		sw.start();
    		Object o = methodInvocation.proceed();
    		methodInvocation.proceed();
    		sw.stop();
    		this.logInfo(methodInvocation, sw.getTime());
    
    		return o;
    	}
    And here is the log in the console :

    2007-06-07 18:01:50,519;INFO ;STDOUT;18:01:50,519;http-0.0.0.0-8080-4;WARN;com.test.core.aop.PerformanceInterceptor1;D uree d'execution : 15 ms com.test.core.dao.impl.DaoUtilisateurImpl hasAnyFunction
    2007-06-07 18:01:50,551;INFO ;STDOUT;18:01:50,519;http-0.0.0.0-8080-4;WARN;com.test.core.aop.PerformanceInterceptor1;D uree d'execution : 15 ms com.test.core.dao.impl.DaoUtilisateurImpl hasAnyFunction
    2007-06-07 18:01:50,551;INFO ;STDOUT;18:01:50,551;http-0.0.0.0-8080-4;WARN;com.test.core.aop.PerformanceInterceptor1;D uree d'execution : 0 ms com.test.core.dao.impl.DaoUtilisateurImpl hasAnyFunction
    2007-06-07 18:01:50,551;INFO ;STDOUT;18:01:50,551;http-0.0.0.0-8080-4;WARN;com.test.core.aop.PerformanceInterceptor1;D uree d'execution : 0 ms com.test.core.dao.impl.DaoUtilisateurImpl hasAnyFunction


    Many thanks in advance, and hope you'll understand my english.

    Nick.
    Last edited by MuLdErZ; Jun 8th, 2007, 09:40 AM.

  • #2
    You are calling proceed() twice.
    Code:
    Object o = methodInvocation.proceed();
    methodInvocation.proceed();

    Comment


    • #3
      gosh ! i hope it's a copy paste error of my code in here .... cause if it's really what's in my code .... i'd be really pissed off !!! i've been trying everything .... i'll check on monday.

      Anyway thanks, sometimes it's when it's the most obivous that you don't see anything ....

      Comment


      • #4
        Originally posted by MuLdErZ View Post
        gosh ! i hope it's a copy paste error of my code in here .... cause if it's really what's in my code .... i'd be really pissed off !!! i've been trying everything .... i'll check on monday.
        , if it fixes it great. Let me know how you get on!

        Originally posted by MuLdErZ View Post
        Anyway thanks, sometimes it's when it's the most obivous that you don't see anything ....
        Indeed, they are usually the hardest to spot.

        Comment


        • #5
          Wasn't that ....

          It was a copy paste error of my code ... i do not have the double call of the method .proceed() .... I'd have prefered to have it, it would have explain everything ... So any idea why all intercepted method are called twice ???

          EDIT :

          I made a Junit Test to test just the basic .... Here is what i got :

          14:30:02,214;main;INFO;com.core.aop.PerformanceInt erceptor1;Duree d'execution : 1000 ms com.core.test.aop.PerformanceInterceptorTesterServ iceImpl passTime
          14:30:02,214;main;INFO;com.core.aop.PerformanceInt erceptor1;Duree d'execution : 1000 ms com.core.test.aop.PerformanceInterceptorTesterServ iceImpl passTime
          14:30:02,230;main;INFO;com.core.aop.PerformanceInt erceptor1;Duree d'execution : 16 ms com.core.test.aop.PerformanceInterceptorTesterServ iceImpl passTime
          14:30:02,230;main;INFO;com.core.aop.PerformanceInt erceptor1;Duree d'execution : 16 ms com.core.test.aop.PerformanceInterceptorTesterServ iceImpl passTime


          and here is the code of my test :

          PerformanceInterceptorTesterService service = (PerformanceInterceptorTesterService) spring.getBean("aop.performance.logger.test");
          service.passTime(1000);
          service.passTime(10);

          so just two calls ... i get 4 lines of log ...
          Last edited by MuLdErZ; Jun 11th, 2007, 08:53 AM.

          Comment


          • #6
            Try to see whether any other interceptor is matching joinpoint(regular exp in this case).

            Comment


            • #7
              It can be a problem in log4j setup also..

              Comment


              • #8
                I think the problem in your test comes from usage of two proxying mechanisms: TransactionProxyFactoryBean and DefaultAdvisorAutoProxyCreator. Auto-proxying is applied to all beans.
                In this way you can end up having double proxying on your classes: in this particular case I think a proxy is created for your dao using logging advisor then another proxy is created which adds transactional behavior and is possible (I'm not sure here) that auto-proxying being applied on your already transactional bean instance.

                I recommend using a single point for proxy creation.
                For example, you can use auto-proxying for transactional behavior also, using TransactionAttributeSourceAdvisor , TransactionInterceptor and an implementation of TransactionAttributeSource .

                Comment


                • #9
                  Are other log outputs also doubled? Perhaps it is a configuration issue of your logger.

                  Regards,
                  Andreas

                  Comment

                  Working...
                  X