Performance problems with Eclipse/STS + Roo Project

[Wolfram]

Hello everyone,

I am experiencing some annoying performance issues working on a Roo project in Eclipse-based IDEs (beyond the usual). I acknowledge that these issues are not Roo-specific but most likely based on all the background work done in Eclipse working with AspectJ/AJDT.

I am working on a Macbook Pro (2.4GHz Core2Duo, 4GB Ram) and am using mostly the Eclipse JavaEE package (+AJDT), sometimes STS 2.3.0. I am deploying to a non-Spring Tomcat 6.0.24 from within the IDE and have only the current project opened. Roo is running from the Terminal, not integrated into the IDE. My Roo project is roughly 25 entities, 10 controllers plus the generated Roo code.

I am most certain that the AspectJ/AJDT background processes are the cause for my problems (more likely: my inability to configure everything to its needs) as I am not experiencing any problems working on non-AspectJ projects.

The symptoms:
Tedious workspace builds and refreshs (like saving a file => having to wait for 10 seconds), high memory consumption (up to 1.6GB in case of STS, leaving me with virtually none memory available) and a irresponsive UI (sometimes a complete "IDE-freeze" for some time). This sounds like "thrashing", as described in the Eclipse help.

The only countermeasure I tried is "tuning" the -vmargs in the eclipse.ini / STS.ini like this (should/can I go up?):

-Xms256m
-Xmx1024m
-XX:PermSize=128m
-XX:MaxPermSize=512m

I know the system requirements for STS state "2GB memory" but am left wondering if a 4GB Macbook is just not enough for working on a Roo project using all the IDE support available by default.

I am interested in any hints, tipps, suggestions you might have that could help me speed up the processes again. I guess a good start would be to get some general configuration from someone who has all this running more vividly (especially for the AspectJ part of it).

Thank you

Wolfram

[Stefan Schmidt]

Wolfram,

I have asked our experts to take a look at this thread. In the meantime, can you confirm that you have enabled JDT weaving in your preferences?

Cheers,
Stefan

[Andy Clement]

Hi Wolfram,

To gain some insight into what AspectJ/AJDT are doing, you can open the AJDT event trace view (Windows>ShowView>AJDT Event Trace). On that window are some configuration options that enable you to see many common events that occur whilst AJDT is running. If you are, for example, seeing full rebuilds when you would only be expecting quick incremental builds - that will be visible in the event trace. Having the view open does have a slight performance impact (as events are not collected when it is closed), but I find it can give a real insight into whether AJDT is doing something you don't expect.

Your memory settings look more than adequate, I work on very large projects and never have more than 1G specified for Xmx.

It is possible there is some characteristic of your project that is causing full builds when they should only be incremental builds - and this would be a bug. Using the event trace it should be obvious if this is the case.

I'm not sure how that will relate to memory consumption though, your project doesn't sound very large. But let's first see what the event trace tells us about your build process.

cheers,
Andy
---
Andy Clement
AspectJ Project Lead

[Christian Dupuis]

Wolfram,

let me ask two questions to get some more information:

1. Are you using Carbon or Cocoa based versions of STS/Eclipse?
2. Could you please check if you have JDT Weaving enabled (Preferences -> JDT Weaving)

If you are using Cocoa please try it with the Carbon version. If you are running without JDT weaving, please try switching it on.

Regards, Christian

[Wolfram]

Thanks for your replies.

1) I am using the Carbon version.
2) JDT weaving is enabled.

I will observe the AJDT event trace and will be back with details. It seems really feasible that complete builds are done. The behaviour definitely feels like it. I am also checking another setup (Windows 7) at home if it behaves any different (starts with half the heap memory with no project opened but is generally the same as soon as the project is open). The project is neither big nor have I done anything of which I would assume that it would interfer with anything aspect-related.

Again, thanks for your answers.

Wolfram

[jeduan]

I have found that having a separate terminal running either

mvn jetty:run

or

mvn tomcat run

helps a lot to deal with the problems you mentioned.

[rvauradkar]

