Skip to main content

[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index] [List Home]
Re: [aspectj-users] Mac/Linux LTW mismatch and Autowiring advised classes

Hi Wendel,

Yes I think the default caching model is perloader. 

The fact that increasing the memory removes that Spring error, that is very interesting. I'm not quite sure about the interaction there but it is very interesting :)

For testing out with modified pointcuts, you could, for example just (for a test run) use a simple aspect that weaves one particular method - that will tell us if it LTW in general that is slowing things down or if it seems to be the specific aspects you are using. Or you could tighten up your aspect to maybe targeting just one class that you want to instrument - how does that perform, is it ok? then gradually loosen the constraints (switching to wildcards in your pointcuts) and see at what point the performance issue hits.

What do you mean by code style?  
There are two ways to write an aspect, annotation style or code style

Annotation style:

@Aspect
public class C {
  @Before("execution(* *(..))")
  public void advice() {
    ...
  }
}

or code style

public aspect C {
  before(): execution(* *(..)) {
    ..
  }
}

Code style has had many more years of hardening than annotations style and does enable the compiler/weaver to do smarter checking/optimizations in some areas.  But if the memory changes are getting you beyond the closure issue, you don't need to try this. Code style aspects need to be built with the ajc compiler whereas annotation style can be built with javac.

cheers,
Andy



On 30 October 2013 15:10, Wendel Schultz <wendel.schultz@xxxxxxxxx> wrote:

Re: the forum, I have noticed actually that many people just hang around on stackoverflow these days. People seem to like to score points by answering questions on there so it can be a great place to get answers.
Yeah.
 

I had a look at what you sent me. Your pointcuts look fine. As you note it is the pure method ones that check for an annotation that are going to be the slowest. aop.xml file looks good too.
Thank you for taking the time to look at it!

 
First, switch it on:

aj.weaving.cache.enabled=true
Check. 
Second, choose an implementation:
aj.weaving.cache.impl=perloader
or
aj.weaving.cache.impl=shared
What is the default behavior?  I suspect it is perloader
The 'shared' option is faster but only works if all your classloaders that are using aspects are using the exact same aspects (This may be the case for you, so try it).
Shared does make sense and I'm trying that out.
 

Other thoughts about speed: is the JVM tight on memory? There are some strategies employed in the weaver that involve throwing things away and recovering them again if needed (via weak/soft references). If a JVM is tight on memory this can slow things down, even though weaving is working.
I think this is accounting for some of what is going on wrt initial load; I need to follow this lead a bit.  However, more curiously, the exceptions noted in my Spring AOP forum thread go away when I give it more memory; bumping from a couple hundred MBs to 1 GB "fixed" this.  I'm not completely convinced, but I now have new leads to suss out more info.
 

Have you tried using the weaver (via -javaagent) but not actually passing in the aspect via aop.xml - is it still slow? Have you adding/removing/adjusting some of the pointcuts to see if that has an impact - maybe there is one that is really hurting things. I wonder if there are some very critical joinpoints being hit that are a bottleneck for everything.
I don't know that I know how to accomplish what you're describing.  I find that when I don't specify aop.xml then the app doesn't weave. 
 
 One observation on your code, your pointcut 'metricAverseMethod()' is checking for types that have '@MetricAware' on them, is that right?
No.  You have shamed me.  And I thank you.
 

You could try a code style aspect. Using code style the compiler does some extra things and may even do more advice inlining to reduce the number of closures created (which actually might get you beyond the compile time weaving problem you were seeing...)
What do you mean by code style?  

Do you mean CTW?  I had to back away from CTW, so if I can see this work for me I may very well revisit.
 

I usually take a yourkit profile as the next stage (or try your jvm profiling tool of choice). 
Hopefully it won't come to this.  I'll let you know.
 

cheers,
Andy
Thanks for your help thus far.
 






On 30 October 2013 08:44, Wendel Schultz <wendel.schultz@xxxxxxxxx> wrote:


I'd be building 1.7.4 if I wasn't answering this post :)
Forum guilt. 

In an act of desperation, I see the same thing with 1.7.4, sadly.
 
I referenced before is an article about using the built in timers to assess whether your pointcuts are taking a long time to match.

In the spring forum thread, I mention what I'm doing.  One thing is looking for method annotations (@Timed, @MetricAware) defined as a @Pointcut("execution(@com.whatever.MetricAware)"), etc.  

