Community
Participate
Working Groups
reported by Thomas on the list.
AJDT 1.6.3 log highlights Not sure why there is an entry that says: Resetting list of modified source files. Was [C:\ws\ivk rsa 7.5\com.dcx.ivkmds.fwk.common.ass.persist\src\com\dcx\ivkmds\fwk\common\ass\persist\NlTextProperty.java, C:\ws\ivk rsa 7.5\com.dcx.ivkmds.fwk.common.ass.persist\src\com\dcx\ivkmds\fwk\common\ass\persist\NlTextProperty.java, C:\ws\ivk rsa 7.5\com.dcx.ivkmds.fwk.common.ass.persist\src\com\dcx\ivkmds\fwk\common\ass\persist\NlTextProperty.java, C:\ws\ivk rsa 7.5\com.dcx.ivkmds.fwk.common.ass.persist\src\com\dcx\ivkmds\fwk\common\ass\persist\NlTextProperty.java, C:\ws\ivk rsa 7.5\com.dcx.ivkmds.fwk.common.ass.persist\src\com\dcx\ivkmds\fwk\common\ass\persist\NlTextProperty.java, C:\ws\ivk rsa 7.5\com.dcx.ivkmds.fwk.common.ass.persist\src\com\dcx\ivkmds\fwk\common\ass\persist\NlTextProperty.java, C:\ws\ivk rsa 7.5\com.dcx.ivkmds.fwk.common.ass.persist\src\com\dcx\ivkmds\fwk\common\ass\persist\NlTextProperty.java, C:\ws\ivk rsa 7.5\com.dcx.ivkmds.fwk.common.ass.persist\src\com\dcx\ivkmds\fwk\common\ass\persist\NlTextProperty.java, C:\ws\ivk rsa 7.5\com.dcx.ivkmds.fwk.common.ass.persist\src\com\dcx\ivkmds\fwk\common\ass\persist\NlTextProperty.java, C:\ws\ivk rsa 7.5\com.dcx.ivkmds.fwk.common.ass.persist\src\com\dcx\ivkmds\fwk\common\ass\persist\NlTextProperty.java, C:\ws\ivk rsa 7.5\com.dcx.ivkmds.fwk.common.ass.persist\src\com\dcx\ivkmds\fwk\common\ass\persist\NlTextProperty.java, C:\ws\ivk rsa 7.5\com.dcx.ivkmds.fwk.common.ass.persist\src\com\dcx\ivkmds\fwk\common\ass\persist\NlTextProperty.java, C:\ws\ivk rsa 7.5\com.dcx.ivkmds.fwk.common.ass.persist\src\com\dcx\ivkmds\fwk\common\ass\persist\NlTextProperty.java, C:\ws\ivk rsa 7.5\com.dcx.ivkmds.fwk.common.ass.persist\src\com\dcx\ivkmds\fwk\common\ass\persist\NlTextProperty.java, C:\ws\ivk rsa 7.5\com.dcx.ivkmds.fwk.common.ass.persist\src\com\dcx\ivkmds\fwk\common\ass\persist\NlTextProperty.java, C:\ws\ivk rsa 7.5\com.dcx.ivkmds.fwk.common.ass.persist\src\com\dcx\ivkmds\fwk\common\ass\persist\NlTextProperty.java] Surely it should only be mentioned once? Timers for his whitespace project change build: 11:10:35 Timer event: 531ms: Total time spent in AJDE 11:10:35 Timer event: 266ms: Refresh after build 11:10:35 Types affected during build = 1 11:10:35 Timer event: 1078ms: Total time spent in AJBuilder.build() 11:10:36 Timer event: 125ms: Post compile AJDE time is a little high. presumably rest of the wasted time in AJBuilder.build is model validation? Build of depending project looks reasonable: 11:10:40 Build kind = AUTOBUILD 11:10:40 Project=com.dcx.ivkmds.fwk.common.businessobjects.persistent, kind of build requested=Incremental AspectJ compilation 11:10:40 build: Examined delta - no source file or classpath changes for project com.dcx.ivkmds.fwk.common.businessobjects.persistent 11:10:40 File: C:\ws\ivk rsa 7.5\com.dcx.ivkmds.fwk.common.ass.persist\src\com\dcx\ivkmds\fwk\common\ass\persist\NlTextProperty.java has changed. 11:10:40 build: Examined delta - 1 changed, 0 added, and 0 deleted source files in required project com.dcx.ivkmds.fwk.common.ass.persist 11:10:40 Setting list of classpath elements with modified contents: 11:10:40 [C:/ws/ivk rsa 7.5/com.dcx.ivkmds.fwk.common.ass.persist/bin, C:/ws/ivk rsa 7.5/com.dcx.ivkmds.fwk.common.ass.persist/bin] 11:10:40 Timer event: 47ms: Pre compile 11:10:40 Sending the following configuration changes to the compiler: [] 11:10:40 0 source file changes since last build 11:10:40 Compiler configuration for project com.dcx.ivkmds.fwk.common.businessobjects.persistent has been read by compiler. Resetting. 11:10:40 Configuration was [] 11:10:40 Resetting list of modified source files. Was [] 11:10:40 Found state instance managing output location : C:\ws\ivk rsa 7.5\com.dcx.ivkmds.fwk.common.ass.persist\bin 11:10:40 Change detected in C:\ws\ivk rsa 7.5\com.dcx.ivkmds.fwk.common.ass.persist\bin\com\dcx\ivkmds\fwk\common\ass\persist\NlTextProperty.class but it is not structural 11:10:40 Found state instance managing output location : C:\ws\ivk rsa 7.5\com.dcx.ivkmds.fwk.common.ass.persist\bin 11:10:40 Change detected in C:\ws\ivk rsa 7.5\com.dcx.ivkmds.fwk.common.ass.persist\bin\com\dcx\ivkmds\fwk\common\ass\persist\NlTextProperty.class but it is not structural 11:10:40 Preparing for build: planning to be an incremental build 11:10:40 AspectJ reports build successful, build was: INCREMENTAL 11:10:40 AJDE Callback: finish. Was full build: false 11:10:40 Timer event: 31ms: Total time spent in AJDE 11:10:40 Timer event: 219ms: Refresh after build 11:10:40 Timer event: 328ms: Total time spent in AJBuilder.build() 11:10:40 Timer event: 125ms: Post compile times for other downstream projects are fine (Time spent in AJDE): com.dcx.ivkmds.fwk.rcs - 47ms com.dcx.ivkmds.csolver.cts - 16ms com.dcx.ivkmds.common.businessobjects.persistent - 125ms com.dcx.ivkmds.common.businessobjects.fwktest - 219ms - included double analysis of the change for some reason com.dcx.ivkmds.fwk.ass - 47ms com.dcx.ivkmds.application.ass - 422ms com.dcx.ivkmds.csolver.ass - 328ms com.dcx.ivkmds._45_export_import.ass - 375ms com.dcx.ivkmds._00_fwktest.ass - 125ms com.dcx.ivkmds.testfwk - 734ms - bit high, double analysis again com.dcx.ivkmds.fwk.test.rcs - 860ms - high com.dcx.ivkmds.fwk.test.ass - 891ms - high com.dcx.ivkmds.fwk.test.common - 750ms - high com.dcx.ivkmds._45_export_import.test.ass - 688ms - high
AJDT 1.6.4 log observations: same problem reporting the same file changed lots of times: 14:54:56 Resetting list of modified source files. Was [C:\ws\ivk rsa 7.5\com.dcx.ivkmds.fwk.common.ass.persist\src\com\dcx\ivkmds\fwk\common\ass\persist\NlTextProperty.java, C:\ws\ivk rsa 7.5\com.dcx.ivkmds.fwk.common.ass.persist\src\com\dcx\ivkmds\fwk\common\ass\persist\NlTextProperty.java, C:\ws\ivk rsa 7.5\com.dcx.ivkmds.fwk.common.ass.persist\src\com\dcx\ivkmds\fwk\common\ass\persist\NlTextProperty.java, C:\ws\ivk rsa 7.5\com.dcx.ivkmds.fwk.common.ass.persist\src\com\dcx\ivkmds\fwk\common\ass\persist\NlTextProperty.java, C:\ws\ivk rsa 7.5\com.dcx.ivkmds.fwk.common.ass.persist\src\com\dcx\ivkmds\fwk\common\ass\persist\NlTextProperty.java, C:\ws\ivk rsa 7.5\com.dcx.ivkmds.fwk.common.ass.persist\src\com\dcx\ivkmds\fwk\common\ass\persist\NlTextProperty.java, C:\ws\ivk rsa 7.5\com.dcx.ivkmds.fwk.common.ass.persist\src\com\dcx\ivkmds\fwk\common\ass\persist\NlTextProperty.java, C:\ws\ivk rsa 7.5\com.dcx.ivkmds.fwk.common.ass.persist\src\com\dcx\ivkmds\fwk\common\ass\persist\NlTextProperty.java, C:\ws\ivk rsa 7.5\com.dcx.ivkmds.fwk.common.ass.persist\src\com\dcx\ivkmds\fwk\common\ass\persist\NlTextProperty.java, C:\ws\ivk rsa 7.5\com.dcx.ivkmds.fwk.common.ass.persist\src\com\dcx\ivkmds\fwk\common\ass\persist\NlTextProperty.java, C:\ws\ivk rsa 7.5\com.dcx.ivkmds.fwk.common.ass.persist\src\com\dcx\ivkmds\fwk\common\ass\persist\NlTextProperty.java, C:\ws\ivk rsa 7.5\com.dcx.ivkmds.fwk.common.ass.persist\src\com\dcx\ivkmds\fwk\common\ass\persist\NlTextProperty.java, C:\ws\ivk rsa 7.5\com.dcx.ivkmds.fwk.common.ass.persist\src\com\dcx\ivkmds\fwk\common\ass\persist\NlTextProperty.java, C:\ws\ivk rsa 7.5\com.dcx.ivkmds.fwk.common.ass.persist\src\com\dcx\ivkmds\fwk\common\ass\persist\NlTextProperty.java, C:\ws\ivk rsa 7.5\com.dcx.ivkmds.fwk.common.ass.persist\src\com\dcx\ivkmds\fwk\common\ass\persist\NlTextProperty.java, C:\ws\ivk rsa 7.5\com.dcx.ivkmds.fwk.common.ass.persist\src\com\dcx\ivkmds\fwk\common\ass\persist\NlTextProperty.java] 14:54:58 Timer event: 1531ms: Total time spent in AJDE 14:54:58 Timer event: 235ms: Refresh after build 14:54:58 Types affected during build = 1 14:54:58 Crosscutting model sanity checked with no problems 14:54:58 Timer event: 1937ms: Total time spent in AJBuilder.build() 14:54:58 Timer event: 109ms: Post compile 3 times slower to build the code, not sure why - suppose it *could* be the extra incremental analysis we are now performing for declare parents statements. https://bugs.eclipse.org/bugs/show_bug.cgi?id=259649 dependent projects: com.dcx.ivkmds.fwk.common.businessobjects.persistent - 406ms - contains double analysis (looks like it is probably just because something is on the classpath twice for the project) com.dcx.ivkmds.fwk.rcs - 266ms com.dcx.ivkmds.csolver.cts - 31ms ... having trouble processing the logs now because of all the model verification STUFF that is dumped in there.
Created attachment 128945 [details] AJDT Event trace for AJDT 1.6.3 Taken from mailing list. This event trace shows the effect of a whitespace change. It is taking longer than it should. One thing I notice is that the time for "Refresh after build" is taking too long. It is well over half the time spent in AJBuilder. Time spent in AJDE seems reasonable, though. I suspect that these are projects with lots of files.
Comment on attachment 128945 [details] AJDT Event trace for AJDT 1.6.3 This is the event trace for the 1.6.3 version.
Ok, 1.6.4 logs: com.dcx.ivkmds.fwk.common.ass.persist - 1531 com.dcx.ivkmds.fwk.common.businessobjects.persistent - 406ms com.dcx.ivkmds.fwk.rcs - 266ms com.dcx.ivkmds.csolver.cts - 31ms com.dcx.ivkmds.common.businessobjects.persistent - 32ms com.dcx.ivkmds.common.businessobjects.fwktest - 235ms com.dcx.ivkmds.fwk.ass - 31ms com.dcx.ivkmds.application.ass - 469ms com.dcx.ivkmds.csolver.ass - 485ms com.dcx.ivkmds._45_export_import.ass - 1516ms com.dcx.ivkmds._00_fwktest.ass - 547ms com.dcx.ivkmds.testfwk - 5500ms com.dcx.ivkmds.fwk.test.rcs - 2875ms com.dcx.ivkmds.fwk.test.ass - 5047ms com.dcx.ivkmds.fwk.test.common - 1609ms com.dcx.ivkmds._45_export_import.test.ass - 6203ms
we appear to be slowing down as we go along. Things that worry me: - Does the model checking code consume large amounts of memory? - Does it leak memory in any of its processing? Given that the only logs we have to go on are 1.6.3 without model checking and 1.6.4 with model checking, it is hard to proceed on this. We need a 1.6.4 log without model checking. I know Andrew was working on making this something that could be switched off - i think we need Thomas to try a build with that option in, so at least we are comparing similar runs of the same thing. The 1.6.3 times for AJDE (time spent in the AspectJ compiler) do not look completely unreasonable although it appears to be quite a project chain so there is a big knock-on compilation effect for other projects when a whitespace change is done in the top one. However the whitespace change is correctly being recognized as non-structural. In the 1.6.3 case, the times for the last 5 projects: com.dcx.ivkmds.testfwk - 734ms com.dcx.ivkmds.fwk.test.rcs - 860ms - high com.dcx.ivkmds.fwk.test.ass - 891ms - high com.dcx.ivkmds.fwk.test.common - 750ms - high com.dcx.ivkmds._45_export_import.test.ass - 688ms - high seem a bit unusual compared to the rest.
Created attachment 128950 [details] Latest build logs
In the new 1.6.3 logs we see that, yes, the classpath is a monster, especially for those downstream projects. We ought to find a quick way to discount many of the early entries from our search. (We are searching to see if 'we' are managing any change-state for the classpath entries, if we are then we can make quick decisions about whether anything has changed, rather than diving in to check timestamps)
Created attachment 128954 [details] AJDT UI version that does not perform model checking This version of the plugin has model checking turned off. No other difference. I've tried it myself and it seems to behave exactly the same as before, except no model checking is performed after build. To install: 1. make a copy of your original org.eclipse.ajdt.ui_1.6.4.20090313172428.jar 2. replace with this one 3. perform a build with the AJDT Event Trace view open and make sure that model checking does not occur Try this out and please post your results back here.
Oh, and you must be using the latest dev build of AJDT (version 1.6.4.20090313172428, the release candidate).
Created attachment 129053 [details] Trace No. 1 taken with patched ajdt.ui plugin Performance feels like 1.6.3 (if not better)
Created attachment 129054 [details] Trace No. 2 takenn with patched ajdt.ui plugin Essentially the same trace as ajdt 1.6.4 patched - 5 -small change to NlTextProperty.tracen just a second run.
(In reply to comment #6) > we appear to be slowing down as we go along. Things that worry me: > > - Does the model checking code consume large amounts of memory? > - Does it leak memory in any of its processing? > > Given that the only logs we have to go on are 1.6.3 without model checking and > 1.6.4 with model checking, it is hard to proceed on this. We need a 1.6.4 log > without model checking. I know Andrew was working on making this something > that could be switched off - i think we need Thomas to try a build with that > option in, so at least we are comparing similar runs of the same thing. > > The 1.6.3 times for AJDE (time spent in the AspectJ compiler) do not look > completely unreasonable although it appears to be quite a project chain so > there is a big knock-on compilation effect for other projects when a whitespace > change is done in the top one. However the whitespace change is correctly > being recognized as non-structural. > > In the 1.6.3 case, the times for the last 5 projects: > com.dcx.ivkmds.testfwk - 734ms > com.dcx.ivkmds.fwk.test.rcs - 860ms - high > com.dcx.ivkmds.fwk.test.ass - 891ms - high > com.dcx.ivkmds.fwk.test.common - 750ms - high > com.dcx.ivkmds._45_export_import.test.ass - 688ms - high > > seem a bit unusual compared to the rest. > The testfwk project contains some framework classes (superclasses and utilities) for unit test. It also contains three .aj files with aspects that apply to some of the testfwk classes as well as to the actual test found in the projects test.rcs, test.ass, test.common, _45_export_import.test.ass.
(In reply to comment #13) > (In reply to comment #6) > > we appear to be slowing down as we go along. Things that worry me: > > > > - Does the model checking code consume large amounts of memory? > > - Does it leak memory in any of its processing? > > > > Given that the only logs we have to go on are 1.6.3 without model checking and > > 1.6.4 with model checking, it is hard to proceed on this. We need a 1.6.4 log > > without model checking. I know Andrew was working on making this something > > that could be switched off - i think we need Thomas to try a build with that > > option in, so at least we are comparing similar runs of the same thing. > > > > The 1.6.3 times for AJDE (time spent in the AspectJ compiler) do not look > > completely unreasonable although it appears to be quite a project chain so > > there is a big knock-on compilation effect for other projects when a whitespace > > change is done in the top one. However the whitespace change is correctly > > being recognized as non-structural. > > > > In the 1.6.3 case, the times for the last 5 projects: > > com.dcx.ivkmds.testfwk - 734ms > > com.dcx.ivkmds.fwk.test.rcs - 860ms - high > > com.dcx.ivkmds.fwk.test.ass - 891ms - high > > com.dcx.ivkmds.fwk.test.common - 750ms - high > > com.dcx.ivkmds._45_export_import.test.ass - 688ms - high > > > > seem a bit unusual compared to the rest. > > > > > The testfwk project contains some framework classes (superclasses and > utilities) for unit test. It also contains three .aj files with aspects that > apply to some of the testfwk classes as well as to the actual test found in the > projects test.rcs, test.ass, test.common, _45_export_import.test.ass. > Do you need some numbers about projects, number of types etc? Which ones?
BTW, here is some information on the computer I am using. It is a Lenovo T61P with: - Intel Core 2 Duo T9500 @ 2.6 Ghz - 4 GB RAM (only 3 usable due to 32 bit Windows XP) - HD: HTS722020K9SA00 with 7200 RPM
Created attachment 129090 [details] Another trace when a small change is made in class that multiple projects depend on I add this trace so that you have another trace to look at. I made only an internal change to a method.
Created attachment 129092 [details] Trace where method Name was changed Just on more trace
Thanks for the traces Thomas. I'm on a T61p too ;) > Do you need some numbers about projects, number of types etc? Which ones? I think I have enough to tinker a little bit - but Andrew might want more info? In each case the 'time spent in AJDE' is the time spent in the compiler itself whilst the 'time spent in AJBuilder.build()' is that plus time spent in AJDT preparing for the build and processing whatever the compiler did. I look at the former times and Andrew looks into the AJDT times. From an AJDE point of view, my biggest concern is the loong 'time spent in AJDE' times towards the end of each log where the compiler is not actually doing any building, but is just taking a while to work out that it doesn't need to. I don't have any project configs like that, with a long chain of dependencies, but I'll try and fake something up. I have a suspicion of the cause but it'll take a while to confirm.
Ok, converted all of AspectJ to be AspectJ projects - making a small change in the FileUtil class (in util project) causes multiple downstream rebuilds, the final one: 9:0:6 Build kind = AUTOBUILD 9:0:6 Project=run-all-junit-tests, kind of build requested=Incremental AspectJ compilation 9:0:6 build: Examined delta - no source file or classpath changes for project run-all-junit-tests 9:0:6 File: D:\Andy\eclipse_ws\ws34\util\src\org\aspectj\util\FileUtil.java has changed. 9:0:6 build: Examined delta - 1 changed, 0 added, and 0 deleted source files in required project util 9:0:6 Setting list of classpath elements with modified contents: 9:0:6 [D:/Andy/eclipse_ws/ws34/ajbrowser/bin, D:/Andy/eclipse_ws/ws34/ajde/bin, D:/Andy/eclipse_ws/ws34/asm/bin, D:/Andy/eclipse_ws/ws34/bridge/bin, D:/Andy/eclipse_ws/ws34/taskdefs/bin, D:/Andy/eclipse_ws/ws34/lib/commons/commons.jar, D:/Andy/eclipse_ws/ws34/testing/bin, D:/Andy/eclipse_ws/ws34/testing-client/bin, D:/Andy/eclipse_ws/ws34/testing-drivers/bin, D:/Andy/eclipse_ws/ws34/testing-util/bin, D:/Andy/eclipse_ws/ws34/util/bin, D:/Andy/eclipse_ws/ws34/weaver/bin, D:/Andy/eclipse_ws/ws34/tests/bin, D:/Andy/eclipse_ws/ws34/ajdoc/bin, D:/Andy/eclipse_ws/ws34/util/bin, D:/Andy/eclipse_ws/ws34/bridge/bin, D:/Andy/eclipse_ws/ws34/asm/bin, D:/Andy/eclipse_ws/ws34/org.aspectj.ajdt.core/bin, D:/Andy/eclipse_ws/ws34/org.eclipse.jdt.core/jdtcore-for-aspectj.jar, D:/Andy/eclipse_ws/ws34/ajde.core/bin, D:/Andy/eclipse_ws/ws34/org.aspectj.matcher/bin] 9:0:6 Classpath = D:\Andy\eclipse_ws\ws34\run-all-junit-tests\bin;C:/jvms/jdk1.6.0_10/jre/lib/resources.jar;C:/jvms/jdk1.6.0_10/jre/lib/rt.jar;C:/jvms/jdk1.6.0_10/jre/lib/jsse.jar;C:/jvms/jdk1.6.0_10/jre/lib/jce.jar;C:/jvms/jdk1.6.0_10/jre/lib/charsets.jar;C:/jvms/jdk1.6.0_10/jre/lib/ext/dnsns.jar;C:/jvms/jdk1.6.0_10/jre/lib/ext/dns_sd.jar;C:/jvms/jdk1.6.0_10/jre/lib/ext/localedata.jar;C:/jvms/jdk1.6.0_10/jre/lib/ext/sunjce_provider.jar;C:/jvms/jdk1.6.0_10/jre/lib/ext/sunmscapi.jar;C:/jvms/jdk1.6.0_10/jre/lib/ext/sunpkcs11.jar;D:\Andy\eclipse_ws\ws34\ajbrowser\bin;D:\Andy\eclipse_ws\ws34\ajde\bin;D:\Andy\eclipse_ws\ws34\asm\bin;D:\Andy\eclipse_ws\ws34\bridge\bin;D:\Andy\eclipse_ws\ws34\build\bin;D:\Andy\eclipse_ws\ws34\org.aspectj.ajdt.core\bin;D:/Andy/eclipse_ws/ws34/org.eclipse.jdt.core/jdtcore-for-aspectj.jar;D:\Andy\eclipse_ws\ws34\runtime\bin;D:\Andy\eclipse_ws\ws34\taskdefs\bin;D:\Andy\eclipse_ws\ws34\testing\bin;D:/Andy/eclipse_ws/ws34/lib/commons/commons.jar;D:\Andy\eclipse_ws\ws34\testing-client\bin;D:\Andy\eclipse_ws\ws34\testing-drivers\bin;D:\Andy\eclipse_ws\ws34\testing-util\bin;D:\Andy\eclipse_ws\ws34\util\bin;D:\Andy\eclipse_ws\ws34\weaver\bin;D:/Andy/eclipse_ws/ws34/lib/junit/junit.jar;D:\Andy\eclipse_ws\ws34\tests\bin;D:\Andy\eclipse_ws\ws34\aspectj5rt\bin;D:\Andy\eclipse_ws\ws34\ajdoc\bin;D:\Andy\eclipse_ws\ws34\loadtime\bin;D:\Andy\eclipse_ws\ws34\loadtime5\bin;D:\Andy\eclipse_ws\ws34\weaver5\bin;D:\Andy\eclipse_ws\ws34\ajde.core\bin;D:\Andy\eclipse_ws\ws34\org.aspectj.matcher\bin;D:/Andy/e34/eclipse/plugins/org.aspectj.runtime_1.6.4.20090304172355/aspectjrt.jar; 9:0:6 Timer event: 2ms: Pre compile 9:0:6 Sending the following configuration changes to the compiler: [] 9:0:6 0 source file changes since last build 9:0:6 Compiler configuration for project run-all-junit-tests has been read by compiler. Resetting. 9:0:6 Configuration was [] 9:0:6 Resetting list of modified source files. Was [] 9:0:6 Found state instance managing output location : D:\Andy\eclipse_ws\ws34\ajbrowser\bin 9:0:6 Found state instance managing output location : D:\Andy\eclipse_ws\ws34\ajde\bin 9:0:6 Found state instance managing output location : D:\Andy\eclipse_ws\ws34\asm\bin 9:0:6 Found state instance managing output location : D:\Andy\eclipse_ws\ws34\bridge\bin 9:0:6 Found state instance managing output location : D:\Andy\eclipse_ws\ws34\taskdefs\bin 9:0:6 Found state instance managing output location : D:\Andy\eclipse_ws\ws34\testing\bin 9:0:6 Found state instance managing output location : D:\Andy\eclipse_ws\ws34\testing-client\bin 9:0:6 Found state instance managing output location : D:\Andy\eclipse_ws\ws34\testing-drivers\bin 9:0:6 Found state instance managing output location : D:\Andy\eclipse_ws\ws34\testing-util\bin 9:0:6 Found state instance managing output location : D:\Andy\eclipse_ws\ws34\util\bin 9:0:6 Change detected in D:\Andy\eclipse_ws\ws34\util\bin\org\aspectj\util\FileUtil$1.class but it is not structural 9:0:6 Change detected in D:\Andy\eclipse_ws\ws34\util\bin\org\aspectj\util\FileUtil$2.class but it is not structural 9:0:6 Change detected in D:\Andy\eclipse_ws\ws34\util\bin\org\aspectj\util\FileUtil$3.class but it is not structural 9:0:6 Change detected in D:\Andy\eclipse_ws\ws34\util\bin\org\aspectj\util\FileUtil$4.class but it is not structural 9:0:6 Change detected in D:\Andy\eclipse_ws\ws34\util\bin\org\aspectj\util\FileUtil$5.class but it is not structural 9:0:6 Change detected in D:\Andy\eclipse_ws\ws34\util\bin\org\aspectj\util\FileUtil$Pipe.class but it is not structural 9:0:6 Change detected in D:\Andy\eclipse_ws\ws34\util\bin\org\aspectj\util\FileUtil.class but it is not structural 9:0:6 Found state instance managing output location : D:\Andy\eclipse_ws\ws34\weaver\bin 9:0:6 Found state instance managing output location : D:\Andy\eclipse_ws\ws34\tests\bin 9:0:6 Timer event: 0ms: Post compile 9:0:6 Found state instance managing output location : D:\Andy\eclipse_ws\ws34\ajdoc\bin 9:0:6 Found state instance managing output location : D:\Andy\eclipse_ws\ws34\util\bin 9:0:6 Change detected in D:\Andy\eclipse_ws\ws34\util\bin\org\aspectj\util\FileUtil$1.class but it is not structural 9:0:6 Change detected in D:\Andy\eclipse_ws\ws34\util\bin\org\aspectj\util\FileUtil$2.class but it is not structural 9:0:6 Change detected in D:\Andy\eclipse_ws\ws34\util\bin\org\aspectj\util\FileUtil$3.class but it is not structural 9:0:6 Change detected in D:\Andy\eclipse_ws\ws34\util\bin\org\aspectj\util\FileUtil$4.class but it is not structural 9:0:6 Change detected in D:\Andy\eclipse_ws\ws34\util\bin\org\aspectj\util\FileUtil$5.class but it is not structural 9:0:6 Change detected in D:\Andy\eclipse_ws\ws34\util\bin\org\aspectj\util\FileUtil$Pipe.class but it is not structural 9:0:6 Change detected in D:\Andy\eclipse_ws\ws34\util\bin\org\aspectj\util\FileUtil.class but it is not structural 9:0:6 Found state instance managing output location : D:\Andy\eclipse_ws\ws34\bridge\bin 9:0:6 Found state instance managing output location : D:\Andy\eclipse_ws\ws34\asm\bin 9:0:6 Failed to find a state instance managing output location : D:\Andy\eclipse_ws\ws34\org.aspectj.ajdt.core\bin 9:0:6 Found state instance managing output location : D:\Andy\eclipse_ws\ws34\ajde.core\bin 9:0:6 Found state instance managing output location : D:\Andy\eclipse_ws\ws34\org.aspectj.matcher\bin 9:0:7 Preparing for build: planning to be an incremental build 9:0:7 AspectJ reports build successful, build was: INCREMENTAL 9:0:7 AJDE Callback: finish. Was full build: false 9:0:7 Timer event: 493ms: Total time spent in AJDE 9:0:7 Timer event: 9ms: Refresh after build 9:0:7 Crosscutting model sanity checked with no problems 9:0:7 Timer event: 504ms: Total time spent in AJBuilder.build() This final project taking 493ms just to check it doesn't have to do anything - it has a similar look to the traces for Thomas' final projects. time to fire up yourkit
I am concerned about the time it is taking for refreshing a project. I created bug 269017 to see if it is still necessary to refresh the project after a build. Also, I am a little confused by how the same file appears as changed many times in the list of modified files. Could you post your .classpath file for the project that contains this class?
Created attachment 129105 [details] Requested .classpath file It contains an entry for <classpathentry kind="con" path="org.eclipse.tptp.platform.instrumentation.ui.ContainerInitializer/Build to Manage Libraries"/> which must have been added recently while I was "playing around" with the new features in RSA 7.5. It is not needed there I I just noticed that it is there. I will remove it and see if it makes a difference.
ok, yourkit numbers for a whitespace change. This causes 15 downstream project rebuilds to occur. Two numbers are: - time spent in this method and below - time spent in this method alone AjCompiler.build() 3697ms 0 (invoked 16 times) AjdeCoreBuildManager.performBuild(boolean) 3697 0 AjBuildManager.incrementalBuild(AjBuildConfig, IMessageHandler) 3697 0 AjBuildManager.performBuild(AjBuildConfig, IMessageHandler, boolean) 3697 0 AjBuildManager.performCompilation(Collection) 2277 0 AjState.prepareForNextBuild(AjBuildConfig) 1404 0 AjState.pathChange(AjBuildConfig, AjBuildConfig) 1388 15 AjState.classFileChangedInDirSinceFullBuild(File) 1357 15 "java.io.File.lastModified() 811 811 "org.aspectj.util.FileUtil.listClassFiles(File) 499 0 "java.util.AbstractList$Itr.next() 15 15 IncrementalStateManager.findStateManagingOutputLocation(File) 15 "java.io.File.exists() 15 15 AJBuilder$2.recordDecision(String) 15 15 AjState.getBinaryFilesToCompile(boolean) 15 0 interpretation: 16 times we enter performBuild, 1 time that leads to a compilation (performCompilation()), 15 times it leads to 'prepareForNextBuild()'. In prepareForNextBuild we analyse the changes that occurred in code we depend upon. In prepareForNextBuild - in which we are spending 1.4seconds in a profiled run, we spend 0.8seconds calling File.lastModified() and 0.5seconds listing the class files in a directory (so we can call lastModified) So optimizing prepareForNextBuild would potentially remove 1.3seconds of the 1.4seconds spent in prepareForNextBuild
I'm also seeing this problem of the changed file appear multiple times. I only make one whitespace change in FileUtil.java and save but it is listed 16 times in the changes list in the event trace: (not sure if the 16 is related to how many projects I have in my workspace, or it is just coincidence that it matches how many projects will get built). 19:17:38 =========================================================================================== 19:17:38 Build kind = AUTOBUILD 19:17:38 Project=util, kind of build requested=Incremental AspectJ compilation 19:17:38 File: D:\Andy\eclipse_ws\ws34\util\src\org\aspectj\util\FileUtil.java has changed. 19:17:38 build: Examined delta - 1 changed, 0 added, and 0 deleted source files in required project util 19:17:38 Setting list of classpath elements with modified contents: 19:17:38 [] 19:17:38 Classpath = D:\Andy\eclipse_ws\ws34\util\bin;D:/Andy/eclipse_ws/ws34/lib/junit/junit.jar;C:/jvms/jdk1.6.0_10/jre/lib/resources.jar;C:/jvms/jdk1.6.0_10/jre/lib/rt.jar;C:/jvms/jdk1.6.0_10/jre/lib/jsse.jar;C:/jvms/jdk1.6.0_10/jre/lib/jce.jar;C:/jvms/jdk1.6.0_10/jre/lib/charsets.jar;C:/jvms/jdk1.6.0_10/jre/lib/ext/dnsns.jar;C:/jvms/jdk1.6.0_10/jre/lib/ext/dns_sd.jar;C:/jvms/jdk1.6.0_10/jre/lib/ext/localedata.jar;C:/jvms/jdk1.6.0_10/jre/lib/ext/sunjce_provider.jar;C:/jvms/jdk1.6.0_10/jre/lib/ext/sunmscapi.jar;C:/jvms/jdk1.6.0_10/jre/lib/ext/sunpkcs11.jar;D:/Andy/e34/eclipse/plugins/org.aspectj.runtime_1.6.4.20090304172355/aspectjrt.jar; 19:17:38 Timer event: 12ms: Pre compile 19:17:38 Sending the following configuration changes to the compiler: [] 19:17:38 16 source file changes since last build 19:17:38 Compiler configuration for project util has been read by compiler. Resetting. 19:17:38 Configuration was [] 19:17:38 Resetting list of modified source files. Was [D:\Andy\eclipse_ws\ws34\util\src\org\aspectj\util\FileUtil.java, D:\Andy\eclipse_ws\ws34\util\src\org\aspectj\util\FileUtil.java, D:\Andy\eclipse_ws\ws34\util\src\org\aspectj\util\FileUtil.java, D:\Andy\eclipse_ws\ws34\util\src\org\aspectj\util\FileUtil.java, D:\Andy\eclipse_ws\ws34\util\src\org\aspectj\util\FileUtil.java, D:\Andy\eclipse_ws\ws34\util\src\org\aspectj\util\FileUtil.java, D:\Andy\eclipse_ws\ws34\util\src\org\aspectj\util\FileUtil.java, D:\Andy\eclipse_ws\ws34\util\src\org\aspectj\util\FileUtil.java, D:\Andy\eclipse_ws\ws34\util\src\org\aspectj\util\FileUtil.java, D:\Andy\eclipse_ws\ws34\util\src\org\aspectj\util\FileUtil.java, D:\Andy\eclipse_ws\ws34\util\src\org\aspectj\util\FileUtil.java, D:\Andy\eclipse_ws\ws34\util\src\org\aspectj\util\FileUtil.java, D:\Andy\eclipse_ws\ws34\util\src\org\aspectj\util\FileUtil.java, D:\Andy\eclipse_ws\ws34\util\src\org\aspectj\util\FileUtil.java, D:\Andy\eclipse_ws\ws34\util\src\org\aspectj\util\FileUtil.java, D:\Andy\eclipse_ws\ws34\util\src\org\aspectj\util\FileUtil.java] 19:17:38 Preparing for build: planning to be an incremental build 19:17:38 Starting incremental compilation loop 1 of possibly 5 19:17:39 Timer event: 446ms: Time to first compiled message 19:17:39 Timer event: 451ms: Time to first woven message
I have a prototype of a version that calls lastModifiedTime far less. My times for the dependee project builds used to be: Timer event: 120ms: Total time spent in AJDE Timer event: 11ms: Total time spent in AJDE Timer event: 17ms: Total time spent in AJDE Timer event: 24ms: Total time spent in AJDE Timer event: 26ms: Total time spent in AJDE Timer event: 25ms: Total time spent in AJDE Timer event: 96ms: Total time spent in AJDE Timer event: 27ms: Total time spent in AJDE Timer event: 28ms: Total time spent in AJDE Timer event: 41ms: Total time spent in AJDE Timer event: 106ms: Total time spent in AJDE Timer event: 215ms: Total time spent in AJDE Timer event: 97ms: Total time spent in AJDE Timer event: 268ms: Total time spent in AJDE Timer event: 144ms: Total time spent in AJDE Timer event: 302ms: Total time spent in AJDE and now they are: Timer event: 3ms: Total time spent in AJDE Timer event: 6ms: Total time spent in AJDE Timer event: 6ms: Total time spent in AJDE Timer event: 5ms: Total time spent in AJDE Timer event: 6ms: Total time spent in AJDE Timer event: 31ms: Total time spent in AJDE Timer event: 6ms: Total time spent in AJDE Timer event: 8ms: Total time spent in AJDE Timer event: 30ms: Total time spent in AJDE Timer event: 58ms: Total time spent in AJDE Timer event: 110ms: Total time spent in AJDE Timer event: 23ms: Total time spent in AJDE Timer event: 81ms: Total time spent in AJDE Timer event: 90ms: Total time spent in AJDE Timer event: 123ms: Total time spent in AJDE that is down from a total of 1.427 seconds to 0.586 seconds and the saving will scale with however much work has to be done. Those latter ones are still high, wonder why?
(In reply to comment #24) I am wondering why it is necessary to iterate over all dependent projects at all. If I make a change only to a method body for example what needs to be done in dependent projects? As I can see from the traces it is recognized that there are no structural changes in the class the others depend upon. And why need the dependent projects be checked for last modification? I can only imagine that this would need to be done if build all was switched off and is now turned on again and thus it would be possible that these projects needed to be rebuilt. Can you explain this to me please?
> I am wondering why it is necessary to iterate over all dependent projects at > all. If I make a change only to a method body for example what needs to be > done in dependent projects? The intention is the cost of downstream projects should be negligible and you shouldn't notice it, because those builds should terminate straightaway when deciding there is nothing they need to do. That is not the case at the moment, as you are seeing in your case. The eclipse infrastructure is driving these builds based on project dependencies, not me. JDT is not as vocal about logging what it is doing, and is rather more optimal in its analysis, so you don't notice it. From the times for the initial few downstream projects in my most recent comment: Timer event: 3ms: Total time spent in AJDE Timer event: 6ms: Total time spent in AJDE Timer event: 6ms: Total time spent in AJDE Timer event: 5ms: Total time spent in AJDE Timer event: 6ms: Total time spent in AJDE Even if there were 20 projects downstream and they all took 10ms, you wouldn't really notice it, and it would be even less if the event trace view was closed. But currently it is these further downstream ones that need addressing: Timer event: 110ms: Total time spent in AJDE Timer event: 23ms: Total time spent in AJDE Timer event: 81ms: Total time spent in AJDE Timer event: 90ms: Total time spent in AJDE Timer event: 123ms: Total time spent in AJDE You should understand that what we have now is a general solution to incremental compilation, it is far from finished or optimized. I work on situations as I can, when they get to the top of my priority list (yours came up to the top because you observed a regression from 1.6.4 to 1.6.3 and that is unacceptable). If work is done to optimize the downstream builds then that benefits all situations: whether a white space change, a method body change or a structural change. Until as recently as AspectJ 1.6.2 the performance was even worse but I did a huge chunk of work under bug 245566 to improve things. That still left some work to do on the multi project setups, and that is covered by bug 249212 (which is still open) - although I seem to be addressing it in this one actually. > As I can see from the traces it is recognized that there are no structural > changes in the class the others depend upon. > > And why need the dependent projects be checked for last modification? I can > only imagine that this would need to be done if build all was switched off and > is now turned on again and thus it would be possible that these projects > needed to be rebuilt. lastModificationTime needs to be used in cases where there is no state maintained for the class files upon which the project is depending. The state captures detailed information about inter-type dependencies and when sources were last fully built. There can be a few reasons for this: - you have some external class folder on your classpath, inpath or aspectpath. We have no state for it, we don't know what changes might have been made to the .class files. The only way to know if we need to rebuild this project is whether the last modification times for .class files in the class folder are later than the last time we built this project. Maybe you did just make a method body change, but if all i have to go on is the timestamp change for the .class file then I don't know that, and if I don't assume the worst (and so do a full build) there will be situations where you change something and we don't pick it up - that would be awful. - you depend on a Java project. The JDT keeps its state projects in black box entities which we have trouble seeing inside of, so we don't know what has changed in the other project. We have made progress on this issue, but there is still more to be done. So... I'll carry on fixing things as I can. Incremental compilation is the most complex area of the code, with the most possible variations in user configurations and is tricky to write testcases for.
Here are todays numbers which I am quite pleased with. Timer event: 175ms: Total time spent in AJDE Timer event: 1ms: Total time spent in AJDE Timer event: 1ms: Total time spent in AJDE Timer event: 1ms: Total time spent in AJDE Timer event: 1ms: Total time spent in AJDE Timer event: 1ms: Total time spent in AJDE Timer event: 1ms: Total time spent in AJDE Timer event: 1ms: Total time spent in AJDE Timer event: 2ms: Total time spent in AJDE Timer event: 1ms: Total time spent in AJDE Timer event: 1ms: Total time spent in AJDE Timer event: 1ms: Total time spent in AJDE Timer event: 2ms: Total time spent in AJDE Timer event: 3ms: Total time spent in AJDE Timer event: 2ms: Total time spent in AJDE Timer event: 2ms: Total time spent in AJDE Timer event: 1ms: Total time spent in AJDE Timer event: 2ms: Total time spent in AJDE Timer event: 9ms: Total time spent in AJDE but they do unfortunately shift a lot of blame to AJDT (these times include the AJDE time): Timer event: 223ms: Total time spent in AJBuilder.build() Timer event: 38ms: Total time spent in AJBuilder.build() Timer event: 43ms: Total time spent in AJBuilder.build() Timer event: 21ms: Total time spent in AJBuilder.build() Timer event: 36ms: Total time spent in AJBuilder.build() Timer event: 123ms: Total time spent in AJBuilder.build() Timer event: 126ms: Total time spent in AJBuilder.build() Timer event: 59ms: Total time spent in AJBuilder.build() Timer event: 199ms: Total time spent in AJBuilder.build() Timer event: 53ms: Total time spent in AJBuilder.build() Timer event: 46ms: Total time spent in AJBuilder.build() Timer event: 85ms: Total time spent in AJBuilder.build() Timer event: 143ms: Total time spent in AJBuilder.build() Timer event: 119ms: Total time spent in AJBuilder.build() Timer event: 48ms: Total time spent in AJBuilder.build() Timer event: 2898ms: Total time spent in AJBuilder.build() Timer event: 80ms: Total time spent in AJBuilder.build() Timer event: 28ms: Total time spent in AJBuilder.build() Timer event: 24ms: Total time spent in AJBuilder.build() i'm still testing these changes, nothing committed yet.
Created attachment 129284 [details] Log of a run with latest AspectJ changes Here is a complete log for a whitespace change to the top level project.
All AspectJ changes are in - this will help the AJDE times - it should be in an imminent AJDT 1.6.5 dev build. Needs a lot of testing before AspectJ 1.6.4 is final though. I don't plan to do anything further on the AspectJ side for this bug unless there are still issues with Thomas' configuration and the fixes so far. I know Andrew is now looking into reducing the AJDT times.
i should say that obviously i reduced the times so drastically by removing unnecessary calls to lastModifiedTime() and listClassFiles() because there were some situations where we were erroneously not trusting the state object when we should have. However, as I'm uncovering in bug 267245 the lack of proper support for when the aj project depends on a java project (because we can't see into their state) needs addressing as we will fall back on listClassFiles()/lastModifiedTime().
First of all thanks for your efforts you are putting into this. I have one more questions. If I understand correctly the problem is that you need to determine if the class files in a project A have changed in case project B depends on it. This will only be of interest in case project B is an AspectJ project. If project A is also an AspectJ project the state about project A is saved in an AJDE internal data structure (BTW what does AJDE stand for?). So it is easy to determine if class files that have changed since the last time project A was build exist in project B. This state is not persistent at the moment (see bug 268822). Now, when I make a white space change in project B project A will be built. If project A also depends on say project C which is not an AspectJ project you will need to fall back to checking last modification times of the class files in project C. Is this correct? If so wouldn't it be even faster if I'd convert all Java projects to AspectJ projects to speedup these issues? The problem is that currently I have quite a lot of projects upon which some of the downstream AspectJ projects depend on. In the concrete sample for which I made the traces it is like this. I am making a change to fwk.common.ass.persist which is an AspectJ project. The downstream project fwk.rcs is also an Aspectj project but it depends on these projects: org.eclipse.ui org.eclipse.core.runtime org.eclipse.ui.forms org.apache.commons.lang com.dcx.iap.clientcontainer.plugin com.ibm.ebiz.fwk com.ibm.ebiz.fwk.eclipse com.dcx.ivkmds.fwk.common com.dcx.ivkmds.fwk.common.ass.cmd com.dcx.ivkmds.fwk.common.ass.cmd.ejb.client com.dcx.ivkmds.fwk.common.ass.error com.dcx.ivkmds.fwk.common.ass.lrt com.dcx.ivkmds.fwk.common.ass.persist -> AspectJ project com.dcx.ivkmds.fwk.common.ass.security com.dcx.ivkmds.fwk.common.ass.usecase com.dcx.ivkmds.fwk.common.spec.error com.dcx.ivkmds.fwk.common.spec.lrt com.dcx.ivkmds.fwk.common.spec.trace com.dcx.ivkmds.fwk.common.spec.perflog com.dcx.ivkmds.fwk.common.spec.time org.aspectj.runtime Only one of these referenced projects is an AspectJ project I could convert these projects to AspectJ projects: com.ibm.ebiz.fwk com.ibm.ebiz.fwk.eclipse com.dcx.ivkmds.fwk.common com.dcx.ivkmds.fwk.common.ass.cmd com.dcx.ivkmds.fwk.common.ass.cmd.ejb.client com.dcx.ivkmds.fwk.common.ass.error com.dcx.ivkmds.fwk.common.ass.lrt com.dcx.ivkmds.fwk.common.ass.persist -> AspectJ project com.dcx.ivkmds.fwk.common.ass.security com.dcx.ivkmds.fwk.common.ass.usecase com.dcx.ivkmds.fwk.common.spec.error com.dcx.ivkmds.fwk.common.spec.lrt com.dcx.ivkmds.fwk.common.spec.trace com.dcx.ivkmds.fwk.common.spec.perflog com.dcx.ivkmds.fwk.common.spec.time The others are precompiled. That said, I believe working on getting the necessary state form JDT directly would improve performance in my case a lot. How are the chances getting this done?
This is now live in the latest AJDT dev builds. > If project A is also an AspectJ project the state about project A is saved in > an AJDE internal data structure (BTW what does AJDE stand for?). So it is easy > to determine if class files that have changed since the last time project A > was build exist in project B. This state is not persistent at the moment > (see bug 268822). AJDE is kind of an historical thing, a name for the AspectJ Development Environment interface - the point where an IDE hands over to the compiler to do compilation. AJDE is suitable for plugging into any IDE (eclipse or something else). > If so wouldn't it be even faster if I'd convert all Java projects to AspectJ > projects to speedup these issues? Yes, it will - but I'm always nervous to suggest that to people, it may be just too big of a step for them. And it kind of forces AspectJ on them to work around a bug we haven't fixed yet - it used to be more painful than it is now because at least the editors are well behaved in an aj project now. I just tried it myself and have attached some numbers at the end of this comment based on todays AJDT dev build. Converting them all to AJ may also impact your eclipse start time as all the projects (even those that used to be Java) will be rebuilt from scratch. > That said, I believe working on getting the necessary state form JDT directly > would improve performance in my case a lot. How are the chances getting this > done? Without JDT weaving it would be very tricky, but now that AJDT is capable of weaving JDT as eclipse starts, we can do it more easily. It is not a trivial bit of work though - initially I'll use some reflection to get at the state and if that works look to modify it more cleanly with JDT Weaving. Have you tried the latest build just to see if your numbers are any better? Here are my figures with the latest build for AJDE and in the AJDT builder. Initially one project is still a Java project in the chain: Timer event: 108ms: Total time spent in AJDE Timer event: 1ms: Total time spent in AJDE Timer event: 1ms: Total time spent in AJDE Timer event: 0ms: Total time spent in AJDE Timer event: 0ms: Total time spent in AJDE Timer event: 1ms: Total time spent in AJDE Timer event: 0ms: Total time spent in AJDE Timer event: 0ms: Total time spent in AJDE Timer event: 0ms: Total time spent in AJDE Timer event: 0ms: Total time spent in AJDE Timer event: 0ms: Total time spent in AJDE >> this next project is the first time we hit a project build that >> has a java project dependency - see the jump in time, here and for >> all downstream builds. Timer event: 54ms: Total time spent in AJDE Timer event: 51ms: Total time spent in AJDE Timer event: 1ms: Total time spent in AJDE Timer event: 51ms: Total time spent in AJDE Timer event: 46ms: Total time spent in AJDE Timer event: 41ms: Total time spent in AJDE --- Converting that project to an aspectj project too: Timer event: 108ms: Total time spent in AJDE Timer event: 0ms: Total time spent in AJDE Timer event: 1ms: Total time spent in AJDE Timer event: 0ms: Total time spent in AJDE Timer event: 0ms: Total time spent in AJDE Timer event: 1ms: Total time spent in AJDE Timer event: 1ms: Total time spent in AJDE Timer event: 1ms: Total time spent in AJDE Timer event: 0ms: Total time spent in AJDE Timer event: 0ms: Total time spent in AJDE Timer event: 0ms: Total time spent in AJDE Timer event: 0ms: Total time spent in AJDE Timer event: 3ms: Total time spent in AJDE Timer event: 1ms: Total time spent in AJDE Timer event: 1ms: Total time spent in AJDE Timer event: 1ms: Total time spent in AJDE Timer event: 1ms: Total time spent in AJDE Timer event: 5ms: Total time spent in AJDE But the AJBuilder times are still ugly: Timer event: 141ms: Total time spent in AJBuilder.build() Timer event: 34ms: Total time spent in AJBuilder.build() Timer event: 44ms: Total time spent in AJBuilder.build() Timer event: 23ms: Total time spent in AJBuilder.build() Timer event: 37ms: Total time spent in AJBuilder.build() Timer event: 183ms: Total time spent in AJBuilder.build() Timer event: 153ms: Total time spent in AJBuilder.build() Timer event: 40ms: Total time spent in AJBuilder.build() Timer event: 77ms: Total time spent in AJBuilder.build() Timer event: 64ms: Total time spent in AJBuilder.build() Timer event: 122ms: Total time spent in AJBuilder.build() Timer event: 263ms: Total time spent in AJBuilder.build() Timer event: 195ms: Total time spent in AJBuilder.build() Timer event: 70ms: Total time spent in AJBuilder.build() Timer event: 3845ms: Total time spent in AJBuilder.build() Timer event: 83ms: Total time spent in AJBuilder.build() Timer event: 55ms: Total time spent in AJBuilder.build() we must get rid of the refresh. I see two ways to proceed: - the hard way (and the correct way) - get what we need out of the JDT state object. Going to be tricky as I might need a callback to AJDT to ask for it because in the compiler I can't just grab it. - a simpler way that will help but not fix everything. As we see in the first set of numbers I put in today, we pay a price for encountering a java project. But we pay the same price each time it is encountered after that - it would be very easy to remember (for that compile only) what we learn for a particular bin folder and not recalculate it each time. For the numbers above: Timer event: 54ms: Total time spent in AJDE Timer event: 51ms: Total time spent in AJDE Timer event: 1ms: Total time spent in AJDE Timer event: 51ms: Total time spent in AJDE Timer event: 46ms: Total time spent in AJDE Timer event: 41ms: Total time spent in AJDE it would then be likely that everything after the first 54 will be back down to 0/1. i might explore the first option a little and if I hit a brick wall for now then switch to the second. The second seems more achievable for 1.6.4
I'd like to remove the refresh after build for AJ projects, but it is proving to be more difficult than I had thought. Bug 101481 describes how a full refresh after build is required when there is a Java project that depends on this AJ project. Apparently, even with the new finer grained control over refreshes, this is still a necessity. Currently, when we only have AJ projects, AJDT is more nuanced with its refreshing. It tries to only refresh output folders that have changed, but now I think that even this can be disabled due to our better management of file creation. As Andy suggests, though, this is not necessarily a recommendation to turn everything into an AJ project. So, in this scenario, we are seeing these huge refresh times because there are Java projects that depend on your AJ projects. I think we can optimize this. So, I will look into this some more.
Good news. It seems that AJDT was only doing a refresh when a class file hadn't previously existed. So, if ajc had deleted and then created a new class file, no refresh would have occurred because Eclipse wasn't aware of the deletion. So, now I changed things so that when AJDT is notified of a write to a class file, it always refreshes regardless of its previous existance. Now, dependent Java projects properly see the changed class files. And I think I can remove the refresh after build. I still need to do some more testing, but I am confident that this will work. I may need to tweak the way resources are refreshed.
adding dependency on bug 269435 since we'll need that map to inspect the state objects for java projects. The 'quick solution' is harder than I first thought - due to the lifecycle issue. We don't really know when to clear any cached information as builds can be fired off at any time for any reason by the eclipse infrastructure.
I think AJDT is going to need a new call back for deleted Java files and deleted class files. There is already: CoreOutputLocation.reportClassFileWrite I require something like CoreOutputLocation.reportClassFileRemove This should be called when a class file is removed, but not recreated. Alternatively, if this information is not easy to get, you can just call CoreOutputLocation.reportClassFileRemove for every class file removed and then call reportClassFileWrite for when they are recreated. I don't think the performance hit would be too bad.
i will look into that tomorrow
Thanks. I'm also noticing that there seems to be a full build (or at least all class files are recreated) when a source file is deleted or a package is deleted. Maybe this is supposed to happen, but it does seem inefficient. Attaching a test project.
Arrgh. I was hoping to have a good test case for this, but can't make it fail consistently. It may have something to do with timestamps and ensuring that they are > 1000ms apart between builds. Too tired to look at this now.
defer that to another bug - raise one to track it. I think the focus on this bug is fast incremental for the mainline case and that is repeated editing and saving whilst working on an existing source file.
New callback is now implemented in AspectJ (with empty implementation) in AJDT: reportClassFileRemove()
Thanks. However, the reportClassFileRemoved() method must be called after the actual removal occurs. This way, the call to refreshLocal picks up the change.
sigh - just the same thing as we had with that other api last time. fix committed.
*** Bug 249212 has been marked as a duplicate of this bug. ***
Ok, I'm using the stub implementation API for mapping outputlocation to java project, here are the times with it switched off. (Time jumps to 23ms when we hit the Java project on the classpath) Timer event: 160ms: Total time spent in AJDE Timer event: 0ms: Total time spent in AJDE Timer event: 0ms: Total time spent in AJDE Timer event: 0ms: Total time spent in AJDE Timer event: 1ms: Total time spent in AJDE Timer event: 1ms: Total time spent in AJDE Timer event: 1ms: Total time spent in AJDE Timer event: 1ms: Total time spent in AJDE Timer event: 0ms: Total time spent in AJDE Timer event: 1ms: Total time spent in AJDE Timer event: 1ms: Total time spent in AJDE Timer event: 23ms: Total time spent in AJDE Timer event: 24ms: Total time spent in AJDE Timer event: 2ms: Total time spent in AJDE Timer event: 28ms: Total time spent in AJDE Timer event: 1ms: Total time spent in AJDE Timer event: 23ms: Total time spent in AJDE Timer event: 23ms: Total time spent in AJDE Turning on my change: Timer event: 180ms: Total time spent in AJDE Timer event: 0ms: Total time spent in AJDE Timer event: 1ms: Total time spent in AJDE Timer event: 1ms: Total time spent in AJDE Timer event: 1ms: Total time spent in AJDE Timer event: 6ms: Total time spent in AJDE Timer event: 1ms: Total time spent in AJDE Timer event: 1ms: Total time spent in AJDE Timer event: 1ms: Total time spent in AJDE Timer event: 1ms: Total time spent in AJDE Timer event: 1ms: Total time spent in AJDE Timer event: 2ms: Total time spent in AJDE Timer event: 4ms: Total time spent in AJDE Timer event: 4ms: Total time spent in AJDE Timer event: 5ms: Total time spent in AJDE Timer event: 3ms: Total time spent in AJDE Timer event: 7ms: Total time spent in AJDE Timer event: 4ms: Total time spent in AJDE costs are greatly reduced - the remaining time might be reflection, or the hack I'm doing because I can't quickly determine the project for an output folder. So, my side of this is complete - and I'll commit it, but it won't spring to life until the AJDT enhancement in bug 269435 is implemented. At that time I'll do a bit more profiling and testing.
Thomas - do you have many messages come out of your projects when they build? By that I mean warnings/todos/etc? Under bug 269912 I've discovered some code that can slow things down if there are many messages coming out. It added 20% to compile times for my projects that produce 8000 warning messages (which i keep ignoring...)
Created attachment 129869 [details] yourkit profile picture Just 'fyi' I've attached a yourkit profile of an incremental compile that I just performed. This is all threads together so possibly some of the marker work done in jobs is shown here. It may be interesting nevertheless - showing that of the 275seconds (greatly slowed down by a detailed profile run), 40% is in UIBuildListener.postCallListeners(), 29% is in UIBuildListener.preCallListeners() and 27% is actually compiling. I think it is worth a quick look over the methods it indicates to see if anything can be done smarter (even if that requires further compiler callbacks to help AJDT).
I am done on the AspectJ side of this now. I don't plan on doing any more for 1.6.4 but it would be nice to get the remaining two things addressed in AJDT just to make sure the 1.6.4 AspectJ is behaving correctly. What seems to be remaining: - removing refresh after build (bug 269604) - map from output folder to originating java project (bug 269435) Until the latter one is there, my code to do faster builds for AJ projects depending on Java projects will not activate.
Created attachment 130079 [details] trace no. 1 with new dev build Times in AJDT and AJBuilder look much better now. Still we are far away from subsecond times. Looking at the progress view in eclipse revealse that deleting and creeating the markers takes a long time. This can also be seen at the end of the trace. Anyway, build times are much faster now. Thank you very much for your work. I really appreciate it. I hope that you might have some ideas on speeding up the marker creation.
Created attachment 130080 [details] trace no. 2 with new dev build Now this run was much faster. I don't think any markers were changed although I don't understand why not this time.
Created attachment 130081 [details] trace no. 3 with new dev build Also very fast. No markers recreated.
(In reply to comment #51) > Created an attachment (id=130081) [details] > trace no. 3 with new dev build > > Also very fast. No markers recreated. > This looks very promising. If bug 268822 were also fixed in 1.6.5 I think our developers would greatly benefit.
marker creation is happening as a separate job at the end of the build process - so it shouldn't damage your development experience too much as you will be back in control and it will be running in the 'background'. But I agree it would be nice to get those times lower. The AJDT refresh times are now zero, but AJDT is still doing something expensive post build. AJDE times are what I wanted them to be - where there is a >100ms glitch in a downstream build, that may be when a dependency on a Java project is hit and should be addressed when bug 269435 is fixed. Possibly my yk profile in comment 47 will help determine why AJDT is still having issues.
tested fix for 269435 - appears to work in my scenario. Here is the log entry when we hit the java project dependency: 11:30:4 Failed to find a state instance managing output location : F:\workspaces\testws\org.aspectj.ajdt.core\bin 11:30:4 'F:\workspaces\testws\org.aspectj.ajdt.core\bin' is apparently unchanged so not performing timestamp check So, on a whitespace change to my top level project, here are the AJDE times - great! Timer event: 172ms: Total time spent in AJDE Timer event: 1ms: Total time spent in AJDE Timer event: 1ms: Total time spent in AJDE Timer event: 0ms: Total time spent in AJDE Timer event: 0ms: Total time spent in AJDE Timer event: 1ms: Total time spent in AJDE Timer event: 1ms: Total time spent in AJDE Timer event: 0ms: Total time spent in AJDE Timer event: 1ms: Total time spent in AJDE Timer event: 1ms: Total time spent in AJDE Timer event: 1ms: Total time spent in AJDE Timer event: 1ms: Total time spent in AJDE Timer event: 2ms: Total time spent in AJDE Timer event: 1ms: Total time spent in AJDE Timer event: 2ms: Total time spent in AJDE Timer event: 0ms: Total time spent in AJDE Timer event: 2ms: Total time spent in AJDE Timer event: 2ms: Total time spent in AJDE Here are the AJBuilder times: Timer event: 195ms: Total time spent in AJBuilder.build() Timer event: 16ms: Total time spent in AJBuilder.build() Timer event: 13ms: Total time spent in AJBuilder.build() Timer event: 7ms: Total time spent in AJBuilder.build() Timer event: 17ms: Total time spent in AJBuilder.build() Timer event: 26ms: Total time spent in AJBuilder.build() Timer event: 23ms: Total time spent in AJBuilder.build() Timer event: 31ms: Total time spent in AJBuilder.build() Timer event: 2ms: Total time spent in AJBuilder.build() Timer event: 6ms: Total time spent in AJBuilder.build() Timer event: 10ms: Total time spent in AJBuilder.build() Timer event: 10ms: Total time spent in AJBuilder.build() Timer event: 34ms: Total time spent in AJBuilder.build() Timer event: 5ms: Total time spent in AJBuilder.build() Timer event: 24ms: Total time spent in AJBuilder.build() Timer event: 3ms: Total time spent in AJBuilder.build() Timer event: 6ms: Total time spent in AJBuilder.build() Timer event: 5ms: Total time spent in AJBuilder.build()
The remaining time in AJBuilder is spent, I believe, in the sections that look for deltas in the current project and the projects it depends on. I am adding a bunch more logging statements in the builder code that can help prove this. If so, there might be some work I can do to get these times down even further.
i'll lookout for the timers appearing and give you some numbers.
just timed a project that was showing a build time of 4ms (ajde) then 43ms (ajbuilder) - yourkit says the cost is in UIBuildListener.projectAlreadyMarked 75% of it is Resource.findMarkers() 13% of it is Marker.getAttribute(String, int) 10% of it is Marker.getAttribute(String,String) the data from the log is something like: 13:36:34 =========================================================================================== 13:36:34 Build kind = AUTOBUILD 13:36:34 Project=tests, kind of build requested=Incremental AspectJ compilation 13:36:34 Timer event: 0ms: Flush included source file cache 13:36:34 Timer event: 0ms: Check delta 13:36:34 Timer event: 0ms: Looking for and marking configurartion changes in tests 13:36:34 Configuration changes found: false 13:36:34 build: Examined delta - no source file or classpath changes for project tests 13:36:34 Timer event: 0ms: Looking for and marking configurartion changes in testing-drivers 13:36:34 Configuration changes found: false 13:36:34 Timer event: 0ms: Looking for and marking configurartion changes in lib 13:36:34 Configuration changes found: false 13:36:34 Timer event: 0ms: Looking for and marking configurartion changes in testing 13:36:34 Configuration changes found: false 13:36:34 Timer event: 0ms: Looking for and marking configurartion changes in org.aspectj.ajdt.core 13:36:34 Configuration changes found: false 13:36:34 File: F:\workspaces\testws\util\src\org\aspectj\util\FileUtil.java has changed. 13:36:34 build: Examined delta - 1 changed, 0 added, and 0 deleted source files in required project util 13:36:34 Timer event: 0ms: Looking for and marking configurartion changes in util 13:36:34 Configuration changes found: true 13:36:34 Timer event: 55ms: Look for source/resource changes 13:36:34 Setting list of classpath elements with modified contents: 13:36:34 [F:/workspaces/testws/testing-drivers/bin, F:/workspaces/testws/lib/commons/commons.jar, F:/workspaces/testws/testing/bin, F:/workspaces/testws/util/bin, F:/workspaces/testws/bridge/bin, F:/workspaces/testws/util/bin, F:/workspaces/testws/bridge/bin, F:/workspaces/testws/asm/bin, F:/workspaces/testws/org.aspectj.ajdt.core/bin, F:/workspaces/testws/org.eclipse.jdt.core/jdtcore-for-aspectj.jar, F:/workspaces/testws/ajde.core/bin, F:/workspaces/testws/asm/bin, F:/workspaces/testws/weaver/bin, F:/workspaces/testws/testing-util/bin, F:/workspaces/testws/org.aspectj.matcher/bin] 13:36:34 Classpath = F:\workspaces\testws\tests\bin;F:\workspaces\testws\testing-drivers\bin;F:/workspaces/testws/lib/junit/junit.jar;F:\workspaces\testws\testing\bin;F:/workspaces/testws/lib/commons/commons.jar;F:\workspaces\testws\org.aspectj.ajdt.core\bin;F:\workspaces\testws\util\bin;F:\workspaces\testws\bridge\bin;F:\workspaces\testws\ajde.core\bin;F:\workspaces\testws\asm\bin;F:/workspaces/testws/org.eclipse.jdt.core/jdtcore-for-aspectj.jar;F:/workspaces/testws/lib/bcel/bcel.jar;F:/workspaces/testws/lib/ant/lib/ant-launcher.jar;F:\workspaces\testws\weaver\bin;F:\workspaces\testws\testing-util\bin;F:/workspaces/testws/lib/bcel/bcel-verifier.jar;E:/jvms/jdk1.6.0_06/jre/lib/resources.jar;E:/jvms/jdk1.6.0_06/jre/lib/rt.jar;E:/jvms/jdk1.6.0_06/jre/lib/jsse.jar;E:/jvms/jdk1.6.0_06/jre/lib/jce.jar;E:/jvms/jdk1.6.0_06/jre/lib/charsets.jar;E:/jvms/jdk1.6.0_06/jre/lib/ext/dnsns.jar;E:/jvms/jdk1.6.0_06/jre/lib/ext/localedata.jar;E:/jvms/jdk1.6.0_06/jre/lib/ext/sunjce_provider.jar;E:/jvms/jdk1.6.0_06/jre/lib/ext/sunmscapi.jar;E:/jvms/jdk1.6.0_06/jre/lib/ext/sunpkcs11.jar;F:\workspaces\testws\org.aspectj.matcher\bin;F:/workspaces/aspectj16_2/org.aspectj.runtime/aspectjrt.jar; 13:36:34 Timer event: 102ms: Pre compile 13:36:34 Sending the following configuration changes to the compiler: [] 13:36:34 0 source file changes since last build 13:36:34 Compiler configuration for project tests has been read by compiler. Resetting. 13:36:34 Configuration was [] 13:36:34 Resetting list of modified source files. Was [] 13:36:34 Found state instance managing output location : F:\workspaces\testws\testing-drivers\bin 13:36:34 No reported changes in that state 13:36:34 Found state instance managing output location : F:\workspaces\testws\testing\bin 13:36:34 No reported changes in that state 13:36:34 Found state instance managing output location : F:\workspaces\testws\util\bin 13:36:34 No reported changes in that state 13:36:34 Found state instance managing output location : F:\workspaces\testws\bridge\bin 13:36:34 No reported changes in that state 13:36:34 Found state instance managing output location : F:\workspaces\testws\util\bin 13:36:34 No reported changes in that state 13:36:34 Found state instance managing output location : F:\workspaces\testws\bridge\bin 13:36:34 No reported changes in that state 13:36:34 Found state instance managing output location : F:\workspaces\testws\asm\bin 13:36:34 No reported changes in that state 13:36:34 Failed to find a state instance managing output location : F:\workspaces\testws\org.aspectj.ajdt.core\bin 13:36:34 'F:\workspaces\testws\org.aspectj.ajdt.core\bin' is apparently unchanged so not performing timestamp check 13:36:34 Found state instance managing output location : F:\workspaces\testws\ajde.core\bin 13:36:34 No reported changes in that state 13:36:34 Found state instance managing output location : F:\workspaces\testws\asm\bin 13:36:34 No reported changes in that state 13:36:34 Found state instance managing output location : F:\workspaces\testws\weaver\bin 13:36:34 No reported changes in that state 13:36:34 Found state instance managing output location : F:\workspaces\testws\testing-util\bin 13:36:34 No reported changes in that state 13:36:34 Found state instance managing output location : F:\workspaces\testws\org.aspectj.matcher\bin 13:36:34 No reported changes in that state 13:36:34 Preparing for build: planning to be an incremental build 13:36:34 AspectJ reports build successful, build was: INCREMENTAL 13:36:34 AJDE Callback: finish. Was full build: false 13:36:34 Timer event: 3ms: Total time spent in AJDE 13:36:34 Timer event: 0ms: Refresh after build 13:36:34 Timer event: 106ms: Total time spent in AJBuilder.build() 13:36:34 ===========================================================================================
Doesn't surprise me that the findMarkers() is taking so long. It is doing a search for the markers at an infinite depth (ie- it trawls the whole project). I really don't understand why the infinite depth is specified. Seems to me that it should only be a depth of 0 (ie- the project resource itself). If I search only to a depth of 0, then these times below should be significantly reduced. But, I don't know what other consequences it will have. (In reply to comment #57) > UIBuildListener.projectAlreadyMarked > 75% of it is Resource.findMarkers() > 13% of it is Marker.getAttribute(String, int) > 10% of it is Marker.getAttribute(String,String)
OK. Just committed a new UIBuildListener where IResource.DEPTH_INFINITE is replaced with IResource.DEPTH_ZERO for marking and unmarking projects. Can you try this out to see fi it works better for you?
Yes, it is faster with that change in: 15:18:11 Build kind = AUTOBUILD 15:18:11 Project=tests, kind of build requested=Incremental AspectJ compilation 15:18:11 Timer event: 0ms: Flush included source file cache 15:18:11 Timer event: 0ms: Check delta 15:18:11 Timer event: 0ms: Looking for and marking configurartion changes in tests 15:18:11 Configuration changes found: false 15:18:11 build: Examined delta - no source file or classpath changes for project tests 15:18:11 Timer event: 0ms: Looking for and marking configurartion changes in testing-drivers 15:18:11 Configuration changes found: false 15:18:11 Timer event: 0ms: Looking for and marking configurartion changes in lib 15:18:11 Configuration changes found: false 15:18:11 Timer event: 0ms: Looking for and marking configurartion changes in testing 15:18:11 Configuration changes found: false 15:18:11 Timer event: 0ms: Looking for and marking configurartion changes in org.aspectj.ajdt.core 15:18:11 Configuration changes found: false 15:18:11 File: F:\workspaces\testws\util\src\org\aspectj\util\FileUtil.java has changed. 15:18:11 build: Examined delta - 1 changed, 0 added, and 0 deleted source files in required project util 15:18:11 Timer event: 0ms: Looking for and marking configurartion changes in util 15:18:11 Configuration changes found: true 15:18:11 Timer event: 1ms: Look for source/resource changes 15:18:11 Setting list of classpath elements with modified contents: 15:18:11 [F:/workspaces/testws/testing-drivers/bin, F:/workspaces/testws/lib/commons/commons.jar, F:/workspaces/testws/testing/bin, F:/workspaces/testws/util/bin, F:/workspaces/testws/bridge/bin, F:/workspaces/testws/util/bin, F:/workspaces/testws/bridge/bin, F:/workspaces/testws/asm/bin, F:/workspaces/testws/org.aspectj.ajdt.core/bin, F:/workspaces/testws/org.eclipse.jdt.core/jdtcore-for-aspectj.jar, F:/workspaces/testws/ajde.core/bin, F:/workspaces/testws/asm/bin, F:/workspaces/testws/weaver/bin, F:/workspaces/testws/testing-util/bin, F:/workspaces/testws/org.aspectj.matcher/bin] 15:18:11 Classpath = F:\workspaces\testws\tests\bin;F:\workspaces\testws\testing-drivers\bin;F:/workspaces/testws/lib/junit/junit.jar;F:\workspaces\testws\testing\bin;F:/workspaces/testws/lib/commons/commons.jar;F:\workspaces\testws\org.aspectj.ajdt.core\bin;F:\workspaces\testws\util\bin;F:\workspaces\testws\bridge\bin;F:\workspaces\testws\ajde.core\bin;F:\workspaces\testws\asm\bin;F:/workspaces/testws/org.eclipse.jdt.core/jdtcore-for-aspectj.jar;F:/workspaces/testws/lib/bcel/bcel.jar;F:/workspaces/testws/lib/ant/lib/ant-launcher.jar;F:\workspaces\testws\weaver\bin;F:\workspaces\testws\testing-util\bin;F:/workspaces/testws/lib/bcel/bcel-verifier.jar;E:/jvms/jdk1.6.0_06/jre/lib/resources.jar;E:/jvms/jdk1.6.0_06/jre/lib/rt.jar;E:/jvms/jdk1.6.0_06/jre/lib/jsse.jar;E:/jvms/jdk1.6.0_06/jre/lib/jce.jar;E:/jvms/jdk1.6.0_06/jre/lib/charsets.jar;E:/jvms/jdk1.6.0_06/jre/lib/ext/dnsns.jar;E:/jvms/jdk1.6.0_06/jre/lib/ext/localedata.jar;E:/jvms/jdk1.6.0_06/jre/lib/ext/sunjce_provider.jar;E:/jvms/jdk1.6.0_06/jre/lib/ext/sunmscapi.jar;E:/jvms/jdk1.6.0_06/jre/lib/ext/sunpkcs11.jar;F:\workspaces\testws\org.aspectj.matcher\bin;F:/workspaces/aspectj16_2/org.aspectj.runtime/aspectjrt.jar; 15:18:11 Timer event: 2ms: Pre compile 15:18:11 Sending the following configuration changes to the compiler: [] 15:18:11 0 source file changes since last build 15:18:11 Compiler configuration for project tests has been read by compiler. Resetting. 15:18:11 Configuration was [] 15:18:11 Resetting list of modified source files. Was [] 15:18:11 Found state instance managing output location : F:\workspaces\testws\testing-drivers\bin 15:18:11 No reported changes in that state 15:18:11 Found state instance managing output location : F:\workspaces\testws\testing\bin 15:18:11 No reported changes in that state 15:18:11 Found state instance managing output location : F:\workspaces\testws\util\bin 15:18:11 No reported changes in that state 15:18:11 Found state instance managing output location : F:\workspaces\testws\bridge\bin 15:18:11 No reported changes in that state 15:18:11 Found state instance managing output location : F:\workspaces\testws\util\bin 15:18:11 No reported changes in that state 15:18:11 Found state instance managing output location : F:\workspaces\testws\bridge\bin 15:18:11 No reported changes in that state 15:18:11 Found state instance managing output location : F:\workspaces\testws\asm\bin 15:18:11 No reported changes in that state 15:18:11 Failed to find a state instance managing output location : F:\workspaces\testws\org.aspectj.ajdt.core\bin 15:18:11 'F:\workspaces\testws\org.aspectj.ajdt.core\bin' is apparently unchanged so not performing timestamp check 15:18:11 Found state instance managing output location : F:\workspaces\testws\ajde.core\bin 15:18:11 No reported changes in that state 15:18:11 Found state instance managing output location : F:\workspaces\testws\asm\bin 15:18:11 No reported changes in that state 15:18:11 Found state instance managing output location : F:\workspaces\testws\weaver\bin 15:18:11 No reported changes in that state 15:18:11 Found state instance managing output location : F:\workspaces\testws\testing-util\bin 15:18:11 No reported changes in that state 15:18:11 Found state instance managing output location : F:\workspaces\testws\org.aspectj.matcher\bin 15:18:11 No reported changes in that state 15:18:11 Preparing for build: planning to be an incremental build 15:18:11 AspectJ reports build successful, build was: INCREMENTAL 15:18:11 AJDE Callback: finish. Was full build: false 15:18:11 Timer event: 2ms: Total time spent in AJDE 15:18:11 Timer event: 0ms: Refresh after build 15:18:11 Timer event: 5ms: Total time spent in AJBuilder.build() ---- but is it a safe change? What markers is it looking for and are they only ever found on the top most element?
(In reply to comment #60) > but is it a safe change? What markers is it looking for and are they only ever > found on the top most element? > Yes. The markers are only added to the top-most (project) resource. These markers are used to determine if there was a failure during the previous build (eg- build was canceled or there was a compiler error, etc). The particular snippet of code checks to see if any depending projects have been marked as failed with a rebuild required. If so, then this project is marked the same. So, it is safe to change the depth. This is a part of the code that I have not looked at yet and it does seem to require a bit of refactoring. I may do so later.
that is great news. sounds like we are pretty much wrapped up on this issue then.
all work completed for this bug.
> > This is a part of the code that I have not looked at yet and it does seem to > require a bit of refactoring. I may do so later. > Did you do this refactoring and check in some changes? When will this be available in a dev build? Thanks.
(In reply to comment #64) > > Did you do this refactoring and check in some changes? When will this be > available in a dev build? > > Thanks. > These changes are currently available in the latest dev build. Further refactorings will likely be covered by a different bug.
I've just noticed this in my day to day work. I have a JDT base project that my AJDT project depends on. If I change a file that isn't woven in the base, I get a very quick build and no re-weaving. If I change one that is woven, it falls back to a full build. This works beautifully for me, as the woven stuff is files I can only do bug fixes to. Nice work!
