Bug 245566 - [plan] [incremental] Reduce overhead in preparing for incremental compiles
Summary: [plan] [incremental] Reduce overhead in preparing for incremental compiles
Status: RESOLVED FIXED
Alias: None
Product: AspectJ
Classification: Tools
Component: Compiler (show other bugs)
Version: unspecified   Edit
Hardware: PC Windows XP
: P2 critical (vote)
Target Milestone: 1.6.2   Edit
Assignee: aspectj inbox CLA
QA Contact:
URL:
Whiteboard:
Keywords:
Depends on:
Blocks:
 
Reported: 2008-08-28 13:43 EDT by Andrew Clement CLA
Modified: 2012-04-03 14:12 EDT (History)
1 user (show)

See Also:


Attachments
implementation of AspectJ incremental building opimizations (131.05 KB, patch)
2008-09-06 00:49 EDT, Andrew Eisenberg CLA
aclement: iplog+
Details | Diff
mylyn/context/zip (452.95 KB, application/octet-stream)
2008-09-06 00:50 EDT, Andrew Eisenberg CLA
no flags Details
patch and test for validating classpath before build (7.67 KB, patch)
2008-09-08 13:03 EDT, Andrew Eisenberg CLA
aclement: iplog+
Details | Diff
Patch to fix some Core tests that were affected by previous patch (11.29 KB, patch)
2008-09-08 14:16 EDT, Andrew Eisenberg CLA
aclement: iplog+
Details | Diff

Note You need to log in before you can comment on or make changes to this bug.
Description Andrew Clement CLA 2008-08-28 13:43:18 EDT
Too much time is spent messing about getting ready for an incremental compile - fix it!
Comment 1 Andrew Clement CLA 2008-08-28 14:00:16 EDT
New test suite 'IncrementalPerformanceTests'.

I've used the RunWeaveTests that Noel Markham wrote a long time ago to generate some java code.  I have 2 projects now, a 64 class one and a 512 class one.  But just looking at the 64 class one for now.  The aim is to full build it, then touch a source file and do an incremental build.  Using a profiler we can see where time is spent in between the testsuite asking for an incremental build and compilation actually occurring.

Here is typical test output right now for testBuildingProject64Files():

Full build time: 3203ms
Incr build time: 172ms

(Thinkpad T61p)

Measuring the overhead we see that we enter AjCompiler.build():

AjCompiler.build() 171ms
- AjState.prepareForNextBuild() 140ms (!)
- AjState.getFilesToCompile() 15ms
- AjdeCoreBuildManager.genAjBuildConfig 15ms

The actual compilation and weaving was so quick it didnt register...

And the hotspots in compilation were:

File.lastModified(), File.getCanonicalPath(), File.listFiles(), File.isDirectory(), File.isFile(), AbstractSet.removeAll(), String.endsWith(), File.getAbsolutePath()

lastModified() accounting for 62ms of the time.
Comment 2 Andrew Clement CLA 2008-08-28 14:14:13 EDT
oops - my mistake, the compile time does register.  but that isn't what I'm investigating here.  First job is to tackle this I think:

- AjdeCoreBuildManager.genAjBuildConfig 15ms

I want to have the build config just get reused if nothing has changed, and not rebuild a new one each time.  I need that in place before tackling the big prepareForNextBuild problem.
Comment 3 Andrew Clement CLA 2008-08-28 16:41:53 EDT
I have added to the ICompilerConfiguration interface.  There are two new methods:

int getConfigurationChanges();

void configurationRead();

The first returns a set of bitflags indicating if any of the configuration have changed since it was last processed.  The method configurationRead() is called by the compiler once the configuration has been processed and compilation is proceeding.  Basically once a configurationRead() event has occurred, a well behaved compilerconfiguration should track changes to other settings (classpath/sourcefiles/etc) and return appropriate bits on getConfigurationChanges().  The compiler can then reduce the amount of work it does based on changes to the configuration.

A lazy ICompilerConfiguration implementation can just return EVERYTHING for getConfigurationChanged() and AspectJ will behave as it always did.

I've put in these two APIs and done some basic testing - it seems to work nicely.

I then used the new support to add a simple optimization to prepareForNextBuild().  I changed the path detection logic to avoid comparing paths if the compiler configuration did not report them as changed:
ASPECTPATH_CHANGED, CLASSPATH_CHANGED, INPATH_CHANGED, etc.

Due to the fact that I can just return EVERYTHING if I want to see the old behaviour, I can easily compare performance with and without the new optimizations :)