This is the timing information I get when I configure my weaver with -timers (grepped for brevity):
[TomcatInstrumentableClassLoader@7543073a] info Pointcut fast matching cost (total=3ms for 250 fast match calls):
[TomcatInstrumentableClassLoader@7543073a] info Pointcut fast matching cost (total=7ms for 500 fast match calls):
[TomcatInstrumentableClassLoader@7543073a] info Pointcut fast matching cost (total=11ms for 750 fast match calls):
[TomcatInstrumentableClassLoader@7543073a] info Pointcut fast matching cost (total=14ms for 1000 fast match calls):
[TomcatInstrumentableClassLoader@7543073a] info Pointcut fast matching cost (total=16ms for 1250 fast match calls):
[TomcatInstrumentableClassLoader@7543073a] info Pointcut fast matching cost (total=19ms for 1500 fast match calls):
[TomcatInstrumentableClassLoader@7543073a] info Pointcut fast matching cost (total=20ms for 1750 fast match calls):
[TomcatInstrumentableClassLoader@7543073a] info Pointcut fast matching cost (total=22ms for 2000 fast match calls):
[TomcatInstrumentableClassLoader@7543073a] info Pointcut fast matching cost (total=23ms for 2250 fast match calls):
[TomcatInstrumentableClassLoader@7543073a] info Pointcut fast matching cost (total=25ms for 2500 fast match calls):
[TomcatInstrumentableClassLoader@7543073a] info Pointcut fast matching cost (total=26ms for 2750 fast match calls):
[TomcatInstrumentableClassLoader@7543073a] info Pointcut fast matching cost (total=28ms for 3000 fast match calls):
[TomcatInstrumentableClassLoader@7543073a] info Pointcut matching cost (total=311ms for 25000 joinpoint match calls):
[TomcatInstrumentableClassLoader@7543073a] info Pointcut fast matching cost (total=29ms for 3250 fast match calls):
[TomcatInstrumentableClassLoader@7543073a] info Pointcut fast matching cost (total=30ms for 3500 fast match calls):
[TomcatInstrumentableClassLoader@7543073a] info Pointcut fast matching cost (total=31ms for 3750 fast match calls):
[TomcatInstrumentableClassLoader@7543073a] info Pointcut fast matching cost (total=32ms for 4000 fast match calls):
[TomcatInstrumentableClassLoader@7543073a] info Pointcut fast matching cost (total=34ms for 4250 fast match calls):
[TomcatInstrumentableClassLoader@7543073a] info Pointcut fast matching cost (total=37ms for 4500 fast match calls):
[TomcatInstrumentableClassLoader@7543073a] info Pointcut fast matching cost (total=39ms for 4750 fast match calls):
[TomcatInstrumentableClassLoader@7543073a] info Pointcut matching cost (total=399ms for 50000 joinpoint match calls):
[TomcatInstrumentableClassLoader@7543073a] info Pointcut fast matching cost (total=42ms for 5000 fast match calls):
[TomcatInstrumentableClassLoader@7543073a] info Pointcut fast matching cost (total=44ms for 5250 fast match calls):
[TomcatInstrumentableClassLoader@7543073a] info Pointcut fast matching cost (total=46ms for 5500 fast match calls):
[TomcatInstrumentableClassLoader@7543073a] info Pointcut fast matching cost (total=49ms for 5750 fast match calls):
[TomcatInstrumentableClassLoader@7543073a] info Pointcut fast matching cost (total=51ms for 6000 fast match calls):

 This indicates 2-3 seconds spent matching, where only 710ms is spent in second-phase matching.  Where would the other 2 minutes go?  Is there other debug/profiling/timing info I can enable somehow?


Basically you need to try and ensure there is a fast matching component to your point cut so a quick decision is possible on things that definitely can't match. If you want to email me your pointcuts privately I am happy to take a look over them.  
Most of the time there is a fast-matching component, though even as-is, it doesn't seem too unreasonable.  Also, my aop.xml restricts the classes to within my package namespace, adding an additional within.  Is it possible that my aspect is completely horrible and hard to weave (it is a single @Around)?  I have sent it to you as well as my aop.xml.


Did you post on the spring forum about your closure being treated as a bean issue?
 

There are different degrees of caching. I accepted a contribution a while back from someone about a cache that worked well if all your class loaders are using the same aspects.  Some use cases utilize different aspects at different levels in the class loader hierarchy, those can utilize caching but it doesn't work as efficiently as the simple case. If all the class loaders in a system are using the same aspects you know that whichever person loads a type, it will be woven exactly the same - this means if class loader loads a type T and weaves it, any other class loader that subsequently loads T can used the cached version.  This shared fast cache is discussed here:
As I read it, I use the -usefullltw option on my weaver?  Or is this a JVM argument?


