RE: [aspectj-users] Overall problem with AJDT performance

[Thomas Hofmann <email@xxxxxxxxxxxxxxxxx>]

Hi Andy,

thanks for the zips. Here is a first result:

21:59:2 Compiler configuration for project com.dcx.ivkmds.fwk.test.ass doesn't know previous state, so assuming EVERYTHING has changed.
21:59:2 ===========================================================================================
21:59:2 Build kind = FULLBUILD
21:59:2 Project=com.dcx.ivkmds.fwk.test.ass, kind of build requested=Full AspectJ compilation
21:59:2 Timer event: 0ms: Flush included source file cache
21:59:2 Timer event: 0ms: Check delta
21:59:2 Builder: Tidied output folder(s), removed class files and derived resources
21:59:2 Timer event: 526ms: Pre compile
21:59:2 Compiler configuration for project com.dcx.ivkmds.fwk.test.ass has been read by compiler.  Resetting.
21:59:2      Configuration was [PROJECTSOURCEFILES_CHANGED, JAVAOPTIONS_CHANGED, ASPECTPATH_CHANGED, CLASSPATH_CHANGED, INPATH_CHANGED, NONSTANDARDOPTIONS_CHANGED, OUTJAR_CHANGED, PROJECTSOURCERESOURCES_CHANGED, OUTPUTDESTINATIONS_CHANGED, INJARS_CHANGED]

21:59:2 Resetting list of modified source files.  Was null
21:59:2 Preparing for build: not going to be incremental because no successful previous full build
21:59:4 Timer event: 1141ms: Time to first compiled message
21:59:4 Timer event: 1974ms: Time to first woven message
22:1:9 AspectJ reports build successful, build was: FULL
22:1:9 AJDE Callback: finish. Was full build: true
22:1:9 Timer event: 126764ms: Total time spent in AJDE
22:1:9 Timer event: 0ms: Refresh after build
22:1:9 Types affected during build = 24
22:1:9 Timer event: 0ms: Update visualizer, xref, advice listeners for (separate thread): com.dcx.ivkmds.fwk.test.ass
22:1:9 Timer event: 127389ms: Total time spent in AJBuilder.build()
22:1:9 Timer event: 16ms: Delete markers: com.dcx.ivkmds.fwk.test.ass (Finished deleting markers for com.dcx.ivkmds.fwk.test.ass)
22:1:9 Timer event: 20ms: Delete markers: com.dcx.ivkmds._00_fwktest.ass (Finished deleting markers for com.dcx.ivkmds._00_fwktest.ass)
22:1:13 Timer event: 3915ms: Create markers: com.dcx.ivkmds._00_fwktest.ass (Finished creating markers for com.dcx.ivkmds._00_fwktest.ass)
22:1:13 Created 179 markers in 4 files
22:1:16 Timer event: 12ms: Delete markers: com.dcx.ivkmds.fwk.test.ass (Finished deleting markers for com.dcx.ivkmds.fwk.test.ass)
22:1:16 Timer event: 175ms: Delete markers: com.dcx.ivkmds.common.businessobjects.fwktest (Finished deleting markers for com.dcx.ivkmds.common.businessobjects.fwktest)
22:1:19 Timer event: 2941ms: Create markers: com.dcx.ivkmds.common.businessobjects.fwktest (Finished creating markers for com.dcx.ivkmds.common.businessobjects.fwktest)
22:1:19 Created 111 markers in 32 files
22:1:24 Timer event: 7906ms: Create markers: com.dcx.ivkmds.fwk.test.ass (Finished creating markers for com.dcx.ivkmds.fwk.test.ass)
22:1:24 Created 572 markers in 24 files


Timing ------------
Entire time spent in the weaver instance created for this build:
> performing model repairs=0ms
> reweavable processing=0ms
> verifying consistency=1ms
> weaving aspects=828ms
> weaving classes=123344ms
  for those two weave steps, time spent pre-post calling the individual type wea
ver instance: 37ms
> weaving normal itds=24ms
> weaving structural itds=1ms

Breakdown of time spent in type weaver instances:
class prep = 0ms
typeWeaving = 0ms
decaWeaving = 0ms
fastShadowMatching = 0ms
shadowMatching = 122806ms
shadowWeaving = 0ms
postWeave = 3ms
Total =122811ms

Timing: time spent in pipeline weaving: 124700ms
Timing ------------


More later...




-----Original Message-----
From: aspectj-users-bounces@xxxxxxxxxxx [mailto:aspectj-users-bounces@xxxxxxxxxxx] On Behalf Of Andy Clement
Sent: Freitag, 9. Oktober 2009 17:57
To: aspectj-users@xxxxxxxxxxx
Subject: Re: [aspectj-users] Overall problem with AJDT performance

Hi Thomas,

I've put a zip up on our download site containing two jars that
produce timing information.  The zip is here:

http://www.eclipse.org/downloads/download.php?file=/tools/aspectj/dev/timedAspectJ.zip

It contains jars ajde.jar and aspectjweaver.jar