So, returning EVERYTHING, incremental build time is 172ms.
Returning NO_CHANGES (which is true in our scenario with no changes for the incremental build): 47ms

so it takes 70% less time and this is just the beginning.

Now, there is a gotcha here.  It places more responsibility on the compiler invoker to track changes and know what it needs to tell AspectJ about, whereas previously AspectJ always did the right thing due to doing a very very thorough analysis of whether changes had occurred (and thats what was killing performance).

A problem I can already foresee with the optimization I have made is that it is the callers responsibility to know whether a file on the classpath has changed (as opposed to whether the classpath itself has changed).  In an eclipse scenario, suppose project A had project B on the classpath.  if project B is rebuilt then although the classpath for project A has not changed, the files upon that classpath may have changed and AspectJ won't go and check it unless the getConfigurationChanges() method returns CLASSPATH_CHANGE.  However, it should be OK since I think it is reasonable for AJDT to track that project B got compiled and it knows project A has it on its classpath and should return CLASSPATH_CHANGE.  Effectively we are optimizing around a situation where a user is just editing a single file and wants a super fast response on save - in that scenario we should limit path analysis.

Comment 4 Andrew Clement CLA 2008-08-28 16:55:03 EDT
I forgot to mention, with the introduction of the two new methods, I've removed the time spent in AjdeCoreBuildManager.genAjBuildConfig() since we don't need to do it anymore on incremental compiles unless something has changed.  Currently any indicated change will trigger it to be rebuilt but as use of the interface grows I will change it to reconstruct parts of the config based on what has changed.
Comment 5 Andrew Clement CLA 2008-08-28 17:58:55 EDT
Further enhancements before I commit something.

I enhanced the getModifiedFiles() calculation in AjState to use any configuration supplied information (if available) rather than calculating it by itself (by calling lastModifiedTime() for every source file in the project).

The ICompilerConfiguration interface has a getProjectSourceFilesChanged().  Returning null from this method indicates the compiler invoker doesnt know and AspectJ should go through checking the timestamps as before.  If the invoker does know, it should return a List<File> that indicate the files it knows have changed, and AspectJ will trust it and not perform the expensive timestamp check.

After this I observed a lot of Set manipulation to determine whether any files have been added or deleted since the previous build.  I put in a guard that avoids any of this set manipulation if the configuration did not indicate tell me that PROJECTSOURCEFILES_CHANGED when getConfigurationChanges() was called.

What remained after this was the cost of actual compilation plus an expensive call to getLibraryAccess() made in AjBuildManager.performCompilation().  I think the return value of that can be cached, but I won't tackle that just yet.  I'd like to see the impact of AJDT implementing the interfaces so far defined.

With these changes, I was able to further improve the time taken to do an incremental build where nothing has changed.  if nothing has changed and the method getProjectSourceFilesChanged() is correctly implemented to indicate an empty list (meaning yes I do know what's changed and it is nothing).  Then the time taken for an incremental build is 0 (too low to measure).
Comment 6 Andrew Clement CLA 2008-08-28 20:17:14 EDT
initial changes are now in AspectJ.  Just moving them across to AJDT now.  I will likely initially do a dumb implementation of the new methods just to make sure nothing breaks.  Then work with Andrew on a more optimal implementation.

there is no reason these changes can't make it into both AJDT 1.5 and 1.6
Comment 7 Andrew Clement CLA 2008-08-29 13:11:35 EDT
New AspectJ is now in AJDT 1.6.  The implementation of the interface is basically:

	public int getConfigurationChanges() {
		return EVERYTHING;
	}

Which causes AJDT to behave as 'normal'.

Now there are two routes to proceed down and as AJDT support these things, AspectJ will get faster and faster.

1) Need to properly implement 'getConfigurationChanges()' - so that it returns the right set of bitflags for what has changed.  Always better to err on the side of caution so if not sure, say it has changed.

2) Support monitoring the list of changed files that have led to the need to build and return the list from getProjectSourceFilesChanged().  I'll attach the beginnings of a patch for this.


Comment 8 Andrew Eisenberg CLA 2008-08-29 14:40:02 EDT
Great.  This should help a lot.

