Community
Participate
Working Groups
We are working on a scenario that has 50 or so projects. With only a couple made AspectJ projects and the rest being normal Java projects, the development experience is OK. When they are all converted to AspectJ projects, and the aspects from the base AJ projects (which provide FFDC and Trace) are applied across *all of them* (by inclusion of those base projects on the aspectpath of all the other projects), the development experience slows to a crawl. Observations so far: - some of these projects include resources and incremental compilation treatment of resources hasn't been optimized. - AJDT may be rebuilding the element map (ajdts version of the structure model) when not necessary I've developed an AJ testcase for the first scenario and have a fix that seems to be behaving.
Created attachment 109585 [details] Patch to ensure that auto build does not occur after a full build. I went pretty far into the bowels looking at this thing and here is the first patch of possibly several that will help make the AJDT experience of working many projects more pleasant. When a project A has the binary output folder of another project B on its aspect path, a second auto build occurs after every full build. The reason is that during a full build, the binary output folder of project B is wiped and then recreated. So that after the build, project A sees that the output folder of B (on its Java build path) is new and this triggers an auto build. This is an issue that comes from the Eclipse workspace and is out of the control of AJDT. Apparently, this must have been happening since we started putting aspect path elements on the Java build path, but no one had noticed it. The way around this is to use project references instead of binary folder references (this feature has only been available since AJDT 1.5.3). This patch includes a test case to ensure that the double build does not happen when using a project reference. Also, I made a few fixes to the way that projects are added to the aspect and in paths so that build errors do not occur when a project's out folder does not exist.
Created attachment 109689 [details] Reworked the test on the previous patch This patch is a slight reworking of the test included in the previous version of the patch. Now, the test executes the project and checks the output to ensure that the aspect has been properly applied.
can't seem to apply the part of the patch that changes UITestCase - was it created against HEAD?
managed to get the patch forced in. Now committed. I had to change the test slightly so it was OK on windoze
Addressing the resource copying mentioned in my first post on the bug. The compiler was deleting resources and recopying them each time (yikes!) - so now lets have AJDT handle the incremental changes and AspectJ will do the up front copy on first fresh build. Changing this behaviour causes two aspectj tests to fail relating to resource copying, she mention of this bug in MoreOutputLocationManagerTests. changes committed.
I decided to measure the AsmHierarchyBuilder code to see if that was a problem. It has never been optimized but I had to use a nanosecond timer rather than millisecond to actually get any numbers out. Typically it is taking less than 1ms per file. When building the entire shadows project (our 'example' AspectJ project) - which is a copy of the JDT compiler with aspects applied - it spent just 1s of the full build time in AsmHierarchyBuilder. And on an incremental build of one file, typically 1ms or less. The target for incremental compilation should be about 500ms at worst - so 1ms indicates there are other places to look right now.
I've been profiling incremental builds. I'm using my main AspectJ demo project (shadows) and making a whitespace change to CompilationEngine. Profiling revealed the hotspots I expected: org.aspectj.asm.internal.AspectJElementHierarchy.findElementForHandle(IProgramElement, String) (15% 1.3s) called from AsmManager.removeRelationsTargettingThisType File.getCanonicalFile() - called from ConfigParser.makeFile() File.lastModified() - called from AjState.getModifiedFiles(long) (called through getFilesToCompile(boolean)) AbstractList.iterator() - called through AspectJElementHierarchy.findElementForHandle AbstractList$Iter.next() - called through AspectJElementHierarchy.findElementForHandle ZipFile$3.nextElement() - called through ClasspathJar.isPackage(String) Of the about 5s to recompile the file we spent 20% of the time messing about with the model. After adding some debug into the code I observed the following usage of the handle>programelement cache. On a full build of the entire project the cache is accessed 3331 times, of which 848 are misses and 2499 are hits. On an incremental white space change build it is accessed 13499 times (!!) of which 13631 hits and 456 misses. This excess is due to the sub-optimal incremental model repair code that I'm now looking through. Other observations so far are: - the handles (Strings) are very long - it is not exploited that the handle to an element is an extension of the handle to its parent element (so we can make intelligent navigation decisions when walking down a hierarchy rather than blindly looking at every node all over the tree) There is a lot of scope here to speed things up and reduce memory usage.
oops, typo, should read: 13499 cache accesses on one incremental build 13163 hit/456 miss
- Changed to exploit knowledge that handles for parents are simply shorter variants of the handles for children - prevents exploration of the entire model for a handle. - Removed unnecessary cache accesses (still more to do) - optimized relationship implementation
I've put these changes into a private build to try it. Typical times (in ms) for the: 17:07:33 Timer event: XXXXms: Total time spent in AJDE line in the AJDT event trace were (before my changes): 3984/5125/4015 Now the times are: 2985/3828/3313/3203 So quite a reduced time - and more to come. I'd like to see it halved at least.
More observations. We really need to address this crappy interface between AJDT and the compiler. At least it doesn't write a file out now to communicate between the two, but what it does isn't much better than that. On every build the compiler builds a brand new object to hold the configuration of the compile that AJDT wants to do, it does this by asking AJDT for the inpath/classpath/aspectpath/options/sourcefiles/etc/etc/etc. Even if only one source file has changed it asks for everything and reprocesses it. Particularly annoying is that the compiler proceeds to go through all the source files to see which one has changed, after AJDT already did that (it just didn't tell AspectJ what it found out). This means in the case of me rebuilding shadows, my white space change leads to the compiler processing the 1146 source files again into a config object (when it is the same set of sources as before) and then asking all of them if their lastmodtime has changed - rather than AJDT (which has just processed the delta of eclipse changes) telling me the one file that changed. lastModifiedTime() is not a cheap operation, nor is getCanonicalFile and both of those are called 1146 times in my case. I know these numbers are worse on larger projects (and this bug is intended to cover small projects) - but I think fixing this will benefit every kind of project so is worth doing. (this is all to reduce the 'time spent in AJDE' message - i've still not looked into any time wasted in AJDT).
There's a lot of room for improvement on the AJDT side as well. After every build, AJDT asks the compiler for the new project model and discards the old one (actually, it saves the previous model to do model comparisons). Not every part of the model needs to be recreated, but it is tricky to tease out what does and does not. I think spending a week or so to clean up this interface can save a lot of time on both sides. I don't know if this will be appropriate for the 1.6.0 release, though.
continuing on from comment 10, where the times were: 2985/3828/3313/3203 I changed the ICompilerConfiguration interface so that it could return the list of modified files (if the caller knew them). I also changed AjBuildManager.performCompilation to maintain a name environment rather than trash it between compilations (need to check ongoing memory consumption of this mechanism). Times reduced to: 1359/2281/1281/1313 And seeing as how the file I'm white space changing is affected by aspects and contains 5 inner types that also get woven, that's not bad. I then switched to whitespace changes on a file in the same project that is not affected by aspects: CodeSnippetEnvironment With current 1.6 dev build: Time spent in AJDE: 1704/1750/1718/1735 With all the changes I'm proposing: Time spent in AJDE: 109/94/79/93/78 Hmmm - slight improvement... It will take a little while to fully integrate my changes, there are some necessary AJDT changes and currently it doesn't notice if other features of the project change (like the classpath) - but that can be fixed and it would be nice to move to a model where AspectJ can ask AJDT "has anything interesting changed?" rather than always ask for all information and process it. When the AJDE times are this low, the full info is: 13:8:56 Build kind = AUTOBUILD 13:8:56 Project=shadows.org.eclipse.jdt.core, kind of build requested=Incremental AspectJ compilation 13:8:56 Considering this as a changed file: C:\asc\ws\debugws-ajdt16\shadows.org.eclipse.jdt.core\eval\org\aspectj\org\eclipse\jdt\internal\eval\CodeSnippetEnvironment.java 13:8:56 build: Examined delta - source file changes in required project shadows.org.eclipse.jdt.core 13:8:56 Preparing for build: planning to be an incremental build 13:8:56 Starting incremental compilation loop 1 of possibly 5 13:8:56 Timer event: 62ms: Time to first compiled message 13:8:56 Timer event: 78ms: Time to first woven message 13:8:56 AspectJ reports build successful, build was: INCREMENTAL 13:8:56 AJDE Callback: finish. Was full build: false 13:8:56 Timer event: 78ms: Total time spent in AJDE 13:8:57 Timer event: 125ms: Create element map (1640 rels in project: shadows.org.eclipse.jdt.core) 13:8:57 Types affected during build = 1 13:8:57 Timer event: 78ms: Add markers (827 markers) 13:8:57 Timer event: 1203ms: Total time spent in AJBuilder.build() So although the time spent in AJDE was 78milliseconds, the time spent in AJBuilder.build was 1203ms. Where does this time get spent? A profile of it reveals: AJBuilder.build(int,Map,IProgressMonitor) (if this is 100%) - AJBuilder.doRefreshAfterBuild(IProject,IProject[],IJavaProject) 80% - AJModel.createMap(IProject,boolean,boolean) 11% - AjCompiler.build() 6% < -- thats the 78ms - AJBuilder.postCallListeners(boolean) 2%
Closing to cover work done for 1.6.2 AspectJ. Single project scenario enhancements (which also impact multi-project scenarios to a degree) are in. There is still work to do looking at multi project setups, but that will be covered in a new bug.
Created attachment 114843 [details] Turn on incremental build optimizations by default This patch will keep the incremental build optimizations preference item around, it will turn it on by default.