These are replacements for the jars in your org.aspectj.ajde and
org.aspectj.weaver plugins (in your eclipse plugins folder).  So
backup the jars you have and replace them with these.

Now run your eclipse with the console view (-consolelog).

When you build a project you should then see per build output like
this (I built a 1000 file project here as an example:)

Timing ------------
Entire time spent in the weaver instance created for this build:
> performing model repairs=4ms
> reweavable processing=10ms
> verifying consistency=6ms
> weaving aspects=454ms
> weaving classes=27433ms
  for those two weave steps, time spent pre-post calling the
individual type weaver instance: 916ms
> weaving normal itds=45ms
> weaving structural itds=56ms

Breakdown of time spent in type weaver instances:
class prep = 154ms
typeWeaving = 32ms
decaWeaving = 19ms
fastShadowMatching = 56ms
shadowMatching = 19303ms
shadowWeaving = 0ms
postWeave = 789ms
Total =20356ms

Timing: time spent in pipeline weaving: 31963ms
Timing ------------

That initial information will enable us to go into the right area
next.  Feel free to start emailing me directly rather than using the
list, or raise a bug and we can communicate through that.  Oh, I would
turn off build automatically and just build a single project so we
know what we are dealing with.  I guess it doesn't matter which, just
one you think is taking too long (I'd saying anything over a 1 or 2
minutes is too long).

Your use of 'call()' is interesting and the fact that you get that
Xlint out.  But let's start with this.  I guess we are currently going
to suspect your shadowMatching time will be large.  Then we can look
at which parts of shadowmatching are taking a long time.  The use of
within() rather than relying on the declaring type in an execution()
pointcut to limit what is woven would enable the fastMatching time
above to increase and the shadowMatching time to decrease because
within() supports fast match and execution does not.  within() and
call() is not such a useful combination.  I might rework these timers
into something more permanent in the codebase.

Andy