From the AJDT side, all I need to do is properly implement getConfigurationChanges?  Are there any other API changes?  (When I say "all", I don't mean to imply that this is a trivial fix.  I think there will be some complexity here.) 
Comment 9 Andrew Clement CLA 2008-08-29 15:08:53 EDT
Properly implementing that method is the start yes.  At the same time implementing getProjectSourceFilesChanged() which will show us some immediate benefits.  I have an impl for that but my eclipse is playing up and wont run any tests successfully, so I haven't provided it yet.  you can probably write it yourself in 5mins...

Things I'm currently wondering are:
- inter project dependencies, do they always manifest as the dependee project considering it has a CLASSPATH_CHANGE
- if a group of files are changed across multiple projects, does the build delta include all changes for all projects or just those for its own project?  getProjectSourceFilesChanged() needs to return a subset of what it originally specified in getProjectSourceFiles() - and not source files in other projects.

Seems like there are some tricky scenarios to get testcases setup for.

I would think we initially want some project level setting in the UI where this funky behaviour can be turned on and off, so we can offer it out to people to test by turning it on for their projects.
Comment 10 Andrew Eisenberg CLA 2008-08-29 15:33:46 EDT
OK...I see think I see the process now:

1. Whenever a configuration element changes, add it to the compiler configuration. (this will likely occur sporadically eg- whenever the .classpath changes, or whenever the .project changes, I don't think this would be possible to determine from the ResourceDelta provided by the platform as a build is happening).
2. When we know of files that have changes add it to the compiler configuration (we can get this from the ResourceDelta during a build).
3. The compiler will call getConfigurationChanges() and getProjectSourceFilesChanged() at some point during or before compilation.
4. This will be followed by a call to configurationRead() and resetModifiedList(), which will presumably state that the compiler is done with reading the changes.  This will signal to the compiler configuration to reset its changed list.
5.  The process will start over again as changes continue to happen.

Is this a correct interpretation?

I need to be careful in that the CoreCompilerConfiguration and UICompilerConfiguration classes are created and discarded in several places.  I need to ensure that the same configurations are used throughout a build.  Or we can even keep the object over multiple builds.
Comment 11 Andrew Clement CLA 2008-08-29 15:59:46 EDT
almost.  resetModifiedList() is not on the interface, just a temporary method I was using from AJBuilder to reset what I was tracking.  Now configurationRead() has been added, that can be the proper lifecycle method to let you know I've checked all changes and checked for modified files.

Maintaining a compilerconfig instance for each project (whilst it is open) sounds a good plan rather than rebuilding one each time.  But I'm not sure what other objects already exist to track what are the source files in the project/etc.  If someone else is already tracking that, maybe they need to be made to implement ICompilerConfiguration and the current impl is discarded (just a thought).

I think I'll work on the other side of the interface so I do more granular updates depending on the combination of flags returned - currently returning anything except NO_CHANGES means behave like we used to. 
Comment 12 Andrew Eisenberg CLA 2008-08-29 17:04:12 EDT
Starting to understand the setup a bit more.  There are 2 implementations of ICompilerConfiguration.  One for ajdt.core and one for ajdt.ui.  The only difference between the two is that the core implementation has a no-op version of getNonStandardOptions (returns and empty string), whereas the UI implementation builds the getNonStandardOptions value from the AspectJPreferences stored for the project.

When the ajdt.ui plugin is present, the UI implementation is used.  When not present (presumably for running AJDT headless), the Core implementation is used.

Note that the AspectJPreferences class has some dependency on a JFace class and hence cannot be moved to the core plugin.

I think we are stuck with two implementations of ICompilerConfiguration.

I am going to update some comments so it is more clear when each implementation is used.
Comment 13 Andrew Eisenberg CLA 2008-08-29 17:13:24 EDT
Seems like the CompilerConfiguration objects, which are attached to AjCompiler objects (and there is generally one for each Aj open project) are destroyed in the following circumstances:

1. a clean of the project
2. AJ nature is removed
3. Project is closed
4. Project is deleted

The CompilerConfiguration seems to be created just before a build, although it could be created at any time because access to the CompilerConfigurationFactory is globally accessible through AspectJPlugin.

This is good news and it means that we can have the compiler configuration store state changes when they occur.

I did notice some unfortunate naming conventions in the ajdt.ui and ajdt.core projects.  Both plugins have classes named ResourceDeltaVisitor and ResourceDeltaListener, but they do very different things.  I renamed them to be more expressive. (will submit a patch later.)
Comment 14 Andrew Clement CLA 2008-08-29 17:21:27 EDT
I've modified AspectJ to share the name environment across compiles - for quick resolution of basic type information.  previously a new name environment was built every time.  I'm not 100% sure that it won't cause us some kind of problem down the line, but I've coded defensively and it passes all the tests we have.  I will try it out in AJDT shortly.  Again, like the other enhancements so far, it will only behave if we can get to a point where getConfigurationChanges() can return NO_CHANGES
Comment 15 Andrew Eisenberg CLA 2008-08-29 17:31:23 EDT
Presumably, the file names expected by the compiler are fully qualified?
Comment 16 Andrew Eisenberg CLA 2008-08-29 17:32:23 EDT
And does it only care about *.java and *.aj files since the builder handles the copying of non-Java resources?
Comment 17 Andrew Clement CLA 2008-08-29 17:42:33 EDT
yes, just fully qualified source files.
Comment 18 Andrew Clement CLA 2008-09-02 11:36:44 EDT
I've spent the weekend playing in this area of code again.  I wanted to improve the situation for multi-project configurations.  I think I now have a further extension that will speed them up.

I want CLASSPATH_CHANGE to mean only that (surprise surprise) the classpath has changed, ie. it used to be a;b;c and now it is a;d;b;c or somesuch.  I don't want it to mean something has changed in a folder on the classpath.  Whether this latter situation has occurred will be answered through a ICompilerConfiguration call:

/**
 * Return a List (Strings) of the directory elements on the classpath that 
 * are likely to contain modified .class files since the
 * previous build and must be checked. This would be used in the situation
 * where a project has a dependency on another project
 * and the dependency is captured by inclusion of one project on the 
 * classpath for the other. When the first project is built,
 * we need to check the classpath element on the second projects classpath 
 * that represents the bin folder of the first project.
 * By explicitly returning a list here we can avoid checking EVERYTHING.
 * 
 * @return a list of modified elements that should be checked (can be empty)
 *         or null if unknown (and in which case every
 *         classpath element will be checked)
 */
public List getClasspathElementsWithModifiedContents();

It is very similar to the call for getting a list of modified source files.  The idea is to reduce the amount of checking of classpath directories.  It relies on the surrounding environment (AJDT) knowing how project dependencies are captured and what the output folders are for projects that other projects are depending upon.
Comment 19 Andrew Eisenberg CLA 2008-09-02 11:53:39 EDT
Getting there.  I have the code mostly written and tested.  I'm just cleaning up the test cases and should have something soon.

Here is what I am doing:

1) checking for changed .java and .aj source files by examining the ResourceDelta at the start of a build.
2) Checking for changed resource files in source folders also by examining the build (this occurs when AJBuilder copies over the new or changed source files and deletes old ones).
3) Check for changes in the .classpath file.  Any changes to .classpath and AJBuilder sets the ASPECTPATH_CHANGED, INPATH_CHANGED IN_PATH, and CLASSPATH_CHANGED flags (all of them).  Just being conservative.
4) All other flags are being ignored (ie- ICompilerConfiguration.getConfigurationChanges always returns those flags as set so the aj compiler must check that part of the configuration before *every* build).