Thanks for the continued help as I try to get to the bottom of this.




cheers,
Andy


On 23 October 2013 13:27, Wendel Schultz <wendel.schultz@xxxxxxxxx> wrote:
I'm glad you responded because I wasn't sure how to comment on my thread a day or so after I sent it.

>>  I see the classes get woven at startup, but then at runtime the aspect isn't executing.
I was able to get through this.  Classic ID 10 T.  Apologies.  "This isn't the user thread you're looking for ..."

Do you by any chance have JMX turned on for the linux case? 
Yes.  Can you comment more on the JMX issues in 1.7.3?  Any thoughts on when 1.7.4 will be released?

If you have a proliferation of classloaders, each will get a weaver.
Good to know.  I am doing a pretty standard Tomcat deployment with a single Server and Context, which context I prime to use the Spring Tomcat instrumentable classloader.  This is the only classloader I see weaving classes via aspectj -debug statements.

 If, with verbose on, you are seeing lots of jsp loaders getting weavers, we can address that.
I don't see any JSP classloaders; only the single Tomcat instrumentable classloader is weaving.

I referenced before is an article about using the built in timers to assess whether your pointcuts are taking a long time to match.
I don't think I'm finding what you're referencing.  Can I trouble you to walk me through this (or more directly reference the article which will)?

I fear that either my pointcuts take forever to process, or the sheer size/number of classes will prevent me from shaving much of the two minutes off, and I'll be at the mercy of the Spring shenanigans.  Would it help to include my aspect and aop.xml?


So, beyond all that,  I've been focusing on getting LTW to work.  And it does.  But I'm experiencing frustration.  

I set aj.weaving.cache.enabled=true and I provide a aj.weaving.cache.dir and things are "working."  The first time.  Subsequent startups give me similar errors not finding the <class>.AjcClosure[n] wiring exceptions I saw when I tried to do compile-time weaving.  This leads me to think even more that this is a Spring issue.  I have a hard time thinking that something this straightforward hasn't been accounted for; I'm really hoping I've missed something obvious and we can all make jokes at my expense.  I'm badgering them too.




On Tue, Oct 22, 2013 at 11:23 AM, Andy Clement <andrew.clement@xxxxxxxxx> wrote:
Hi Wendel,

So sorry I'm slow to reply here.

 I see the classes get woven at startup, but then at runtime the aspect isn't executing.

So the showweaveinfo and 'after' dumped bytecode is showing the weaving is happening but the aspects aren't running? I've not seen that before as usually if the weaving happens, the aspects run. If they don't I'd be expecting some kind of classnotfoundexception as the woven code cannot access the aspect class.  Are you using something like my notes in http://andrewclement.blogspot.ca/2009/02/load-time-weaving-basics.html to debug the load time weaving?  Do you by any chance have JMX turned on for the linux case? I'm aware of a bug in 1.7.3 related to turning on JMX that can adversely affect weaving. (Fixed in 1.7.4 snapshots)

 LTW adds over 2 minutes to startup

Can be many reasons for this. If you have a proliferation of classloaders, each will get a weaver. There are techniques for avoiding certain classloaders (e.g. jsp loaders) that you *know* are loading classes that should never be woven. We can also tweak the pointcuts sometimes to speed up matching (and reduce load time weaving time) - on that blog I referenced before is an article about using the built in timers to assess whether your pointcuts are taking a long time to match.  If, with verbose on, you are seeing lots of jsp loaders getting weavers, we can address that.

