AJDT Event Trace 'Model Sanity Check' improves build performance?!?

[Rob Hadfield]

Hi, I've been tasked to look at performance issues we are having with STS with our medium sized project. Something wierd I've found is that I get a huge usability difference when I change one of the settings on the AJDT Event Trace 'Configure AJDT Event Trace' panel.

(STS Version: 2.5.2.RELEASE Build Id: 201101081000)

I'll click 'Restore default settings' and change some whitespace in a source file. Here's the AJDT Trace output:

11:9:32 ================================================== =========================================
11:9:32 Build kind = AUTOBUILD
11:9:32 Project=tcm, kind of build requested=Incremental AspectJ compilation
11:9:32 Timer event: 0ms: Flush included source file cache
11:9:32 Timer event: 15ms: Check delta
11:9:32 File: <XXX>CaseRecordController.java has changed.
11:9:32 build: Examined delta - 1 changed, 0 added, and 0 deleted source files in required project tcm
11:9:32 Timer event: 0ms: Looking for and marking configuration changes in tcm
11:9:32 Configuration changes found: true
11:9:32 Timer event: 0ms: Look for source/resource changes
11:9:32 Setting list of classpath elements with modified contents:
11:9:32 [C:/rh-workspace2/tcm/src/main/webapp/WEB-INF/classes]
11:9:32 Timer event: 31ms: Pre compile
11:9:32 Sending the following configuration changes to the compiler: []
11:9:32 1 source file changes since last build
11:9:32 Compiler configuration for project tcm has been read by compiler. Resetting.
11:9:32 Configuration was []
11:9:32 Resetting list of modified source files. Was [C:\XXX\CaseRecordController.java]
11:9:32 ClassFileChangeChecking: failed to find a state instance managing output location : C:\rh-workspace2\tcm\src\main\webapp\WEB-INF\classes
11:9:32 ClassFileChangeChecking: queried JDT and 'C:\rh-workspace2\tcm\src\main\webapp\WEB-INF\classes' is apparently unchanged so not performing timestamp check
11:9:32 Preparing for build: planning to be an incremental build
11:9:32 Starting incremental compilation loop 1 of possibly 5
11:9:33 Timer event: 657ms: Time to first compiled message
11:9:33 Timer event: 704ms: Time to first woven message
11:9:33 AspectJ reports build successful, build was: INCREMENTAL
11:9:33 AJDE Callback: finish. Was full build: false
11:9:33 Timer event: 813ms: Total time spent in AJDE
11:9:33 Timer event: 0ms: Refresh after build
11:9:33 Types affected during build = 1
11:9:33 Timer event: 1063ms: Total time spent in AJBuilder.build()
11:9:33 Timer event: 0ms: Update visualizer, xref, advice listeners for (separate thread): tcm
11:9:34 Timer event: 578ms: Delete markers: tcm (Finished deleting markers for tcm)
11:9:47 Timer event: 13250ms: Create markers: tcm (Finished creating markers for tcm)
11:9:47 Created 5341 markers in 763 files

OK, so without going too deply into the trace output, the painful part is quite obvious - after making a simple change I'm having to wait 15 seconds (from the first trace to last). It is pretty consistently this bad.

Now, when I change the trace option to Enable trace output of 'Model Sanity Check' and make a whitespace change to my code I get a slightly different trace:

11:14:33 ================================================== =========================================
11:14:33 Build kind = AUTOBUILD
11:14:33 Project=tcm, kind of build requested=Incremental AspectJ compilation
11:14:33 Timer event: 0ms: Flush included source file cache
11:14:33 Timer event: 15ms: Check delta
11:14:33 File: C:\XXX\CaseRecordController.java has changed.
11:14:33 build: Examined delta - 1 changed, 0 added, and 0 deleted source files in required project tcm
11:14:33 Timer event: 16ms: Looking for and marking configuration changes in tcm
11:14:33 Configuration changes found: true
11:14:33 Timer event: 16ms: Look for source/resource changes
11:14:33 Setting list of classpath elements with modified contents:
11:14:33 [C:/rh-workspace2/tcm/src/main/webapp/WEB-INF/classes]
11:14:33 Timer event: 31ms: Pre compile
11:14:33 Sending the following configuration changes to the compiler: []
11:14:33 1 source file changes since last build
11:14:33 Compiler configuration for project tcm has been read by compiler. Resetting.
11:14:33 Configuration was []
11:14:33 Resetting list of modified source files. Was [C:\XXX\CaseRecordController.java]
11:14:33 ClassFileChangeChecking: failed to find a state instance managing output location : C:\rh-workspace2\tcm\src\main\webapp\WEB-INF\classes
11:14:33 ClassFileChangeChecking: queried JDT and 'C:\rh-workspace2\tcm\src\main\webapp\WEB-INF\classes' is apparently unchanged so not performing timestamp check
11:14:33 Preparing for build: planning to be an incremental build
11:14:33 Starting incremental compilation loop 1 of possibly 5
11:14:33 Timer event: 672ms: Time to first compiled message
11:14:33 Timer event: 719ms: Time to first woven message
11:14:33 AspectJ reports build successful, build was: INCREMENTAL
11:14:33 AJDE Callback: finish. Was full build: false
11:14:33 Timer event: 828ms: Total time spent in AJDE
11:14:33 Timer event: 0ms: Refresh after build
11:14:33 Types affected during build = 1
11:14:34 Timer event: 47ms: Delete markers: tcm (Finished deleting markers for tcm)
11:14:35 Timer event: 1015ms: Create markers: tcm (Finished creating markers for tcm)
11:14:35 Created 5341 markers in 763 files
11:14:36 Crosscutting model sanity checked. The following problems found:
<snipped a bunch of stuff here>
11:14:36
11:14:36 Timer event: 1937ms: Model sanity check for: tcm
11:14:36 Timer event: 3015ms: Total time spent in AJBuilder.build()
11:14:37 Timer event: 0ms: Update visualizer, xref, advice listeners for (separate thread): tcm