At this point, I am trying to do something simple, but will also lead to some significant improvements.
Comment 20 Andrew Eisenberg CLA 2008-09-02 12:18:29 EDT
Regarding comment 18, I hadn't seen it until just now.

The first part is OK.  CLASSPATH_CHANGE will only be set when the actual classpath changes (or at least the .classpath file is touch, a conservative approximation).

The second part will be some work.  

First question/assumption: if I ignore this method and return null, then the compiler will behave as before with no bad effects?

Second: I think you are saying that this method expects a list of classpath entries that have recently changed or been rebuilt.  This will happen if project A depends on project B, B gets rebuilt, and then A will have an entry in getClasspathElementsWithModifiedContents when it is rebuilt.

For this, AJDT needs to keep track of reverse dependencies between projects.  It gets trickier if Project B depends on a class folder or out jar in project A.  I'll have to think about this.
Comment 21 Andrew Clement CLA 2008-09-02 12:46:53 EDT
Answering the questions from comment 20

- First question/assumption: if I ignore this method and return null, then the
compiler will behave as before with no bad effects?

If you ignore this then you will need to return CLASSPATH_CHANGE when you need AspectJ to check the contents of entries on the classpath.  So effectively you will always be returning CLASSPATH_CHANGE if the project has any kind of dependency on another project.  This is why returning EVERYTHING when asked what has changed causes AJ to behave exactly as before.  I think the method for getting modified source files improves incremental performance of a single project whilst this new method improves incremental performance of a project in a multi-project setup.  So all users get a benefit.  If we just get the first case working initially, that is fine, but CLASSPATH_CHANGE will need to always be set.  Then when we have a working getClasspathElementsWithModifiedContents() we can change CLASSPATH_CHANGE to indicate its ideal meaning that there is a real classpath change.

- Second: I think you are saying that this method expects a list of classpath
entries that have recently changed or been rebuilt.  This will happen if
project A depends on project B, B gets rebuilt, and then A will have an entry
in getClasspathElementsWithModifiedContents when it is rebuilt.

