On 3 January 2012 12:12, yohan chandra <
yohan.chandra@xxxxxxxxx> wrote:
> 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 -
>
>