2009/10/9 Thomas Hofmann <email@xxxxxxxxxxxxxxxxx>:
> Hi Andy,
>
> yes we have Ant driven builds. One for the Rich Client Application (based on Eclipse RCP) and one for the J2EE server part that produces an EAR file.
> The former runs about 12-15 minutes but it does not contain the projects with .ass. in the project / package names. The project that took more than 12 minutes to build was one of these server projects. The other one was a test project which also isn't part of the client build. The creation of the EAR file uses Ant tasks that take what is already compiled in the eclipse workspace so I have no other numbers for that part.
>
> I'm not sure if my pointcuts are well written. My experience with AspectJ is not that big. Anyway, I can say that the aspects that are woven into the application.ass project (the one that takes more than 12 minutes) don't use within().I'm not quite sure what would be the benefit of using within. Almost all classes in the project need to have the advice applied.
>
> I'm using mostly execution and call together with matching based on types.
>
> Let me give you some more details for the most problematic project:
> com.dcx.ivkmds.application.ass
>
> It contains repositories that handle persistence using Hibernate internally. There is a Java interface and an implementation based on Hibernate for each repository. In addition there are some utility classes but only a few.
>
> I don't see how within() would make much difference in terms of types affected (but of course I would like to learn if I'm wrong).
>
> The aspects that are applied reside in another project: com.dcx.ivkmds.fwk.ass. This a part of our "framework". The aspects in this project apply to other projects that make use of the framework, not just to com.dcx.ivkmds.application.ass.
>
> com.dcx.ivkmds.fwk.ass contains the following aspects:
>
> AssComponentAspect:
> Contains ITDs for all classes that implement the AssComponent interface.
>
> BaseSessionLifecycleControl:
> Is an abstract aspect that contains an around advice to open and close the Hibernate session. It contains an abstract pointcut that subclasses of the aspect may you to specify the boundaries for Hibernate sessions.
>
> SessionLifecycleControl:
> A concrete subclass of BaseSessionLifecycleControl. It contains the pointcut that determines where the advice is to be applied.
>
> MeasuringPoint:
> Contains pointcuts and advice for performance logging.
>
> DatabaseConnectionCustomization:
> Contains two after advices and one before advice to make 3rd party JDBC driver specific calls on the JDBC connection when a new connection is retrieved.
>
> DatabaseErrorTransformation:
> Uses an around advice to add special error handling for exceptions from the database. The are inspected and transformed to application specific exception types.
>
>
> Only the last three aspects apply to the classes in com.dcx.ivkmds.application.ass.
>
> Will the other three aspects visible on the aspect path of com.dcx.ivkmds.application.ass have a great negative performance impact? Would this require within()?
>
> What I don't like about within() is that it kind of turns dependencies around. If I need to specify within() in the aspects that are part of the framework I need to know what other parts of the framework make use of them.
> I even have to make the clients of the framework visible to the framework. This would result in cycles I believe.
>
> I would be glad to try out a debug build that would provide more insight into where the time is spent.
> Regarding yourkit I can only say that I don't have a license for it. I could probably use the 15 day evalutation version but would need to get some instructions on how to configure it to filter the classes your are interessted in.
>
> My eclipse wasn't running short of memory. Heap space was 1200 MB. During the build 600-900 MB were used (which is too much - but this is a different issue).
>
> I can give you more details on the aspects but I don't want to spam the mailing list. So please tell me if you think this is the right place to discuss these issues. I could also open a bug in bugzilla or we could use direct email or skype for example to exchange further details.
> Posting lots of source code to the mailing list or bugzilla is not what I want to do. I would prefer direct (not public) communication for this.
>
> Do you see any obvious problems with the setup I described above?
>
> Regards,
>
> Thomas
>
>
> -----Original Message-----
> From: aspectj-users-bounces@xxxxxxxxxxx [mailto:aspectj-users-bounces@xxxxxxxxxxx] On Behalf Of Andy Clement
> Sent: Donnerstag, 8. Oktober 2009 17:37
> To: aspectj-users@xxxxxxxxxxx
> Subject: Re: [aspectj-users] Overall problem with AJDT performance
>
> Hi Thomas,
>
> Those build times do look unreasonable.  Do you do product builds
> outside of eclipse (perhaps Ant driven) - do these builds exhibit the
> same issue?
>
> I've never seen a project build take 12minutes so clearly something
> unusual is happening.  I presume all your aspects are using well
> written pointcuts that involve scoping within() clauses and don't just
> attempt matching with just kinded pointcuts (like execution).  To see
> all the affected joinpoints in one place, you can turn on the
> weaveinfo info messages for the project.  Are you using ITDs?
>
> I think we need more visibility into the build time - I could do you a
> debug build of the plugins that will include extra stats about where
> the time goes.  (Or even better you could do a yourkit profile and
> send it to me? That would make it obvious).
>
> Oh, and is your eclipse running tight on memory?  I wondered if you
> were running near the limit and it was thrashing.
>
> Andy
>
>
> 2009/10/8 Thomas Hofmann <email@xxxxxxxxxxxxxxxxx>:
>> Hi Andy, Andrew J
>>
>>
>>
>> I'm still having problems with the performance of AJDT and AspectJ in my
>> workspace.
>>
>>
>>
>> Let me start by describing my environment:
>>
>>
>>
>> Thinkpad T61p
>>
>>
>>
>> Eclipse Java EE IDE for Web Developers.
>>
>> Version: 1.2.0.20090621-0820
>>
>> Build id: 20090621-0832
>>
>> based on Eclipse 3.5.0
>>
>>
>>
>> Version: 2.0.1.e35x-20091001-1600
>>
>> AspectJ version: 1.6.6.20090930185500
>>
>>
>>
>> The workspace contains about 148 Java projects (and some others like
>> features, project set projects etc.)
>>
>>
>>
>> I disabled Build Automatically, restarted Eclipse and then cleaned the whole
>> workspace. Then I started the build with Build All. The AJDT trace was set
>> to the default values and opened. It is attached to this mail.
>>
>>
>>
>> Here are the most relevant parts:
>>
>>
>>
>> Line 192: 13:50:34 Project=com.dcx.ivkmds.application.ass, kind of build
>> requested=Full AspectJ compilation
>>
>> Line 208: 14:3:17 Types affected during build = 292
>>
>> Line 211:Timer event: 766396ms: Total time spent in AJBuilder.build() ->
>> more than 12 minutes!
>>
>> Line 707: 14:22:6 Timer event: 117857ms: Create markers:
>> com.dcx.ivkmds.application.ass (Finished creating markers for
>> com.dcx.ivkmds.application.ass)
>>
>>
>>
>> Line 370: 14:10:32 Project=com.dcx.ivkmds.fwk.test.ass, kind of build
>> requested=Full AspectJ compilation
>>
>> Line 387: 14:18:45 Types affected during build = 24
>>
>> Line 390; 14:18:46 Timer event: 493759ms: Total time spent in
>> AJBuilder.build() -> more than 8 minutes!
>>
>>
>>
>> Line 701: 14:21:10 Timer event: 62468ms: Create markers:
>> com.dcx.ivkmds.fwk.test.ass (Finished creating markers for
>> com.dcx.ivkmds.fwk.test.ass)
>>
>>
>>
>> I figure that the types in these projects have a lot of joinpoints. Is there
>> any place where I can see the number of joinpoints in these projects?
>>
>>
>>
>> Actually, the number of types involved isn't very high I would say.
>>
>>
>>
>> So the question is are these compile / weave times normal? For us it is a
>> major problem when the time to rebuild the whole workspace takes 38 minutes.
>>
>>
>>
>> Is there anything I could try to do to improve the performance besides
>> reducing the number of joinpoints?
>>
>>
>>
>> I really like the benefit AspectJ provides but under these circumstances it
>> is very unpleasant and difficult to work with it.
>>
>>
>>
>> I'm looking forward to your reply.
>>
>>
>>
>> Regards,
>>
>>
>>
>> Thomas
>>
>>
>>
>>
>>
>> _______________________________________________
>> 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