Re: [aspectj-users] aspectj and jsp load

[yohan chandra <yohan.chandra@xxxxxxxxx>]

Hi,

Are you confident your pointcuts aren't doing unnecessary matching, as
that will also hurt startup time.  Are they all using within() clauses
to guard the set of types against which they will apply?  You might
want to use the timers support to see if the pointcuts are spending a
lot of time matching:
http://andrewclement.blogspot.com/2009/a11/aspectj-profiling-pointcut-matching.html

for within() clauses, I use include within options from aop.xml and only include necessary classes, for example:
        <include within="com.services.factory.account.AccountDbServicesCareImpl"/>
        <include within="com.services.factory.mobile.MobileDbServicesCareImpl"/>        
        <include within="com.services.factory.resetpassword.CommonResetPasswordServicesImpl"/>
        <include within="com.services.tlg.utils.AddContractUtil"/>
        <include within="com.servlets.SalesPortalServlet"/>
        <include within="com.utils.CareComLogon"/>
        <include within="com.utils.CareLogonUtil"/>
        <include within="com.utils.CSSUtil"/>
        . . . .

I have enabled the -timers option and below are from the logs:
Line 4199: [ChangeAwareClassLoader@1e50bd5] info Pointcut fast matching cost (total=101ms for 3000 fast match calls):
Line 4226: [ChangeAwareClassLoader@1e50bd5] info Pointcut matching cost (total=7805ms for 50000 joinpoint match calls):

I checked the time logs, most of them are about 0-2ms, several 200ish ms, only two are outstanding (>1000ms):
fast matching:
Line 4200: [ChangeAwareClassLoader@1e50bd5] info Time:31ms (types:#428) fast matching against ((((execution(* *(..)) && this(BindingTypePattern(java.lang.Object, 0))) &&   @annotation(org.springframework.transaction.annotation.Transactional)) && persingleton(org.springframework.transaction.aspectj.AnnotationTransactionAspect)) || (((execution(public * (@org.springframework.transaction.annotation.Transactional *).*(..)) && this(BindingTypePattern(java.lang.Object, 0))) && @this(org.springframework.transaction.annotation.Transactional)) && persingleton(org.springframework.transaction.aspectj.AnnotationTransactionAspect)))    
Line 4205: [ChangeAwareClassLoader@1e50bd5] info Time:1ms (types:#108) fast matching against (((call(* com.cv.webservices.client.GenerateOOWQuestionsAnswers_Impl.*(..)) && if()) && persingleton(com.aspect.CustomerVerifyAdvice)) || ((call(* com.cv.webservices.client.GenerateOOWQuestionsAnswersPortType.*(..)) && if()) && persingleton(com.aspect.CustomerVerifyAdvice)))

matching:
Line 4227: [ChangeAwareClassLoader@1e50bd5] info Time:1745ms (jps:#4104) matching against ((((execution(* *(..)) && this(BindingTypePattern(java.lang.Object, 0))) && @annotation(org.springframework.transaction.annotation.Transactional)) && persingleton(org.springframework.transaction.aspectj.AnnotationTransactionAspect)) || (((execution(public * (@org.springframework.transaction.annotation.Transactional *).*(..)) && this(BindingTypePattern(java.lang.Object, 0))) && @this(org.springframework.transaction.annotation.Transactional)) && persingleton(org.springframework.transaction.aspectj.AnnotationTransactionAspect)))    
Line 4233: [ChangeAwareClassLoader@1e50bd5] info Time:4174ms (jps:#8095) matching against (((call(* com.cv.webservices.client.GenerateOOWQuestionsAnswers_Impl.*(..)) && if()) && persingleton(com.aspect.CustomerVerifyAdvice)) || ((call(* com.cv.webservices.client.GenerateOOWQuestionsAnswersPortType.*(..)) && if()) && persingleton(com.aspect.CustomerVerifyAdvice)))
    
However I don't think the matching time is the issue because our application does not weave anything to the jsp classes (jsp is not even included in our aop.xml), I checked the log all this weaving time info is from changeAwareClassLoader only, nothing from the jspClassLoader.

I observed the log, when the jsp is loaded, changeAwareClassLoader is not printing any log, the only related aspectj logs are registration of jspclassloaders and the aspects.

I took the log for a page in our application and found out 8 jsp classloaders were registered and each registration took about ~1-2s (the log was moving slowly and after 1-2s another jsp class loader registration started and took about the same time)
...
[JspClassLoader@14e2e89] info AspectJ Weaver Version 1.6.9 built on Monday Jul 5, 2010 at 15:28:35 GMT
[JspClassLoader@14e2e89] info register classloader weblogic.servlet.jsp.JspClassLoader@14e2e89
. . .
[JspClassLoader@1b150] info AspectJ Weaver Version 1.6.9 built on Monday Jul 5, 2010 at 15:28:35 GMT
[JspClassLoader@1b150] info register classloader weblogic.servlet.jsp.JspClassLoader@1b150
. . .
[JspClassLoader@1201afd] info AspectJ Weaver Version 1.6.9 built on Monday Jul 5, 2010 at 15:28:35 GMT
[JspClassLoader@1201afd] info register classloader weblogic.servlet.jsp.JspClassLoader@1201afd
. . .
[JspClassLoader@c0cd51] info AspectJ Weaver Version 1.6.9 built on Monday Jul 5, 2010 at 15:28:35 GMT
[JspClassLoader@c0cd51] info register classloader weblogic.servlet.jsp.JspClassLoader@c0cd51
. . .
[JspClassLoader@146b6a1] info AspectJ Weaver Version 1.6.9 built on Monday Jul 5, 2010 at 15:28:35 GMT
[JspClassLoader@146b6a1] info register classloader weblogic.servlet.jsp.JspClassLoader@146b6a1
. . .
[JspClassLoader@1b52826] info AspectJ Weaver Version 1.6.9 built on Monday Jul 5, 2010 at 15:28:35 GMT
[JspClassLoader@1b52826] info register classloader weblogic.servlet.jsp.JspClassLoader@1b52826
. . .
[JspClassLoader@1521eab] info AspectJ Weaver Version 1.6.9 built on Monday Jul 5, 2010 at 15:28:35 GMT
[JspClassLoader@1521eab] info register classloader weblogic.servlet.jsp.JspClassLoader@1521eab
. . .
[JspClassLoader@1cdee1f] info AspectJ Weaver Version 1.6.9 built on Monday Jul 5, 2010 at 15:28:35 GMT
[JspClassLoader@1cdee1f] info register classloader weblogic.servlet.jsp.JspClassLoader@1cdee1f


Regards,
- yohan chandra -