Yes, exactly.  I'm presuming the project dependency eventually manifests as putting all the output folders of B on the classpath of A?  In which case those folders would be the return value of getClasspathElementsWithModifiedContents().  I'm hoping it is less costly for AJDT to work that out (hopefully it already knows it based on the build methods being called on the various projects?) than it is for AspectJ to go through every .class file in every directory on the project A classpath.  I'm further assuming that inpath/aspectpath entries are automatically included on the classpath and so don't need processing separately.

- For this, AJDT needs to keep track of reverse dependencies between projects. 
It gets trickier if Project B depends on a class folder or out jar in project
A.  I'll have to think about this.

Is it really a reverse dependency?  I thought when build() is called for project A you would already know it depends on project B and when the classpath is built for project A (which ajdt returns for getclasspath) it will include the output folder from project B after seeing it as a project dependency?  I don't want to introduce extra overhead into AJDT unless necessary since that is just moving the cost from AspectJ to AJDT.

I am not a fan of circular dependencies so if project B depends on a class folder of A, you could just 'give up' and return null and CLASSPATH_CHANGE and leave everything to AspectJ.  There is no harm in optimizing the expected scenario and giving people guidelines that it will suck if they create complex setups.

---

I would like to see a UI switch if it isn't too much work -
it'll enable us to do proper benchmarking with/without changes (as well as
enabling us to turn it off if it misbehaves - a bit like pipeline compilation
in the compiler).  Hopefully it won't be too messy to guard some of the changes
you are making with a check on the UI setting.

I've also found that an assumption I previously held was incorrect - I thought
asking a file for lastModifiedTime would be faster than trawling a huge data
structure but it seems I am wrong.  It might be the slow hard disk in this
laptop but the numbers indicate it is cheaper to search the data structure.  So
I'm going to switch around a test we do when walking the classpath.  We
previously checked the mod time and if it looked like a change we would search
a data structure to confirm it - we will now just trawl the data structure and
skip the mod time check.  I can do more in this area if it appears to help the
situation.

