[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index] [List Home]
Re: [aspectj-users] compile time performance (Eclipse 3.3)

Hi Oliver,

That is good to hear.  We have some improvements in AJDT 1.6.4 too and more coming shortly.  Your incremental build on Eclipse 3.4:

22:51:41 Timer event: 980ms: Total time spent in AJDE

is a little bit longer than I'd like, but if you are happy for now, then I am happy.

cheers,
Andy.

2009/3/23 Oliver Böhm <boehm@xxxxxxxxxx>
Hi Andy,

I migrated one of our subprojects to Eclipse 3.4 and it seems that AJDT 1.6.3 is really a performance booster - the speed is really much, much better, especially the incremental compile. Here the times for AJBuilder.build():

               full    incremental
Eclipse 3.3     75s     34s
Eclipse 3.4     30s     1s

You have done a really good job with AJDT 1.6.3 - the incremental compile is more than 30 times faster as before.

regards
Oliver



Here the complete log:


ECLIPSE 3.3 (FULLBUILD)

23:1:11 Removed problems and tasks for project GiropayConnector
23:1:11 Builder: Tidied output folder(s), deleted 161 .class files
23:1:11 ===========================================================================================
23:1:11 Build kind = FULLBUILD
23:1:11 Project=GiropayConnector, kind of build requested=Full AspectJ compilation
23:1:11 Builder: Tidied output folder(s), deleted 0 .class files
23:1:12 Preparing for build: not going to be incremental because no successful previous full build
23:1:12 Timer event: 636ms: Time to first compiled message
23:1:12 Timer event: 721ms: Time to first woven message
23:1:47 AspectJ reports build successful, build was: FULL
23:1:47 AJDE Callback: finish. Was full build: true
23:1:47 Timer event: 35047ms: Total time spent in AJDE
23:2:26 Timer event: 39863ms: Create element map (40038 rels in project: GiropayConnector)
23:2:26 Types affected during build = 159
23:2:27 Timer event: 367ms: Add markers (8496 markers)
23:2:27 Timer event: 75487ms: Total time spent in AJBuilder.build()


ECLIPSE 3.3 (INCREMENTAL)

23:7:5 ===========================================================================================
23:7:5 Build kind = AUTOBUILD
23:7:6 Project=GiropayConnector, kind of build requested=Incremental AspectJ compilation
23:7:6 build: Examined delta - source file changes in required project GiropayConnector
23:7:6 Preparing for build: planning to be an incremental build
23:7:6 Starting incremental compilation loop 1 of possibly 5
23:7:6 Timer event: 227ms: Time to first compiled message
23:7:8 Timer event: 2718ms: Time to first woven message
23:7:8 AspectJ reports build successful, build was: INCREMENTAL
23:7:8 AJDE Callback: finish. Was full build: false
23:7:8 Timer event: 2723ms: Total time spent in AJDE
23:7:39 Timer event: 30516ms: Create element map (40041 rels in project: GiropayConnector)
23:7:39 Types affected during build = 1
23:7:39 Timer event: 336ms: Add markers (8496 markers)
23:7:39 Timer event: 33736ms: Total time spent in AJBuilder.build()


ECLIPSE 3.4 (FULLBUILD)

22:47:52 Removed problems and tasks for project GiropayConnector
22:47:52 Builder: Tidied output folder(s), removed class files and derived resources
22:47:52 Timer event: 49ms: Delete markers: GiropayConnector (Finished deleting markers for GiropayConnector)
22:47:52 Compiler configuration for project GiropayConnector doesn't know previous state, so assuming EVERYTHING has changed.
22:47:52 ===========================================================================================
22:47:52 Build kind = FULLBUILD
22:47:52 Project=GiropayConnector, kind of build requested=Full AspectJ compilation
22:47:52 Builder: Tidied output folder(s), removed class files and derived resources
22:47:52 Timer event: 28ms: Pre compile
22:47:52 Compiler configuration for project GiropayConnector has been read by compiler.  Resetting.
22:47:52      Configuration was [PROJECTSOURCEFILES_CHANGED, JAVAOPTIONS_CHANGED, ASPECTPATH_CHANGED, CLASSPATH_CHANGED, INPATH_CHANGED, NONSTANDARDOPTIONS_CHANGED, OUTJAR_CHANGED, PROJECTSOURCERESOURCES_CHANGED, OUTPUTDESTINATIONS_CHANGED, INJARS_CHANGED]
22:47:52 Resetting list of modified source files.  Was null
22:47:52 Preparing for build: not going to be incremental because no successful previous full build
22:47:53 Timer event: 576ms: Time to first compiled message
22:47:53 Timer event: 638ms: Time to first woven message
22:48:11 AspectJ reports build successful, build was: FULL
22:48:11 AJDE Callback: finish. Was full build: true
22:48:11 Timer event: 18278ms: Total time spent in AJDE
22:48:11 Timer event: 7ms: Refresh after build
22:48:11 Types affected during build = 159
22:48:11 Timer event: 18325ms: Total time spent in AJBuilder.build()
22:48:11 Timer event: 1ms: Delete markers: GiropayConnector (Finished deleting markers for GiropayConnector)
22:48:11 Timer event: 0ms: Post compile
22:48:41 Timer event: 29863ms: Create markers: GiropayConnector (Finished creating markers for GiropayConnector)


ECLIPSE 3.4 (INCREMENTAL)

