Announcement Announcement Module
Collapse
No announcement yet.
Performance problems with Eclipse/STS + Roo Project Page Title Module
Move Remove Collapse
X
Conversation Detail Module
Collapse
  • Filter
  • Time
  • Show
Clear All
new posts

  • Performance problems with Eclipse/STS + Roo Project

    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?):

    Code:
    -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

  • #2
    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

    Comment


    • #3
      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

      Comment


      • #4
        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

        Comment


        • #5
          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

          Comment


          • #6
            I have found that having a separate terminal running either
            Code:
            mvn jetty:run
            or
            Code:
            mvn tomcat run
            helps a lot to deal with the problems you mentioned.

            Comment


            • #7
              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

              Comment


              • #8
                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

                Comment


                • #9
                  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):
                  Code:
                  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:
                  Code:
                  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.
                  Last edited by Wolfram; Feb 24th, 2010, 08:04 AM.

                  Comment


                  • #10
                    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
                    Last edited by rvauradkar; Feb 24th, 2010, 11:44 AM. Reason: Adding more information

                    Comment


                    • #11
                      I have another excerpt from my AJDT trace with some "suspicious" actions.

                      Here is the log (did not leave any message out, the "delete markers" message comes right after the "create x markers" also with no further action by me):
                      Code:
                      16:18:7 Timer event: 909ms: Total time spent in AJBuilder.build()
                      16:18:7 Timer event: 5ms: Update visualizer, xref, advice listeners for (separate thread): myapp
                      16:18:8 Timer event: 248ms: Delete markers: myapp (Finished deleting markers for myapp)
                      16:18:14 Timer event: 6056ms: Create markers: myapp (Finished creating markers for myapp)
                      16:18:14 Created 1737 markers in 247 files
                      16:18:14 Timer event: 284ms: Delete markers: myapp (Finished deleting markers for myapp)
                      16:18:20 Timer event: 6202ms: Create markers: myapp (Finished creating markers for myapp)
                      16:18:20 Created 1737 markers in 247 files
                      Right know, this happens every time I save a file, even when the only thing I did was deleting a whitespace character. All markers are deleted and created again, "sometimes" even twice. I can not find any trace messages corresponding to why this is done.
                      This behaviour does not appear right after starting up STS but I am unable to say at which point it changes.

                      (I guess this does not really belong in the Roo forum anymore as I am not even running Roo at this point.)
                      Last edited by Wolfram; Mar 2nd, 2010, 09:38 AM. Reason: Realized that this might be the wrong place

                      Comment


                      • #12
                        Hi,

                        In the top right of the event trace view you can choose the message granularity, if you turn everything ON it should give you an indication of what is happening to lead to those marker messages.

                        Andy

                        Comment


                        • #13
                          Thanks for your reply.
                          The output actually was from a trace with everything included. I do not know why all markers are deleted and recreated (twice) every time the workspace is built or even if it has to be that way (I guess and hope not).

                          For now, I deactivated automatic building and CMD+B when I want it to build. So far that works for me and even the ~6 to 12 seconds wait is easier to cope with as it appears "onkeypress" and not implicitely on saving.

                          In the long run, I will of course have to find out what causes this behaviour as a 12 second loss on each save with no functional changes made is really annoying.

                          Comment


                          • #14
                            Originally posted by Wolfram View Post
                            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):
                            Code:
                            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:
                            Code:
                            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()
                            I'm slightly confused by the message that says "not going to be incremental" being immediately followed by "build was: INCREMENTAL". 11seconds for an incremental build is an eternity ... But I guess as long as it settles down, I won't worry too much about that.

                            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.
                            That is interesting, you might be right about some interplay with the build in eclipse and when Roo is deleting/adding files in the background. Updating an aspect will probably just result in an incremental builld, but the addition or removal of aspects is actually likely to lead to full builds rather than incremental builds. hmmm... I'll talk to Ben (Alex) about this.

                            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.
                            that sounds a lot... I have 900Meg for my huge AspectJ projects, but not for something like petclinic Roo... do you have yourkit or something similar to give us an idea where the memory goes?

                            Andy

                            Comment


                            • #15
                              Hi,

                              I also experience these 10-20 seconds wait time on each save (on larger projects it can even take longer) with STS on roo projects. Setup is WinXP SP3, JDK6u18, STS2.3.0 but upgraded m2eclipse to 0.9.9!

                              Just as a small hint: In default roo projects there is also the maven builder which comes into play!

                              Here is the .project file of a simple roo project I created. It shows a bunch of builders:
                              Code:
                              <?xml version="1.0" encoding="UTF-8"?>
                              <projectDescription>
                              	<name>roo-test</name>
                              	<comment></comment>
                              	<projects>
                              	</projects>
                              	<buildSpec>
                              		<buildCommand>
                              			<name>org.eclipse.wst.jsdt.core.javascriptValidator</name>
                              			<arguments>
                              			</arguments>
                              		</buildCommand>
                              		<buildCommand>
                              			<name>org.eclipse.wst.common.project.facet.core.builder</name>
                              			<arguments>
                              			</arguments>
                              		</buildCommand>
                              		<buildCommand>
                              			<name>org.eclipse.wst.validation.validationbuilder</name>
                              			<arguments>
                              			</arguments>
                              		</buildCommand>
                              		<buildCommand>
                              			<name>org.eclipse.ajdt.core.ajbuilder</name>
                              			<arguments>
                              			</arguments>
                              		</buildCommand>
                              		<buildCommand>
                              			<name>org.springframework.ide.eclipse.core.springbuilder</name>
                              			<arguments>
                              			</arguments>
                              		</buildCommand>
                              		<buildCommand>
                              			<name>org.maven.ide.eclipse.maven2Builder</name>
                              			<arguments>
                              			</arguments>
                              		</buildCommand>
                              	</buildSpec>
                              	<natures>
                              		<nature>org.maven.ide.eclipse.maven2Nature</nature>
                              		<nature>org.eclipse.wst.common.project.facet.core.nature</nature>
                              		<nature>org.eclipse.jdt.core.javanature</nature>
                              		<nature>org.eclipse.wst.common.modulecore.ModuleCoreNature</nature>
                              		<nature>org.eclipse.jem.workbench.JavaEMFNature</nature>
                              		<nature>org.eclipse.ajdt.ui.ajnature</nature>
                              		<nature>com.springsource.sts.roo.core.nature</nature>
                              		<nature>org.springframework.ide.eclipse.core.springnature</nature>
                              		<nature>org.eclipse.wst.jsdt.core.jsNature</nature>
                              	</natures>
                              </projectDescription>
                              Also I found out that in my case most of the build time (and the afterwards occuring "validation" phase) is spend with getting the xsds for the spring (and spring security/ integration) xml files. It seems as if STS requests the xsds from the web instead of using the ones inside the according jar files.

                              @Wolfram Can you assure this isn't the case in your scenario?

                              Regards
                              Alex

                              Comment

                              Working...
                              X