In my profiling I'm also discovering that the log calls about incremental
decisions we make are becoming increasingly the hot spots where most cpu time
is spent (since I'm fixing every other hotspot...).  It looks like the
CountingMessageHandler is partly to blame, but also I want to make sure that
when the AJDT event trace view is shut that the listeners are definetly not
registered and so the 'decision messages' from the compiler are never produced.

So - i will finish off on this new method on the interface, make the change
around I discussed in paragraph 2 a switchable thing (so AJDT could select the
behaviour to try out - not in the UI but with a simple code tweak) - and call
that the first bunch of changes complete.  We can then test/profile and move
forward from there.
Comment 22 Andrew Clement CLA 2008-09-04 15:16:30 EDT
New method on AsmManager


	/**
	 * @return the Set of files for which the structure model was modified
	 */
	public Set getModelChangesOnLastBuild() {
		return lastBuildChanges;
	}

After an incremental build will return Set<File> for which the model was repaired.

Need to test if that is sufficient.  It might be that the files on the 'other end' of any relationships hitting this file need including.  It should be possible to determine the other ends by looking at relationships affecting these files (all relationships are two way) - but whether it is more expensive to compute that in AJDT or record it in AspectJ and expose it to AJDT, i'm not sure.
Comment 23 Andrew Eisenberg CLA 2008-09-06 00:49:50 EDT
Created attachment 111895 [details]
implementation of AspectJ incremental building opimizations

This patch contains an implementation of the build optimizations.  All the changes stem from the ICompilerConfiguration interface.

For now, this only deals with source, resource, classfile, inpath, and aspect path changes.  Other compiler configuration pieces are not checked for.

(I'm also attaching a mylyn context.  Might be helpful for others.)
Comment 24 Andrew Eisenberg CLA 2008-09-06 00:50:05 EDT
Created attachment 111896 [details]
mylyn/context/zip
Comment 25 Andrew Clement CLA 2008-09-06 11:16:00 EDT
I've applied it... but when I turn it on in my eclipse and then make a whitespace change and save:

8:12:22 Build kind = AUTOBUILD
8:12:22 Project=shadows.org.eclipse.jdt.core, kind of build requested=Incremental AspectJ compilation
8:12:22 File: C:\asc\ws\debugws-ajdt16\shadows.org.eclipse.jdt.core\eval\org\aspectj\org\eclipse\jdt\internal\eval\CodeSnippetAllocationExpression.java has changed.
8:12:22 build: Examined delta - 1 changed, 0 added, and 0 deleted source files in required project shadows.org.eclipse.jdt.core
8:12:22 Setting list of classpath elements with modified contents:
8:12:22 ===========================================================================================
8:12:22 Build kind = AUTOBUILD
8:12:22 Project=shadows.org.eclipse.jdt.core, kind of build requested=Incremental AspectJ compilation
8:12:22 File: C:\asc\ws\debugws-ajdt16\shadows.org.eclipse.jdt.core\eval\org\aspectj\org\eclipse\jdt\internal\eval\CodeSnippetAllocationExpression.java has changed.
8:12:22 build: Examined delta - 1 changed, 0 added, and 0 deleted source files in required project shadows.org.eclipse.jdt.core
8:12:22 Setting list of classpath elements with modified contents:


It just stops after saying it is setting list of classpath elements with modified contents.  It doesn't seem to call the compiler?

It might be this:

org.eclipse.core.internal.resources.ResourceException: Resource '/lib' is not open.
	at org.eclipse.core.internal.resources.Project.checkAccessible(Project.java:116)
	at org.eclipse.core.internal.resources.Project.hasNature(Project.java:489)
	at org.eclipse.ajdt.core.builder.AJBuilder.getChangedRequiredProjects(AJBuilder.java:315)
	at org.eclipse.ajdt.core.builder.AJBuilder.build(AJBuilder.java:217)
	at org.eclipse.core.internal.events.BuildManager$2.run(BuildManager.java:633)
	at org.eclipse.core.runtime.SafeRunner.run(SafeRunner.java:37)
	at org.eclipse.core.internal.events.BuildManager.basicBuild(BuildManager.java:170)
	at org.eclipse.core.internal.events.BuildManager.basicBuild(BuildManager.java:201)
	at org.eclipse.core.internal.events.BuildManager$1.run(BuildManager.java:253)
	at org.eclipse.core.runtime.SafeRunner.run(SafeRunner.java:37)
	at org.eclipse.core.internal.events.BuildManager.basicBuild(BuildManager.java:256)
	at org.eclipse.core.internal.events.BuildManager.basicBuildLoop(BuildManager.java:309)
	at org.eclipse.core.internal.events.BuildManager.build(BuildManager.java:341)
	at org.eclipse.core.internal.events.AutoBuildJob.doBuild(AutoBuildJob.java:140)
	at org.eclipse.core.internal.events.AutoBuildJob.run(AutoBuildJob.java:238)
	at org.eclipse.core.internal.jobs.Worker.run(Worker.java:55)


and I have a whole bunch of closed projects in my workspace.  Actually the lib project is closed, however my AspectJ project has a reference to a jar within it.  I guess when AspectJ checks the classpath it doesnt care about open/closed but the AJDT check does.  We shouldn't fail like this but I'm not quite sure what the right action is.
Comment 26 Andrew Clement CLA 2008-09-06 11:17:24 EDT
OK, hidden amongst my pages of errors was one against my AJ project saying it couldnt see the necessary jar (that was in the lib project).  So it is possible when this problem happens we should just not build because that kind of problem is reported in another way.
Comment 27 Andrew Clement CLA 2008-09-06 11:26:38 EDT
patch from comment 23 committed. iplog.

The failure doesn't need fixing before I commit because it doesn't happen with the option off (which is the default setting).

Might need to start using categories again in AJLog as it is getting quite wordy - new category for AJDT messages related to this feature?
Comment 28 Andrew Eisenberg CLA 2008-09-06 12:42:06 EDT
(In reply to comment #26)
> OK, hidden amongst my pages of errors was one against my AJ project saying it
> couldnt see the necessary jar (that was in the lib project).  So it is possible
> when this problem happens we should just not build because that kind of problem
> is reported in another way.
> 

This makes sense.  If the project is closed, then other projects that put it on the classpath can't access it.  There should have been an error and the build should have failed.  

I'll look into this.
Comment 29 Andrew Eisenberg CLA 2008-09-06 12:42:58 EDT
(In reply to comment #27)
> 
> Might need to start using categories again in AJLog as it is getting quite
> wordy - new category for AJDT messages related to this feature?
> 
I've been using the "builder" category for all of these, but could just as well add a new one.
Comment 30 Andrew Eisenberg CLA 2008-09-08 13:03:07 EDT
Created attachment 111973 [details]
patch and test for validating classpath before build

This patch ensures that an AJBuilder build aborts with an appropriate log message when the classpath is invalid.  No exceptions are thrown.
Comment 31 Andrew Eisenberg CLA 2008-09-08 13:04:44 EDT
This patch should address comment #25.
Comment 32 Andrew Eisenberg CLA 2008-09-08 14:16:29 EDT
Created attachment 111988 [details]
Patch to fix some Core tests that were affected by previous patch

This patch cleans up some core tests that were failing due to the previous patch.

This patch must be applied *instead of* the previous patch.
Comment 33 Andrew Eisenberg CLA 2008-09-08 14:29:32 EDT
With this latest change, the AJBuilder will be stricter when checking classpaths.  In the past, it was possible to build a project even if there was a missing "src" folder.  Now this case will show an error.  This is closer to how the JavaBuilder behaves.
Comment 34 Andrew Clement CLA 2008-09-10 13:16:37 EDT
patch from comment 32 committed
Comment 35 Andrew Clement CLA 2008-09-14 15:34:58 EDT
Latest changes are now available in AJDT 1.6 dev builds.  So what about a real scenario of a whitespace change to AJLog.log(), on save (default event trace options activated).

Performance enhancement turned off:

Project=org.eclipse.ajdt.core
12:22:0 Timer event: 235ms: Total time spent in AJDE
12:22:0 Timer event: 578ms: Total time spent in AJBuilder.build()
Project=org.eclipse.ajdt.core.tests
12:22:0 Timer event: 187ms: Total time spent in AJDE
12:22:0 Timer event: 265ms: Total time spent in AJBuilder.build()
Project=org.eclipse.ajdt.ui
12:22:1 Timer event: 578ms: Total time spent in AJDE
12:22:2 Timer event: 1485ms: Total time spent in AJBuilder.build()
Project=org.eclipse.ajdt.ui.tests
12:22:3 Timer event: 703ms: Total time spent in AJDE
12:22:4 Timer event: 2219ms: Total time spent in AJBuilder.build()
Project=org.eclipse.ajdt.ui.visual.tests
12:22:5 Timer event: 609ms: Total time spent in AJDE
12:22:5 Timer event: 703ms: Total time spent in AJBuilder.build()

Total in AJDE: 2312
Total (AJDE+AJDT): 5250

Similar results on repeated runs.  Now performance option turned on.

Project=org.eclipse.ajdt.core
12:29:23 Timer event: 31ms: Total time spent in AJDE
12:29:24 Timer event: 360ms: Total time spent in AJBuilder.build()
Project=org.eclipse.ajdt.core.tests
12:29:24 Timer event: 125ms: Total time spent in AJDE
12:29:24 Timer event: 250ms: Total time spent in AJBuilder.build()
Project=org.eclipse.ajdt.ui
12:29:24 Timer event: 110ms: Total time spent in AJDE
12:29:25 Timer event: 1015ms: Total time spent in AJBuilder.build()
Project=org.eclipse.ajdt.ui.tests
12:29:25 Timer event: 391ms: Total time spent in AJDE
12:29:27 Timer event: 1937ms: Total time spent in AJBuilder.build()
Project=org.eclipse.ajdt.ui.visual.tests
12:29:27 Timer event: 469ms: Total time spent in AJDE
12:29:27 Timer event: 594ms: Total time spent in AJBuilder.build()

Total in AJDE: 1126
Total (AJDE+AJDT): 4156

Observations:
- Performing kind of as expected, the benefit is all in the AJDE times
- After the initial project build, the dependees still spend >100ms in AJDE, not acceptable for this kind of change

Simplest next test is to profile what happens for the core.tests build and why it takes >100ms.  Detailed event trace reports:

12:33:28 ===========================================================================================
12:33:28 Build kind = AUTOBUILD
12:33:28 Project=org.eclipse.ajdt.core.tests, kind of build requested=Incremental AspectJ compilation
12:33:28 Timer event: 0ms: SourceFilesChanged
12:33:28 Setting list of classpath elements with modified contents:
12:33:28       [C:/asc/ws/ajdt16/org.eclipse.ajdt.core/bin]
12:33:28 Classpath = C:\asc\ws\ajdt16\org.eclipse.ajdt.core.tests\bin;C:/Program Files/Java/jre1.6.0_07/lib/resources.jar;C:/Program Files/Java/jre1.6.0_07/lib/rt.jar;C:/Program Files/Java/jre1.6.0_07/lib/jsse.jar;C:/Program Files/Java/jre1.6.0_07/lib/jce.jar;C:/Program Files/Java/jre1.6.0_07/lib/charsets.jar;C:/Program Files/Java/jre1.6.0_07/lib/ext/dnsns.jar;C:/Program Files/Java/jre1.6.0_07/lib/ext/localedata.jar;C:/Program Files/Java/jre1.6.0_07/lib/ext/QTJava.zip;C:/Program Files/Java/jre1.6.0_07/lib/ext/sunjce_provider.jar;C:/Program Files/Java/jre1.6.0_07/lib/ext/sunmscapi.jar;C:/Program Files/Java/jre1.6.0_07/lib/ext/sunpkcs11.jar;C:/eclipses/e34rc4/eclipse/plugins/org.eclipse.core.runtime_3.4.0.v20080512.jar;C:/eclipses/e34rc4/eclipse/plugins/org.eclipse.osgi_3.4.0.v20080605-1900.jar;C:/eclipses/e34rc4/eclipse/plugins/org.eclipse.equinox.common_3.4.0.v20080421-2006.jar;C:/eclipses/e34rc4/eclipse/plugins/org.eclipse.core.jobs_3.4.0.v20080512.jar;C:/eclipses/e34rc4/eclipse/plugins/org.eclipse.core.runtime.compatibility.registry_3.2.200.v20070717/runtime_registry_compatibility.jar;C:/eclipses/e34rc4/eclipse/plugins/org.eclipse.equinox.registry_3.4.0.v20080516-0950.jar;C:/eclipses/e34rc4/eclipse/plugins/org.eclipse.equinox.preferences_3.2.200.v20080421-2006.jar;C:/eclipses/e34rc4/eclipse/plugins/org.eclipse.core.contenttype_3.3.0.v20080604-1400.jar;C:/eclipses/e34rc4/eclipse/plugins/org.eclipse.equinox.app_1.1.0.v20080421-2006.jar;C:\asc\ws\ajdt16\org.eclipse.ajdt.core\bin;C:/eclipses/e34rc4/eclipse/plugins/org.eclipse.core.resources_3.4.0.v20080604-1400.jar;C:/eclipses/e34rc4/eclipse/plugins/org.eclipse.jdt.core_3.4.0.v_872.jar;C:/eclipses/e34rc4/eclipse/plugins/org.eclipse.jdt.compiler.apt_1.0.100.v20080513-1235.jar;C:/eclipses/e34rc4/eclipse/plugins/org.eclipse.jdt.compiler.tool_1.0.100.v_872.jar;C:/eclipses/e34rc4/eclipse/plugins/org.junit_3.8.2.v20080602-1318/junit.jar;C:/asc/ws/ajdt16/org.aspectj.ajde/ajde.jar;C:/asc/ws/ajdt16/org.aspectj.weaver/aspectjweaver.jar;C:/asc/ws/ajdt16/org.aspectj.runtime/aspectjrt.jar;C:/eclipses/e34rc4/eclipse/plugins/org.eclipse.text_3.4.0.v20080605-1800.jar;C:/eclipses/e34rc4/eclipse/plugins/org.eclipse.ltk.core.refactoring_3.4.0.v20080603-2000.jar;
12:33:28 Sending the following configuration changes to the compiler: []
12:33:28 0 source file changes since last build
12:33:28 Compiler configuration for project org.eclipse.ajdt.core.tests has been read by compiler.  Resetting.
12:33:28      Configuration was []
12:33:28 Resetting list of modified source files.  Was []
12:33:28 Found state instance managing output location : C:\asc\ws\ajdt16\org.eclipse.ajdt.core\bin
12:33:28 Change detected in C:\asc\ws\ajdt16\org.eclipse.ajdt.core\bin\org\eclipse\ajdt\core\AJLog.class but it is not structural
12:33:28 Preparing for build: planning to be an incremental build
12:33:28 AspectJ reports build successful, build was: INCREMENTAL
12:33:28 AJDE Callback: finish. Was full build: false
12:33:28 Timer event: 125ms: Total time spent in AJDE
12:33:29 Timer event: 15ms: Create element map (0 rels in project: org.eclipse.ajdt.core.tests)
12:33:29 Timer event: 0ms: Add markers (0 markers)
12:33:29 Timer event: 266ms: Total time spent in AJBuilder.build()
12:33:29 ===========================================================================================

Only noticeable thing there is a long classpath.
Comment 36 Andrew Eisenberg CLA 2008-09-14 18:52:36 EDT
(In reply to comment #35)
> 
> Total in AJDE: 2312
> Total (AJDE+AJDT): 5250

I am assuming that most of this tim ein AJDT is to recreate the project map.  Do we know this for sure?
Comment 37 Andrew Clement CLA 2008-09-30 16:33:07 EDT
Problems in comment 35 to be covered in bug 249212.  Closing this bug to indicate the work done for AspectJ 1.6.2.