org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'vendorKeyController.AjcClosure9' defined in URL [jar:file:/export/home/infusionsoft/crm-29-sandbox2/

This gets into an area I don't know so well. I don't know why Spring would be trying to treat a generated closure as a bean.  This forum should be a good place for that question:


  • How can I get my LTW to work, even if it is slow (presumably I can use the caching feature to only pay that price once?)
There is nothing special in AspectJ that should cause it to behave differently on different OSs.  Are you using the same JDK (and fixpack level of that JDK) on each OS?
  • How can I get compile-time parity with bytecode generated by LTW?
  • Is there another way to dodge the issue in bold above having ajc-ed?
I would ask on the forum I referenced about that closure being treated as a bean.

cheers,
Andy




On 17 October 2013 10:15, Wendel Schultz <wendel.schultz@xxxxxxxxx> wrote:

If this isn't the appropriate forum, feel free to direct me where I should go.

I have an aspect which measures metrics for annotated classes and methods of a Spring project.  I am looking to measure public @Controller @RequestMapping methods, public @Repository methods and public methods on one of our annotations specifically created to capture measurements.  This is a pretty obvious aspectj use.

I have done a lot of flailing so please be gentle.

I do this as a single @Around advice using @Pointcut("within(@com.spring.Repository) && execution(public * *.*(..))")and so on for each annotation's pointcut definition, ultimately used by my @Around("(repositoryClassPublicMethod() || controllerClassRequestMappingMethod() || metricAwareClassPublicMethod()) && !autowiredMethod())").  I throw in not autowired to trim the fat a little bit.

This is an enormous legacy app we need to chop up, but as-is it has thousands of objects in the Spring context when it loads up.

I am able to compile the @Aspect, compile and war up my project to use Spring's TomcatInstrumentableClassLoader, then instrument the JVM to use Spring's instrumentation javaagent pointing to my aop.xml for load-time weaving support.  It comes alive and I want to buy everybody a round of drinks.  Kind of.

I say kind of because this works on my Mac (10.8), then when I apply the patch and try on my buddy's Ubuntu box, I see the classes get woven at startup, but then at runtime the aspect isn't executing.  Again, the same patch applied on my Mac behaves differently.  We deploy to linux, so I'm at a standstill.  

Even if this worked on his Ubuntu box, LTW adds over 2 minutes to startup (even if I don't showWeaveInfo and don't dump the before/after classes).  I need to do better.

So I looked into compile-time weaving to solve both of these issues (not executing my aspect as well as load times).  I configured our application to use aspectj compile weaver, but then I see the following exceptions:
org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'vendorKeyController.AjcClosure9' defined in URL [jar:file:/export/home/infusionsoft/crm-29-sandbox2/
infusionsoft-dist/target/camp/webapp/WEB-INF/lib/com.infusion.crm-api.jar!/com/infusionsoft/api/authentication/controller/VendorKeyController$AjcClosure9.class]: Instantiation of bean fail
ed; nested exception is org.springframework.beans.BeanInstantiationException: Could not instantiate bean class [com.infusionsoft.api.authentication.controller.VendorKeyController$AjcClosur
e9]: No default constructor found; nested exception is java.lang.NoSuchMethodException: com.infusionsoft.api.authentication.controller.VendorKeyController$AjcClosure9.<init>()

I use the aspectj-maven-plugin (from codehaus, not the maven-aspectj-plugin from apache).

From what I've been able to gather, closures are created when aspectj's compiler can't inline the advice.  OK, that's fine I guess.  This leaves me with a few questions:
  • How can I get my LTW to work, even if it is slow (presumably I can use the caching feature to only pay that price once?)
  • How can I get compile-time parity with bytecode generated by LTW?
  • Is there another way to dodge the issue in bold above having ajc-ed?
  • What bad assumptions am I making?
  • I want to build a Spring context.  I don't really care how that happens.  Other ideas?

I'm not interested in fighting Spring AOP.  It has its own gotchas and we already use it in some situations which lead to a multiple inheritance problem for some of the classes I'd be looking to aspect.  I'd like to find the end of this path I'm on.

Thanks SO much in advance,
-w

_______________________________________________
aspectj-users mailing list
aspectj-users@xxxxxxxxxxx
https://dev.eclipse.org/mailman/listinfo/aspectj-users



_______________________________________________
aspectj-users mailing list
aspectj-users@xxxxxxxxxxx
https://dev.eclipse.org/mailman/listinfo/aspectj-users



_______________________________________________
aspectj-users mailing list
aspectj-users@xxxxxxxxxxx
https://dev.eclipse.org/mailman/listinfo/aspectj-users



_______________________________________________
aspectj-users mailing list
aspectj-users@xxxxxxxxxxx
https://dev.eclipse.org/mailman/listinfo/aspectj-users



_______________________________________________
aspectj-users mailing list
aspectj-users@xxxxxxxxxxx
https://dev.eclipse.org/mailman/listinfo/aspectj-users



_______________________________________________
aspectj-users mailing list
aspectj-users@xxxxxxxxxxx
https://dev.eclipse.org/mailman/listinfo/aspectj-users



_______________________________________________
aspectj-users mailing list
aspectj-users@xxxxxxxxxxx
https://dev.eclipse.org/mailman/listinfo/aspectj-users



Back to the top