22:51:40 ===========================================================================================
22:51:40 Build kind = AUTOBUILD
22:51:40 Project=GiropayConnector, kind of build requested=Incremental AspectJ compilation
22:51:40 File: /home/oliver/projects/GiroPay2009/GiropayConnector/src/main/java/giropay/connect/SmokeTest.java has changed.
22:51:40 build: Examined delta - 1 changed, 0 added, and 0 deleted source files in required project GiropayConnector
22:51:40 Setting list of classpath elements with modified contents:
22:51:40       []
22:51:40 Timer event: 7ms: Pre compile
22:51:40 Sending the following configuration changes to the compiler: []
22:51:40 1 source file changes since last build
22:51:40 Compiler configuration for project GiropayConnector has been read by compiler.  Resetting.
22:51:40      Configuration was []
22:51:40 Resetting list of modified source files.  Was [/home/oliver/projects/GiroPay2009/GiropayConnector/src/main/java/giropay/connect/SmokeTest.java]
22:51:40 Preparing for build: planning to be an incremental build
22:51:40 Starting incremental compilation loop 1 of possibly 5
22:51:40 Timer event: 513ms: Time to first compiled message
22:51:41 Timer event: 956ms: Time to first woven message
22:51:41 AspectJ reports build successful, build was: INCREMENTAL
22:51:41 AJDE Callback: finish. Was full build: false
22:51:41 Timer event: 980ms: Total time spent in AJDE
22:51:41 Timer event: 7ms: Refresh after build
22:51:41 Types affected during build = 1
22:51:41 Timer event: 995ms: Total time spent in AJBuilder.build()
22:51:41 Timer event: 19ms: Post compile
22:51:41 Timer event: 223ms: Delete markers: GiropayConnector (Finished deleting markers for GiropayConnector)



Andy Clement schrieb:

 > as I wrote to Andy an update to Eclipse 3.4 would hopefully solve our problem. The AJDT trace is helpful but it is difficult to > find the "bad" aspects.

As I say, you may not have bad aspects, you may be suffering from using the old analysis code.  I guess just let us know what you find after following Andrews tips.  You didn't mention the scenario where you believe the performance to be poor - is it on an incremental build?  Or is it really the full build? I will say that the goal for an incremental build, if you have the AJDT event trace view open, is that the project involved rebuilds in less than 1second, ideally less than 100ms.  This high level measure is the intention of the AJDT event trace view - it doesn't go into specifics for the pointcuts involved.

Beyond writing good pointcuts, I would say avoid making the project configuration too complicated in a quest for performance - if you start configuring things like 'inpath' then the performance may get worse as the mainline use case we focus all our optimization efforts on at the moment is normal project dependencies.

Andy.

2009/3/22 Oliver Böhm <boehm@xxxxxxxxxx <mailto:boehm@xxxxxxxxxx>>


   Hi Andrew,

   as I wrote to Andy an update to Eclipse 3.4 would hopefully solve
   our problem. The AJDT trace is helpful but it is difficult to find
   the "bad" aspects.

   Since we have the aspect lib under our control I will take a look
   into it and follow your advice to use within() for the right scope.
   Also the tip with the abstract aspects can help us because each
   aspect is already divided into a concrete and an abstract part.
   Perhaps we will extract the concrete part into a separate jar.

   regards
   Oliver



   Andrew Eisenberg schrieb:

       On Sat, Mar 21, 2009 at 3:06 PM, Oliver Böhm <boehm@xxxxxxxxxx
       <mailto:boehm@xxxxxxxxxx>> wrote:

           Hello,

           we use Eclipse 3.3 / ADJT 1.5.3 with Webtools in a project.
           We had big
           problem with one AspectJ lib (patterntesting-check). It has
           some general
           aspects which seems to slow down the compile time a lot. My
           questions:

           * Is the compile time performance of Eclipse 3.4 / AJDT
           1.6.3 much better
           than with AJDT 1.5.3?

       We have done a significant amount of work to ensure that incremental
       compilations are fast.  You will likely see dramatic speedup for
       simple edit-save-compile cycles on non-aspects in Eclipse.  And our
       latest work on the dev builds of AJDT 1.6.5 go even further in this
       direction.

       However, overly generic aspects will still slow the compile down.
       Steps to minimize this are:

       1. Ensure that your aspects are properly scoped through the use of a
       within() pointcut.
       2. Instead of writing a generic aspect, write an abstract
       aspect, that
       can be sub-classed for the specific situations you need it for.
       3. However, neither of these will work for the situation where
       you are
       using a third party aspect.  A proposed feature is to have the
       ability
       for the aop.xml to control weaving scope in static situations.  This
       feature would certainly help your situation.  Andy Clement can talk
       more about this.

       However, I am fairly certain that the problem you are running
       into is
       that in 1.5.3, too many full builds were occurring when there are
       aspects on the aspect path.

           * Are there any "best practices" or performance tips
           available how to use
           AspectJ?


       I assume you are talking about compilation performance, not runtime
       performance.  If so, see above, if not, then ask again.  :-)

           * Is it possible to profile the AspectJ compiler to see,
           which aspects slow
           down the compile time?


       The best thing to do would be to look at the AJDT Event Trace view.
       This view has all sorts of information about what the compiler is
       doing and why it made certain decisions.  I strongly recommend
       moving
       up to a newer version of AJDT.

       Hope this helps,
       --andrew
       _______________________________________________
       aspectj-users mailing list
       aspectj-users@xxxxxxxxxxx <mailto:aspectj-users@xxxxxxxxxxx>

       https://dev.eclipse.org/mailman/listinfo/aspectj-users


   --    Oliver Böhm
   http://www.javatux.de
   _______________________________________________
   aspectj-users mailing list
   aspectj-users@xxxxxxxxxxx <mailto:aspectj-users@xxxxxxxxxxx> ------------------------------------------------------------------------


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

--
Oliver Böhm
http://www.javatux.de
_______________________________________________
aspectj-users mailing list
aspectj-users@xxxxxxxxxxx
https://dev.eclipse.org/mailman/listinfo/aspectj-users