The killer for me here is that with additional trace detail it now only takes 4 seconds. And while 4 seconds is still slow, it is a whole lot better than 15 seconds, after which my mind has travelled far away from what I'm supposed to be doing.

This is a huge improvement for me - maybe it will help others? And maybe someone could look in to this because I would not have expected changing trace output to change behaviour in this way.

[Andrew Eisenberg]

There are a few known things going on here. There also might be a bug. Let me explain what is happening.

1.
I'm guessing that the file you are making a whitespace change to is an @AspectJ file with many relationships to Java files. If it is not, then that implies an incremental compilation problem. Every time an aspect changes (even a whitespace change that has no semantic changes), all relationships must be updated since they are dependent on source locations which would be different.


2.
Having the AJDT Event trace view open itself consumes quite a bit of memory. The messages have to be created and sent to the view. And having a large event trace is not particularly memory efficient. Unless need it, I'd recommend keeping the event trace view closed.

3.
You are noticing this:

11:9:47 Timer event: 13250ms: Create markers: tcm (Finished creating markers for tcm)
11:9:47 Created 5341 markers in 763 files

This marker creation is not really part of the build. It is the job that creates all of the markers in the file gutters that help with navigation. The job occurs in a separate low priority background thread and so it should not prevent you from continuing your work. That being said, if you happen to try to save a file that is also having its markers updated, the UI will be locked until marker creation is finished. This is perhaps something that you are hitting. (This is certainly something that we could improve, however).

4.
Since the marker updating is low priority, the thread may pre-empted, depending on system state. This may account for the discrepancy between the two variants of the AJDT event traces that you are showing.

So, my final question to you is how precisely is this discrepancy in times affecting your experience? Are things running slowly? Is the UI blocked?

[Rob Hadfield]

For example if I change a regular java class (actually a unit test), in a Roo managed project (however I'm not running roo at present, nor changing anything that roo needs to be aware of). I save my changes and click the button which triggers my unit tests to run. The UI is still responsive during the 'update markers' operation but my unit tests won't run until after the update markers is complete - 15 seconds later. And I'm not in the habit of carrying on coding until I can see the results of my unit test.

I've seen that on leaving the AJDT trace open, it gets slower and slower to write to (over the course of a few hours) - if I clear the output buffer it starts going much faster again. I appreciate it uses extra resources but observed that it improved the apparent behaviour which is counter-intuitive.

So I think there is a bug somewhere - the behaviour shouldn't change in this way (i.e. better performance) from switching on trace options.

[Andrew Eisenberg]

[QUOTE=Rob Hadfield;345624]For example if I change a regular java class (actually a unit test), in a Roo managed project (however I'm not running roo at present, nor changing anything that roo needs to be aware of). I save my changes and click the button which triggers my unit tests to run. The UI is still responsive during the 'update markers' operation but my unit tests won't run until after the update markers is complete - 15 seconds later. And I'm not in the habit of carrying on coding until I can see the results of my unit test.
[\QUOTE]

I think we (ie- the STS team) need to think about better locking for this operation. I've opened this bug to track it:
https://bugs.eclipse.org/bugs/show_bug.cgi?id=336966

I'm guessing that a good fix for that bug would solve your major problem.

I've seen that on leaving the AJDT trace open, it gets slower and slower to write to (over the course of a few hours) - if I clear the output buffer it starts going much faster again. I appreciate it uses extra resources but observed that it improved the apparent behaviour which is counter-intuitive.

Yes, this view is only meant for debugging and should not be kept open for long sessions. I am hesitant to add an option to automatically trim the output since there have been situations where we have needed to see large amounts of history from users for debugging purposes.

So I think there is a bug somewhere - the behaviour shouldn't change in this way (i.e. better performance) from switching on trace options.

I wouldn't be entirely surprised if enabling model checking somehow forces the Update AJ markers job to start immediately, rather than block on some other job.