Christian,
I am noticing what I believe is related to this. (using STS 2.3.0 under Windows)
For example. when I am running the PetClinic sample.
1. The project is compiled.
2. I open Pet.java.
3. The AspectJ icon shows up next to the class declaration.
4. I open the Cross References view and click on the icon.
5. The corss reference view shows all the cross-cut behavior.
6. I look at other things in the IDE and come back to Pet.java.
7. Quite often the corss references show nothing. I have to re-inded all over again.
Looks like the cross references are being lost for no reason. JDT weaving is enabled.
Am I doing soemthing wrong?
Regards,
Raj

[Christian Dupuis]

Raj,

could you attach the output of Windows -> ShowView -> AJDT Event Trace as mentioned by Andy? This would help us understand what's going on.

Thanks, Christian

[Wolfram]

Looking at the AJDT event trace it seems to me that everything is in order. It starts with (just one time after opening the project as it is supposed to):

Compiler configuration for project rootestproject doesn't know previous state, so assuming EVERYTHING has changed.

After a small local change in a source file + save:

Build kind = AUTOBUILD
kind of build requested=Incremental AspectJ compilation
Preparing for build: not going to be incremental because no successful previous full build
AspectJ reports build successful, build was: INCREMENTAL
Timer event: 11733ms: Total time spent in AJBuilder.build()

After that another build is done, which is the first incremental build. Then, a third build is started but no changes are found and the build exits.

This all seems ok, and at this point the performance still is ok, might be a memory problem after all. The trace seems also ok when changing a public method name and other files need to be recompiled. One or two incremental builds are run plus another one that exits due to an empty delta.

What happens if I save a file with errors (I do press cmd+s a lot)? Andy indicated in his answer on another question by me that this might cause problems. That sounds reasonable to me, especially when Roo deletes its ".aj" files in the background due to a broken ".java" source.

Also: Is it "normal" that an out-of-the-box STS 2.3.0 takes up 900MB of memory shortly after starting with one small Roo project (AspectJ) and only one source file opened? As I already mentioned this goes up to 1.6GB easily and might go even higher (no more memory available). I do have about 10 files open at a time.

[rvauradkar]

Christian,
Here is the output you requested from "Windows -> ShowView -> AJDT Event Trace ". (FYI: Please note this is for a different project and not the PetClinic I mentioned)

