| Re: [aspectj-users] [ajdt-dev] AJDT Performance Issues |
|
Hi Andy, Thanks for taking the time to respond and providing me with very relevant information..
Here are a few responses and follow-up questions ·
We are using 2.2.3 of AJDT in Eclipse 4.3. We’ve left AJDT using the default RT JAR (1.7.3). I did try it on 1.8.1 but there was no obvious
difference. ·
We do not have any cflow pointcuts ·
I wonder if it’s more popular to use aspect with LTW insead of CTW. Perhaps we are approaching this wrong. ·
10404 marker might be about right.. we’re advising all getter and setters in our entities as you say 14 * 700 would get you this and 14
attributes on average in an entity would sound correct. ·
In relation to the markers I’ve attached a file with a few back to back “clean project” calls.. The marker creation times are about 30
sec (299509 à 318863)
o
When profiling and looking at the output I did notice that our project has LOTS of compiler warnings (un-used imports, raw types, type
safety, deprecated API calls etc). Would this be adding an extra overhead to AJDT that JDT manages better?
·
·
You are correct the timings I was providing were compile + weave times… Prior to making our AspectJ project an eclipse FULL compile was
taking roughly 70 seconds.. So it’s now 1.5 times slower?
o
I’m guessing what makes us more conscious of a FULL compile time now is it seems to occur much more frequently now that the builder is
the ajbuilder and we have acpects.. I’m guessing the triggers which I’ve seen in AJDT Trace are affected by the type of pointcuts we have defined. So even though we have Incremental enabled a lot of the time if decides to do a FULL build rather than incremental ·
I have grepped for “org.aspectj.weaver.WeaverState”
and it is only in the 700 classes we except to weaved so I’m guessing the other types are that debug information the compiler added.. Also the advise markers and cross references in Eclipse have always looked pretty correct. ·
I have attempted to use the non-standard compiler options you mentioned in another
blog
post. This improves the stability of Eclipse greatly as much less memory is used however weaving takes
much longer initially 17:46:49 Timer event: 2609387ms: Total time spent in AJBuilder.build() ·
So the profiling… I’ve attached the file with the profiling output
o
None of these numbers are particularly shocking…. So I assume these times are not per class file but an overall time spent matching for
full weave?
o
The obvious big number is the call advise.. We hope to remove this and place the logic in an execute
o
We do use within() to limit the pointcuts to classes annotated with @Entity yet and we know it only weaves 700 classes yet it seems to
find types:#17731 on fast match.. Is within() not behaving as expected
§
Perhaps other wildcard pointcuts are making the match not so certain? ·
When we weave in our build (via ANT) we weave into the byte code.. We invoke the weave command 12 times to account for the various modules
and the total time spent weaving is about 2 mins… Which suggests weaving requires a significant amount of time.
o
Unfortunately we are not in a position to split out our eclipse project based on these modules delineations
·
I’ve also attached our aspect (minus the code in the advices) in case that helps when reviewing Thanks again for helping with this. Rich From:
ajdt-dev-bounces@xxxxxxxxxxx [mailto:ajdt-dev-bounces@xxxxxxxxxxx]
On Behalf Of Andy Clement Hi Rich, Very fortunate I happened to check this ajdt mailing list, I don't do it very often. I tend to hang around on the aspectj users/dev list (or stack overflow) - that might be a better
place for the discussion (at least more people will see the discussion). Anyway, there is a lot to talk about there but let me start at the beginning: > At this time we have defined a single aspect file which contains ~9 pointcuts and ~ 8 join-points.. You don't define join points. You define pointcuts: pointcut p(): execution(* somemethod(..)); and advice attached to pointcuts: before(): p() {...} Join points are matched by pointcuts. Every program has lots of join points but using the pointcut patterns AspectJ selects a subset to which the advice gets attached. > I think my terminology is correct in saying we have mostly statically determined pointcuts. That is great that they are statically determinable but the cost for matching each one can vary wildly depending on the which elements of the pointcut are specified and which are wildcarded.
Using annotations or type names can speed up matching (as large numbers of join points can be dismissed very quickly) but I know you have said you don't want to specify type or package names. > Right now the pointcuts do have lots of operators (mainly OR’s). Are these know to be less performant? Doesn't really matter about the operators. All pointcuts are translated into a DNF form and the individual components are sorted to ensure those cheaper to analyze are first. > In terms of “Execution Time” the weave process takes ~2.5 mins. When you say 'weave time' should I assume you mean compile and weave time? i.e. the time from when you press 'clean project' to the time when the whole process finishes? If your project
is an AspectJ project then AspectJ is responsible for compilation and weaving - for compilation it is using a modified variant of the JDT compiler. > Our eclipse project is large. It consists of 11334 types (files). Of these types we’re expecting that only types annotated with @Entity (~700 classes) would
be weaved. But AJDT seems to report that 10404 makers are created and if I search the generated bytecode 19228 class files (of 21058) have references to “org.aspectj” in the bytecode. However only the @Entity classes have the inner $AjcClosure classes so I’m
guessing it is advising correctly. Inspecting the non @Entity bytecode which does have references to “org.aspectj” it typically seems to be something like > > org.aspectj.weaver.MethodDeclarationLineNumber: length = 0x8 > > Reading online this seems to be some form of debug information? So what we are seeing it is taking 2.5mins+ and potentially weaving more than it should. grepping through the byte code isn't a great way to tell what was woven. The MethodDeclarationLineNumbers are used if something is advised since Java does not include the line numbers
for method declarations. It is produced during compilation, *not* during weaving. I would expect all classes compiled in an AspectJ project to have these MethodDeclarationLineNumber elements in them (if they contain method declarations) so I presume that is
why 19228 of your 21058 files have them. If you want to identify which files have actually been woven, grep the byte code for the attribute 'org.aspectj.weaver.WeaverState'. My gut reaction is that 10404 markers feels like a lot but I suppose if you have 700
classes that should be advised, it is only 14 per file. In the markers view in eclipse have you seen any markers that look wrong? > Perhaps we need to tweak our pointcuts to skip over classes quicker? Yes, I'm more suspicious of the matching time for pointcuts than the actual weaving time. You don't mention what version of AJDT you are on, I hope it is something recent? I wrote an article a while back on profiling how long your pointcuts are taking to match: And here is one on how to see that information in AJDT: It would be interesting to know if you have any pointcuts that are spending a lot of time in the matching. And whether you are using the more adventurous pointcut designators like cflow. > Is it possible to turn off markers (or perhaps only install the weaver) and not take advantage of advise markers. I've often thought we need that but I don't think we have it right now. Are you able to do a command line build of this project - how does that compare when AJDT is not in the loop? I'm certainly happy to work with you to dig into this. Taking a look at the pointcuts may be the next step. cheers, Andy On 26 September 2014 05:24, Richard Fanning <Richard.Fanning@xxxxxxxxxx> wrote: Hi there, We’re recently started a proof of concept of using AOP (AspectJ) in our existing product/project. At this time we have defined a single aspect file which contains
~9 pointcuts and ~ 8 join-points.. I think my terminology is correct in saying we have mostly statically determined pointcuts. Right now the pointcuts do have lots of operators (mainly OR’s). Are these know to be less performant? The aspect lives in a framework
JAR and projects which use this framework configure Eclipse with the framework JAR in the Aspect path.
We’re encountering some performance problems weaving using AJDT in Eclipse and was hoping for some recommendations from this mailing list. I’d categorize the performance problems as follows
1.
Execution Time
2.
Memory and hanging up Eclipse In terms of “Execution Time” the weave process takes ~2.5 mins. Full output attached but here are snippets from AJDT trace 11:1:59 Timer event: 212035ms: Total time spent in AJBuilder.build() This is after initial startup 11:7:3 Timer event: 141006ms: Total time spent in AJBuilder.build() This is after subsequently doing a CLEAN build 11:2:23 Created 10404 markers in 11334 files 11:7:17 Created 10404 markers in 11334 files Our eclipse project is large. It consists of 11334 types (files). Of these types we’re expecting that only types annotated with @Entity (~700 classes) would
be weaved. But AJDT seems to report that 10404 makers are created and if I search the generated bytecode 19228 class files (of 21058) have references to “org.aspectj” in the bytecode. However only the @Entity classes have the inner $AjcClosure classes so I’m
guessing it is advising correctly. Inspecting the non @Entity bytecode which does have references to “org.aspectj” it typically seems to be something like org.aspectj.weaver.MethodDeclarationLineNumber: length = 0x8 Reading online this seems to be some form of debug information? So what we are seeing it is taking 2.5mins+ and potentially weaving more than it should. Our
aspect does not / can not filter by package.. Does not filter by class name (i.e. our Entity classes are not postfixed with Entity i.e. AccountEntity). Our eclipse setup right now intermingles @Entity classes with other code so we cannot in Eclipse specify
an inpath of certain class folders. We are using compile time byte code weaving so can’t use an aop.xml to filter.. So for now let’s assume re-organising the project is not an option where should be look for improving this performance? We are trying to target
~ 700 classes of ~12000 and targeting the classes by classes annotated with @Entity and the aspect then advises various methods of that class. Is that execution time about right? Perhaps we need to tweak our pointcuts to skip over classes quicker? In terms of 2) Memory usage and eclipse hanging up it’s been a bit of a struggle for developers in Eclipse.. We have incremental compilation enabled but waiting
2.5mins at times really kills productivity. On top of the wait time even with eclipse.ini configured with lots of RAM and multiple VM tuning settings we often need to restart eclipse because
A.
It runs out of memory. Here are some graphics of the memory spikes for the executions above First Execution
Second Execution (can still see first)
Profiling CPU using jvisualvm seems to be a pretty IO intensive operation (as expected)
Here is a graphic of a heap dump I took at one point… Could there be a leak at play?
B.
Secondly on occasion the “Delete & Update markers” process will completely hang blocking other threads in Eclipse. It appears as if we’ve entered
a loop of some sort.
Is it possible to turn off markers (or perhaps only install the weaver) and not take advantage of advise markers. My Environment
·
Windows 7, Oracle (Sun) JDK Java 7_45 64bit, 8GB RAM, i7 quad core processor Here are some of the setting from eclipse.ini… Some of these have improved things somewhat -Xms1024m -Xmx4048m -XX:MaxPermSize=512m -Xverify:none
-XX:+UseG1GC -XX:-DontCompileHugeMethods -XX:MaxInlineSize=1024
-XX:FreqInlineSize=1024 -Xss1m -XX:+UseCMSCompactAtFullCollection -XX:+CMSClassUnloadingEnabled -XX:+DoEscapeAnalysis -XX:+UseCompressedOops -XX:+AggressiveOpts -XX:+ExplicitGCInvokesConcurrentAndUnloadsClasses Any recommendations/advice would be greatly appreciated. Let me know if you need additional information. Thanks Rich
__________________________________________________________ |
15:53:6 Startup information: AJDT version: 2.2.3.e43x-RELEASE-20130627-0800 AspectJ Compiler version: 1.7.3 usingVisualiser=true usingXref=true usingCUprovider=true org.eclipse.ajdt.internal.ui.tracing.checked.filters = set: Compiler,Builder ajde.version.at.previous.startup = 2.2.3.e43x-RELEASE-20130627-0800 15:53:43 Compiler configuration for project FO_JEE6 doesn't know previous state, so assuming EVERYTHING has changed. 15:53:43 =========================================================================================== 15:53:43 Build kind = AUTOBUILD 15:53:43 Project=FO_JEE6, kind of build requested=Incremental AspectJ compilation 15:53:43 Timer event: 1ms: Flush included source file cache 15:53:43 Timer event: 137ms: Check delta 15:53:43 CoreCompilerConfiguration for project FO_JEE6 registered a configuration change: [JAVAOPTIONS_CHANGED, NONSTANDARDOPTIONS_CHANGED, OUTJAR_CHANGED] 15:53:43 Timer event: 55ms: Looking for and marking configuration changes in FO_JEE6 15:53:43 Configuration changes found: true 15:53:43 Timer event: 55ms: Look for source/resource changes 15:53:57 Builder: Tidied output folder(s), removed class files and derived resources 15:54:0 Timer event: 17254ms: Pre compile 15:54:6 Compiler configuration for project FO_JEE6 has been read by compiler. Resetting. 15:54:6 Configuration was [PROJECTSOURCEFILES_CHANGED, JAVAOPTIONS_CHANGED, ASPECTPATH_CHANGED, CLASSPATH_CHANGED, INPATH_CHANGED, NONSTANDARDOPTIONS_CHANGED, OUTJAR_CHANGED, PROJECTSOURCERESOURCES_CHANGED, OUTPUTDESTINATIONS_CHANGED, INJARS_CHANGED] 15:54:6 Resetting list of modified source files. Was null 15:54:6 Preparing for build: not going to be incremental because no successful previous full build 15:54:36 Timer event: 36230ms: Time to first compiled message 15:54:36 Timer event: 36239ms: Time to first woven message 15:57:12 AspectJ reports build successful, build was: FULL 15:57:12 AJDE Callback: finish. Was full build: true 15:57:12 Timer event: 192019ms: Total time spent in AJDE 15:57:12 Timer event: 0ms: Refresh after build 15:57:18 Types affected during build = 11335 15:57:31 Timer event: 228014ms: Total time spent in AJBuilder.build() 15:57:31 Timer event: 0ms: Update visualizer, xref, advice listeners for (separate thread): FO_JEE6 15:57:31 =========================================================================================== 15:57:31 Build kind = FULLBUILD 15:57:31 Project=FO_JEE6, kind of build requested=Full AspectJ compilation 15:57:31 Timer event: 0ms: Flush included source file cache 15:57:31 Timer event: 0ms: Check delta 15:57:39 Builder: Tidied output folder(s), removed class files and derived resources 15:57:40 Timer event: 8903ms: Pre compile 15:57:40 Timer event: 9408ms: Delete markers: FO_JEE6 (Finished deleting markers for FO_JEE6) 15:57:41 Timer event: 487ms: Create markers: FO_JEE6 (Finished creating markers for FO_JEE6) 15:57:41 Created 0 markers in 11334 files 15:57:44 Compiler configuration for project FO_JEE6 has been read by compiler. Resetting. 15:57:44 Configuration was [] 15:57:44 Resetting list of modified source files. Was [] 15:57:44 Preparing for build: not going to be incremental because no successful previous full build 15:57:59 Timer event: 19189ms: Time to first compiled message 15:57:59 Timer event: 19193ms: Time to first woven message 15:59:52 AspectJ reports build successful, build was: FULL 15:59:52 AJDE Callback: finish. Was full build: true 15:59:52 Timer event: 131683ms: Total time spent in AJDE 15:59:52 Timer event: 0ms: Refresh after build 15:59:58 Types affected during build = 11335 16:0:5 Timer event: 153354ms: Total time spent in AJBuilder.build() 16:0:5 Timer event: 0ms: Update visualizer, xref, advice listeners for (separate thread): FO_JEE6 16:0:5 Timer event: 63ms: Delete markers: FO_JEE6 (Finished deleting markers for FO_JEE6) 16:5:4 Timer event: 299509ms: Create markers: FO_JEE6 (Finished creating markers for FO_JEE6) 16:5:4 Created 10404 markers in 11335 files 16:6:46 Removed problems and tasks for project FO_JEE6 16:6:55 Builder: Tidied output folder(s), removed class files and derived resources 16:6:55 Timer event: 91ms: Delete markers: FO_JEE6 (Finished deleting markers for FO_JEE6) 16:6:55 Compiler configuration for project FO_JEE6 doesn't know previous state, so assuming EVERYTHING has changed. 16:6:55 =========================================================================================== 16:6:55 Build kind = FULLBUILD 16:6:55 Project=FO_JEE6, kind of build requested=Full AspectJ compilation 16:6:55 Timer event: 0ms: Flush included source file cache 16:6:55 Timer event: 0ms: Check delta 16:6:55 Builder: Tidied output folder(s), removed class files and derived resources 16:6:57 Timer event: 1654ms: Pre compile 16:7:0 Compiler configuration for project FO_JEE6 has been read by compiler. Resetting. 16:7:0 Configuration was [PROJECTSOURCEFILES_CHANGED, JAVAOPTIONS_CHANGED, ASPECTPATH_CHANGED, CLASSPATH_CHANGED, INPATH_CHANGED, NONSTANDARDOPTIONS_CHANGED, OUTJAR_CHANGED, PROJECTSOURCERESOURCES_CHANGED, OUTPUTDESTINATIONS_CHANGED, INJARS_CHANGED] 16:7:0 Resetting list of modified source files. Was null 16:7:0 Preparing for build: not going to be incremental because no successful previous full build 16:7:22 Timer event: 25799ms: Time to first compiled message 16:7:22 Timer event: 25803ms: Time to first woven message 16:8:58 AspectJ reports build successful, build was: FULL 16:8:58 AJDE Callback: finish. Was full build: true 16:8:58 Timer event: 121224ms: Total time spent in AJDE 16:8:58 Timer event: 0ms: Refresh after build 16:9:4 Types affected during build = 11335 16:9:10 Timer event: 0ms: Update visualizer, xref, advice listeners for (separate thread): FO_JEE6 16:9:10 Timer event: 134943ms: Total time spent in AJBuilder.build() 16:9:10 Timer event: 183ms: Delete markers: FO_JEE6 (Finished deleting markers for FO_JEE6) 16:14:29 Timer event: 318863ms: Create markers: FO_JEE6 (Finished creating markers for FO_JEE6) 16:14:29 Created 10404 markers in 11335 files
14:49:37 Startup information: AJDT version: 2.2.3.e43x-RELEASE-20130627-0800 AspectJ Compiler version: 1.7.3 usingVisualiser=true usingXref=true usingCUprovider=true org.eclipse.ajdt.internal.ui.tracing.checked.filters = set: Compiler,Builder ajde.version.at.previous.startup = 2.2.3.e43x-RELEASE-20130627-0800 14:49:37 Compiler configuration for project FO_JEE6 doesn't know previous state, so assuming EVERYTHING has changed. 14:49:37 =========================================================================================== 14:49:37 Build kind = AUTOBUILD 14:49:37 Project=FO_JEE6, kind of build requested=Incremental AspectJ compilation 14:49:37 Timer event: 2ms: Flush included source file cache 14:49:37 Timer event: 95ms: Check delta 14:49:37 Timer event: 1ms: Looking for and marking configuration changes in FO_JEE6 14:49:37 Configuration changes found: false 14:49:37 build: Examined delta - no source file or classpath changes for project FO_JEE6 14:49:37 Timer event: 0ms: Looking for and marking configuration changes in FO_JEE6 14:49:37 Configuration changes found: false 14:49:37 Compiler configuration for project FO_JEE6 has been read by compiler. Resetting. 14:49:37 Configuration was [PROJECTSOURCEFILES_CHANGED, JAVAOPTIONS_CHANGED, ASPECTPATH_CHANGED, CLASSPATH_CHANGED, INPATH_CHANGED, NONSTANDARDOPTIONS_CHANGED, OUTJAR_CHANGED, PROJECTSOURCERESOURCES_CHANGED, OUTPUTDESTINATIONS_CHANGED, INJARS_CHANGED] 14:49:37 Resetting list of modified source files. Was null 14:49:37 Timer event: 9ms: Look for source/resource changes 14:49:37 No source/resource changes found, exiting build 14:49:37 Timer event: 133ms: Total time spent in AJBuilder.build() 14:50:46 Removed problems and tasks for project FO_JEE6 14:51:1 Builder: Tidied output folder(s), removed class files and derived resources 14:51:1 Timer event: 152ms: Delete markers: FO_JEE6 (Finished deleting markers for FO_JEE6) 14:51:1 Compiler configuration for project FO_JEE6 doesn't know previous state, so assuming EVERYTHING has changed. 14:51:1 =========================================================================================== 14:51:1 Build kind = FULLBUILD 14:51:1 Project=FO_JEE6, kind of build requested=Full AspectJ compilation 14:51:1 Timer event: 0ms: Flush included source file cache 14:51:1 Timer event: 0ms: Check delta 14:51:1 Builder: Tidied output folder(s), removed class files and derived resources 14:51:4 Timer event: 3293ms: Pre compile 14:51:11 Compiler configuration for project FO_JEE6 has been read by compiler. Resetting. 14:51:11 Configuration was [PROJECTSOURCEFILES_CHANGED, JAVAOPTIONS_CHANGED, ASPECTPATH_CHANGED, CLASSPATH_CHANGED, INPATH_CHANGED, NONSTANDARDOPTIONS_CHANGED, OUTJAR_CHANGED, PROJECTSOURCERESOURCES_CHANGED, OUTPUTDESTINATIONS_CHANGED, INJARS_CHANGED] 14:51:11 Resetting list of modified source files. Was null 14:51:11 Preparing for build: not going to be incremental because no successful previous full build 14:51:42 Timer event: 37507ms: Time to first compiled message 14:51:42 Timer event: 37518ms: Time to first woven message 14:55:47 AspectJ reports build successful, build was: FULL 14:55:47 Pointcut matching cost (total=11505ms for 282774 joinpoint match calls): 14:55:47 Time:379ms (jps:#95866) matching against ((((within((@com.abc.bo.annotation.Entity *)) && execution(void set*((java.lang.String || (java.math.BigDecimal || (com.abc.types.TaBlob || (boolean || (com.abc.util.DateTime || (com.abc.util.DateOnly || (long || (int || (com.abc.kernel.Money || (com.abc.kernel.TaEnum || com.abc.kernel.ITaEnum))))))))))))) && target(BindingTypePattern(com.abc.bo.BusinessEntityImpl, 1))) && args(BindingTypePattern(java.lang.Object, 0))) && persingleton(com.abc.EntityAspect)) 14:55:47 Time:139ms (jps:#17927) matching against (((within((@com.abc.bo.annotation.Entity *)) && execution(new(..))) && target(BindingTypePattern(com.abc.bo.BusinessEntityImpl, 0))) && persingleton(com.abc.EntityAspect)) 14:55:47 Time:9080ms (jps:#64374) matching against ((!within(com.abc.bo.BusinessEntityRef+) && call(com.abc.bo.BusinessEntityImpl+.new(..))) && persingleton(com.abc.EntityAspect)) 14:55:47 Time:928ms (jps:#11671) matching against (((((((((within((@com.abc.bo.annotation.Entity *)) && !get(@com.abc.bo.annotation.Transient private * *)) && !execution(public java.lang.String com.abc.bo.BusinessEntityImpl+.getBOCaption())) && !execution(public int com.abc.bo.BusinessEntityImpl+.getClassId())) && execution((java.lang.String || (java.math.BigDecimal || (com.abc.types.TaBlob || (boolean || (com.abc.util.DateTime || (com.abc.util.DateOnly || (long || (int || (com.abc.kernel.Money || (com.abc.kernel.TaEnum || com.abc.kernel.ITaEnum)))))))))) com.abc.bo.BusinessEntityImpl+.get*())) && !execution(public * com.abc.bo.BusinessEntityImpl+.*ConcurrentGuard())) && target(BindingTypePattern(com.abc.bo.BusinessEntityImpl, 0))) && !target(com.abc.bo.BusinessEntityImpl)) && persingleton(com.abc.EntityAspect)) || (((((((((within((@com.abc.bo.annotation.Entity *)) && !get(@com.abc.bo.annotation.Transient private * *)) && !execution(public java.lang.String com.abc.bo.BusinessEntityImpl+.getBOCaption())) && !execution(public int com.abc.bo.BusinessEntityImpl+.getClassId())) && execution((java.lang.String || (java.math.BigDecimal || (com.abc.types.TaBlob || (boolean || (com.abc.util.DateTime || (com.abc.util.DateOnly || (long || (int || (com.abc.kernel.Money || (com.abc.kernel.TaEnum || com.abc.kernel.ITaEnum)))))))))) com.abc.bo.BusinessEntityImpl+.get*())) && !execution(com.abc.bo.BusinessEntity+ com.abc.bo.BusinessEntityImpl+.get*())) && !execution(public * com.abc.bo.BusinessEntityImpl+.*ConcurrentGuard())) && !execution(List<(com.abc.bo.BusinessEntity+)> com.abc.bo.BusinessEntityImpl+.get*())) && target(BindingTypePattern(com.abc.bo.BusinessEntityImpl, 0))) && persingleton(com.abc.EntityAspect))) 14:55:47 Time:240ms (jps:#57923) matching against (((within((@com.abc.bo.annotation.Entity *)) && set(@com.abc.bo.annotation.OneToOne private * *)) && args(BindingTypePattern(java.lang.Object, 0))) && persingleton(com.abc.EntityAspect)) 14:55:47 Time:140ms (jps:#11671) matching against (((within((@com.abc.bo.annotation.Entity *)) && execution(Rel<(com.abc.bo.BusinessEntity+)> com.abc.bo.BusinessEntityImpl+.get*())) && target(BindingTypePattern(com.abc.bo.BusinessEntityImpl, 0))) && persingleton(com.abc.EntityAspect)) 14:55:47 Time:310ms (jps:#11671) matching against ((((within((@com.abc.bo.annotation.Entity *)) && execution(com.abc.bo.BusinessEntity+ com.abc.bo.BusinessEntityImpl+.get*())) && target(BindingTypePattern(com.abc.bo.BusinessEntityImpl, 0))) && persingleton(com.abc.EntityAspect)) || (((within((@com.abc.bo.annotation.Entity *)) && execution(List<(com.abc.bo.BusinessEntity+)> com.abc.bo.BusinessEntityImpl+.get*())) && target(BindingTypePattern(com.abc.bo.BusinessEntityImpl, 0))) && persingleton(com.abc.EntityAspect))) 14:55:47 Time:285ms (jps:#11671) matching against ((((((within((@com.abc.bo.annotation.Entity *)) && execution(boolean com.abc.bo.BusinessEntityImpl+.add*(com.abc.bo.BusinessEntityImpl+))) && !execution(boolean com.abc.bo.BusinessEntityImpl+.removeThe*(com.abc.bo.BusinessEntityImpl+))) && args(BindingTypePattern(com.abc.bo.BusinessEntityImpl, 0))) && persingleton(com.abc.EntityAspect)) || ((((within((@com.abc.bo.annotation.Entity *)) && execution(boolean com.abc.bo.BusinessEntityImpl+.remove*(com.abc.bo.BusinessEntityImpl+))) && !execution(boolean com.abc.bo.BusinessEntityImpl+.removeThe*(com.abc.bo.BusinessEntityImpl+))) && args(BindingTypePattern(com.abc.bo.BusinessEntityImpl, 0))) && persingleton(com.abc.EntityAspect))) || ((((within((@com.abc.bo.annotation.Entity *)) && execution(void com.abc.bo.BusinessEntityImpl+.set*((com.abc.bo.BusinessEntityImpl+ || List<(com.abc.bo.BusinessEntity+)>)))) && !execution(boolean com.abc.bo.BusinessEntityImpl+.removeThe*(com.abc.bo.BusinessEntityImpl+))) && args(BindingTypePattern(com.abc.bo.BusinessEntityImpl, 0))) && persingleton(com.abc.EntityAspect))) 14:55:47 --- 14:55:47 Pointcut fast matching cost (total=5816ms for 141848 fast match calls): 14:55:47 Time:34ms (types:#17731) fast matching against ((((within((@com.abc.bo.annotation.Entity *)) && execution(void set*((java.lang.String || (java.math.BigDecimal || (com.abc.types.TaBlob || (boolean || (com.abc.util.DateTime || (com.abc.util.DateOnly || (long || (int || (com.abc.kernel.Money || (com.abc.kernel.TaEnum || com.abc.kernel.ITaEnum))))))))))))) && target(BindingTypePattern(com.abc.bo.BusinessEntityImpl, 1))) && args(BindingTypePattern(java.lang.Object, 0))) && persingleton(com.abc.EntityAspect)) 14:55:47 Time:59ms (types:#17731) fast matching against (((within((@com.abc.bo.annotation.Entity *)) && execution(new(..))) && target(BindingTypePattern(com.abc.bo.BusinessEntityImpl, 0))) && persingleton(com.abc.EntityAspect)) 14:55:47 Time:854ms (types:#17731) fast matching against ((!within(com.abc.bo.BusinessEntityRef+) && call(com.abc.bo.BusinessEntityImpl+.new(..))) && persingleton(com.abc.EntityAspect)) 14:55:47 Time:12ms (types:#17731) fast matching against (((within((@com.abc.bo.annotation.Entity *)) && set(@com.abc.bo.annotation.OneToOne private * *)) && args(BindingTypePattern(java.lang.Object, 0))) && persingleton(com.abc.EntityAspect)) 14:55:47 Time:3894ms (types:#17731) fast matching against (((((((((within((@com.abc.bo.annotation.Entity *)) && !get(@com.abc.bo.annotation.Transient private * *)) && !execution(public java.lang.String com.abc.bo.BusinessEntityImpl+.getBOCaption())) && !execution(public int com.abc.bo.BusinessEntityImpl+.getClassId())) && execution((java.lang.String || (java.math.BigDecimal || (com.abc.types.TaBlob || (boolean || (com.abc.util.DateTime || (com.abc.util.DateOnly || (long || (int || (com.abc.kernel.Money || (com.abc.kernel.TaEnum || com.abc.kernel.ITaEnum)))))))))) com.abc.bo.BusinessEntityImpl+.get*())) && !execution(public * com.abc.bo.BusinessEntityImpl+.*ConcurrentGuard())) && target(BindingTypePattern(com.abc.bo.BusinessEntityImpl, 0))) && !target(com.abc.bo.BusinessEntityImpl)) && persingleton(com.abc.EntityAspect)) || (((((((((within((@com.abc.bo.annotation.Entity *)) && !get(@com.abc.bo.annotation.Transient private * *)) && !execution(public java.lang.String com.abc.bo.BusinessEntityImpl+.getBOCaption())) && !execution(public int com.abc.bo.BusinessEntityImpl+.getClassId())) && execution((java.lang.String || (java.math.BigDecimal || (com.abc.types.TaBlob || (boolean || (com.abc.util.DateTime || (com.abc.util.DateOnly || (long || (int || (com.abc.kernel.Money || (com.abc.kernel.TaEnum || com.abc.kernel.ITaEnum)))))))))) com.abc.bo.BusinessEntityImpl+.get*())) && !execution(com.abc.bo.BusinessEntity+ com.abc.bo.BusinessEntityImpl+.get*())) && !execution(public * com.abc.bo.BusinessEntityImpl+.*ConcurrentGuard())) && !execution(List<(com.abc.bo.BusinessEntity+)> com.abc.bo.BusinessEntityImpl+.get*())) && target(BindingTypePattern(com.abc.bo.BusinessEntityImpl, 0))) && persingleton(com.abc.EntityAspect))) 14:55:47 Time:108ms (types:#17731) fast matching against (((within((@com.abc.bo.annotation.Entity *)) && execution(Rel<(com.abc.bo.BusinessEntity+)> com.abc.bo.BusinessEntityImpl+.get*())) && target(BindingTypePattern(com.abc.bo.BusinessEntityImpl, 0))) && persingleton(com.abc.EntityAspect)) 14:55:47 Time:320ms (types:#17731) fast matching against ((((within((@com.abc.bo.annotation.Entity *)) && execution(com.abc.bo.BusinessEntity+ com.abc.bo.BusinessEntityImpl+.get*())) && target(BindingTypePattern(com.abc.bo.BusinessEntityImpl, 0))) && persingleton(com.abc.EntityAspect)) || (((within((@com.abc.bo.annotation.Entity *)) && execution(List<(com.abc.bo.BusinessEntity+)> com.abc.bo.BusinessEntityImpl+.get*())) && target(BindingTypePattern(com.abc.bo.BusinessEntityImpl, 0))) && persingleton(com.abc.EntityAspect))) 14:55:47 Time:531ms (types:#17731) fast matching against ((((((within((@com.abc.bo.annotation.Entity *)) && execution(boolean com.abc.bo.BusinessEntityImpl+.add*(com.abc.bo.BusinessEntityImpl+))) && !execution(boolean com.abc.bo.BusinessEntityImpl+.removeThe*(com.abc.bo.BusinessEntityImpl+))) && args(BindingTypePattern(com.abc.bo.BusinessEntityImpl, 0))) && persingleton(com.abc.EntityAspect)) || ((((within((@com.abc.bo.annotation.Entity *)) && execution(boolean com.abc.bo.BusinessEntityImpl+.remove*(com.abc.bo.BusinessEntityImpl+))) && !execution(boolean com.abc.bo.BusinessEntityImpl+.removeThe*(com.abc.bo.BusinessEntityImpl+))) && args(BindingTypePattern(com.abc.bo.BusinessEntityImpl, 0))) && persingleton(com.abc.EntityAspect))) || ((((within((@com.abc.bo.annotation.Entity *)) && execution(void com.abc.bo.BusinessEntityImpl+.set*((com.abc.bo.BusinessEntityImpl+ || List<(com.abc.bo.BusinessEntity+)>)))) && !execution(boolean com.abc.bo.BusinessEntityImpl+.removeThe*(com.abc.bo.BusinessEntityImpl+))) && args(BindingTypePattern(com.abc.bo.BusinessEntityImpl, 0))) && persingleton(com.abc.EntityAspect))) 14:55:47 --- 14:55:47 AJDE Callback: finish. Was full build: true 14:55:47 AJDE Callback: finish. Was full build: true 14:55:47 Timer event: 282589ms: Total time spent in AJDE 14:55:47 Timer event: 0ms: Refresh after build 14:55:52 Printing crosscutting model for all AspectJ projects in the workspace 14:55:52 14:55:52 -------------------------------------- 14:55:52 Printing crosscutting model for FO_JEE6 14:55:52 No structure model available for FO_JEE6 14:55:52 -------------------------------------- 14:55:52 14:56:3 Types affected during build = 11335 14:56:20 Timer event: 319227ms: Total time spent in AJBuilder.build() 14:56:21 Timer event: 361ms: Delete markers: FO_JEE6 (Finished deleting markers for FO_JEE6) 15:16:38 Timer event: 1217622ms: Create markers: FO_JEE6 (Finished creating markers for FO_JEE6) 15:16:38 Created 10404 markers in 11335 files 15:21:35 Timer event: 0ms: Update visualizer, xref, advice listeners for (separate thread): FO_JEE6
Attachment:
EntityAspect.aj
Description: EntityAspect.aj