9:31:38 Startup information:
AJDT version: 2.0.1.e35x-20091001-1600 for Eclipse 3.5
AspectJ Compiler version: 1.6.6
usingVisualiser=true
usingXref=true
usingCUprovider=true
promptForAutoOpenCrossReference = false
ajde.version.at.previous.startup = @AJDEVERSION@
11:35:2 Building AJ code scanner
11:35:2 Editor opened on Service_Roo_Entity.aj
11:42:28 ================================================== =========================================
11:42:28 Build kind = AUTOBUILD
11:42:28 Project=uml, kind of build requested=Incremental AspectJ compilation
11:42:28 Timer event: 0ms: Flush included source file cache
11:42:29 Timer event: 156ms: Check delta
11:42:29 File: C:\misc\roo-projects\uml\src\main\java\com\ampf\uml\domain\Ser vice_Roo_Entity.aj has changed.
11:42:29 build: Examined delta - 1 changed, 0 added, and 0 deleted source files in required project uml
11:42:29 Timer event: 16ms: Looking for and marking configuration changes in uml
11:42:29 Configuration changes found: true
11:42:29 Timer event: 16ms: Look for source/resource changes
11:42:29 Setting list of classpath elements with modified contents:
11:42:29 []
11:42:29 Timer event: 203ms: Pre compile
11:42:29 Sending the following configuration changes to the compiler: []
11:42:29 1 source file changes since last build
11:42:29 Compiler configuration for project uml has been read by compiler. Resetting.
11:42:29 Configuration was []
11:42:29 Resetting list of modified source files. Was [C:\misc\roo-projects\uml\src\main\java\com\ampf\uml\domain\Ser vice_Roo_Entity.aj]
11:42:29 Preparing for build: planning to be an incremental build
11:42:29 Starting incremental compilation loop 1 of possibly 5
11:42:32 Timer event: 3484ms: Time to first compiled message
11:42:32 Timer event: 3515ms: Time to first woven message
11:42:32 AspectJ reports build successful, build was: INCREMENTAL
11:42:32 AJDE Callback: finish. Was full build: false
11:42:32 Timer event: 3532ms: Total time spent in AJDE
11:42:32 Timer event: 0ms: Refresh after build
11:42:32 Types affected during build = 1
11:42:32 Timer event: 16ms: Update visualizer, xref, advice listeners for (separate thread): uml
11:42:32 Timer event: 3984ms: Total time spent in AJBuilder.build()
11:42:33 ================================================== =========================================
11:42:33 Build kind = AUTOBUILD
11:42:33 Project=uml, kind of build requested=Incremental AspectJ compilation
11:42:33 Timer event: 31ms: Augmenting aspect path with args from builder
11:42:33 Timer event: 0ms: Flush included source file cache
11:42:33 Timer event: 0ms: Check delta
11:42:33 File: C:\misc\roo-projects\uml\src\main\java\com\ampf\uml\domain\Ser vice_Roo_Entity.aj has changed.
11:42:33 build: Examined delta - 1 changed, 0 added, and 0 deleted source files in required project uml
11:42:33 Timer event: 16ms: Looking for and marking configuration changes in uml
11:42:33 Configuration changes found: true
11:42:33 Timer event: 16ms: Look for source/resource changes
11:42:33 Setting list of classpath elements with modified contents:
11:42:33 []
11:42:33 Timer event: 109ms: Pre compile
11:42:33 Sending the following configuration changes to the compiler: []
11:42:33 1 source file changes since last build
11:42:33 Compiler configuration for project uml has been read by compiler. Resetting.
11:42:33 Configuration was []
11:42:33 Resetting list of modified source files. Was [C:\misc\roo-projects\uml\src\main\java\com\ampf\uml\domain\Ser vice_Roo_Entity.aj]
11:42:33 Preparing for build: planning to be an incremental build
11:42:33 Starting incremental compilation loop 1 of possibly 5
11:42:33 Timer event: 485ms: Time to first compiled message
11:42:33 Timer event: 532ms: Time to first woven message
11:42:33 AspectJ reports build successful, build was: INCREMENTAL
11:42:33 AJDE Callback: finish. Was full build: false
11:42:33 Timer event: 531ms: Total time spent in AJDE
11:42:33 Timer event: 0ms: Refresh after build
11:42:33 Types affected during build = 1
11:42:33 Timer event: 63ms: Update visualizer, xref, advice listeners for (separate thread): uml
11:42:33 Timer event: 781ms: Total time spent in AJBuilder.build()
11:42:34 Timer event: 0ms: Delete markers: uml (Finished deleting markers for uml)
11:42:35 Timer event: 797ms: Create markers: uml (Finished creating markers for uml)
11:42:35 Created 32 markers in 1 files
11:42:35 Timer event: 203ms: Delete markers: uml (Finished deleting markers for uml)
11:42:38 Timer event: 3110ms: Create markers: uml (Finished creating markers for uml)
11:42:38 Created 343 markers in 65 files
11:42:39 ================================================== =========================================
11:42:39 Build kind = AUTOBUILD
11:42:39 Project=uml, kind of build requested=Incremental AspectJ compilation
11:42:39 Timer event: 0ms: Flush included source file cache
11:42:39 Timer event: 0ms: Check delta
11:42:39 Timer event: 0ms: Looking for and marking configuration changes in uml
11:42:39 Configuration changes found: false
11:42:39 build: Examined delta - no source file or classpath changes for project uml
11:42:39 Compiler configuration for project uml has been read by compiler. Resetting.
11:42:39 Configuration was []
11:42:39 Resetting list of modified source files. Was []
11:42:39 Timer event: 47ms: Look for source/resource changes
11:42:39 No source/resource changes found, exiting build
11:42:39 Timer event: 94ms: Total time spent in AJBuilder.build()


Regards,
Raj