Community
Participate
Working Groups
Created attachment 237914 [details] AspectJ trace We are using Rational Software Architect 8.0.4 64-bit (based on Eclipse 3.6.2) and the AJDT plugin 2.1.3.e36x-20110622-1300 for Eclipse 3.6. We have around 270 projects in our workspace, around 40 of them are AspectJ projects. When accept the latest changes from our scm, the building workspace task takes about an hour, even if only a few thing have changed. Sometimes it even takes two hours or more (Win7 development environment), leaving the developer stuck with a blocked IDE. I am attaching an AspectJ trace which shows a 50 minute example; what I notice is entries like "Compiler configuration for project XYZ doesn't know previous state, so assuming EVERYTHING has changed." although we have "Incremental Compiler Optimizations" checked in the AspectJ workspace preferences and no project specific settings. Could you have a look at the trace and tell me, if it is the sheer number of projects which causes the long build times, or if we maybe have some misconfiguration? Thank you!
Hi, A few things at play here. You are on windows (which may affect path analysis) and you are using a rather old AJDT (and I can't recall what fixes, if any, related to incremental analysis have gone in since mid 2011) - i see it is AspectJ 1.6.12.M1. How is it on memory in this setup, are you running with lots free or at the Xmx threshold? If you are tight on memory some operations will take much longer (like builds) because of GC thrashing. The "doesn't know previous state" message I would expect on first startup of the eclipse or after a workspace clean. But other operations, like pulling in changes from an SCM shouldn't cause that. Was this trace created after a fresh startup where SCM changes were pulled in? AspectJ does not preserve compiler state across eclipse restarts like JDT does, so I would expect this kind of trace after a restart. However, even for a full build the compilation speed seems bad. I'm suspicious of memory again? Having said all that i'm sure there are still issues in the code that analyzes project changes, and it only takes you hitting one of these problems for all downstream projects to suddenly require a full build. Can you confirm when the trace was taken? Most interesting to me would be a trace taken after the first full build has completed, just as you pull in the SCM changes and it triggers a refresh (or you manually trigger a refresh).
Hi Andrew, thanks for the quick response. I created some more traces ("Build Automatically" is always checked): 1. A deliberate full build caused by using "Project - Clean..." on all projects -> 20131203aspectJTrace_Clean.txt taking 1h 13m 2. Pulling some changes from the scm -> 20131203aspectJTrace_Update.txt taking 20s this one looks nice to me, and it also says "Build kind = AUTOBUILD" and "build was: INCREMENTAL" 3. Reverting some local changes I had in my workspace -> 20131203aspectJTrace_Discard.txt taking 1h 13m (like in 1.) it says "Build kind = FULLBUILD" from the beginning (why?) it also mentions "not going to be incremental because no successful previous full build" 4. Again pulling some changes made by others from the scm -> 20131203aspectJTrace_Update_2.txt taking 27m this one is interesting as it starts with "Build kind = AUTOBUILD" but finishes with "build successful, build was: FULL" I hope you can make something out of the traces. Btw the heap goes up to 1800M; a lot, but not yet at the limit of 2048M (-Xmx2048m)
Created attachment 237948 [details] trace: Clean all
Created attachment 237949 [details] trace: Accept changesets from scm
Created attachment 237950 [details] trace: Discard local changes
Created attachment 237951 [details] trace: Accept some more changesets
Quick observation, for case (4) I see a line: 13:20:33 ClassFileChangeChecking: aspect found that has structurally changed : E:\ws_rel17\com.dcx.ivkmds._45_export_import.ass\aspect-bin\com\dcx\ivkmds\_45_export_import\ass\MeasuringPoint.class If an aspect has changed, we do fall back to full builds as we don't know how far reaching the changes are in the aspect. If you have, say, widened the scope of a point cut we don't know which additional types are going to be affected so we have to start again with a full build for projects that might be affected by that aspect. The optimized case (in terms of incremental compilation) is when regular types are changing, whereas aspects changing is the unusual case. Are you heavily changing aspects? If you are confident that the aspect *hasnt* changed, we should investigate that - it would be a bug in the analyzer that detects structural differences. (and it is likely bugs or new unhandled cases in this area that is leading to longer build times)
> it says "Build kind = FULLBUILD" from the beginning (why?) How are you doing the revert? Are you using tools inside eclipse or tools outside of eclipse then doing a refresh inside eclipse? I'm looking at the case (1) too. Unusual thing there is no timer events between 9.31 and 10.04 - I presume it is building java code during that time and not AspectJ projects.
Regarding case (4): The MeasuringPoint.aj has definitely not changed for months. But looking at MeasuringPoint.class in the file system, I see a creation time stamp December 3rd 10:10 (the time of the full build) and a last modification time stamp of December 3rd 12:54! This seems to be coming from the build starting at 12:54:44 in the 20131203aspectJTrace_Update_2.txt I'm doing the revert inside eclipse, using the Jazz SCM plugin. I had removed the AspectJ builder from one of our projects; the revert added it again.
Can I provide anything else? Is there something special I should testcase and trace?
Hi Martin. The fastest way to get this addressed is for me to be able to duplicate the setup and debug it directly - but I don't suppose that is feasible? Debugging such a large configuration with these logs after its happened is very very tricky. If it were a much smaller setup, I might have more of a chance with the logs. What I was just browsing through is the matches for this: grep "aspect found that has structurally changed" 20131203aspectJTrace_Update_2.txt I see about 20 and I'm wondering why.
Also observe this in that log file: 12:54:21 Resetting list of modified source files. Was [E:\ws_rel17\com.dcx.ivkmds.application.ass\src\com\dcx\ivkmds\_2501_change_log\pc\repository\hibernate\DefaultChangeLogRepository.java, E:\ws_rel17\com.dcx.ivkmds.application.ass\src\com\dcx\ivkmds\_2501_change_log\pc\repository\hibernate\DefaultChangeLogRepository.java, E:\ws_rel17\com.dcx.ivkmds.application.ass\src\com\dcx\ivkmds\_2501_change_log\pc\repository\hibernate\DefaultChangeLogRepository.java, E:\ws_rel17\com.dcx.ivkmds.application.ass\src\com\dcx\ivkmds\_2501_change_log\pc\repository\hibernate\DefaultChangeLogRepository.java, E:\ws_rel17\com.dcx.ivkmds.application.ass\src\com\dcx\ivkmds\_2501_change_log\pc\repository\hibernate\DefaultChangeLogRepository.java, E:\ws_rel17\com.dcx.ivkmds.application.ass\src\com\dcx\ivkmds\_2501_change_log\pc\repository\hibernate\DefaultChangeLogRepository.java, E:\ws_rel17\com.dcx.ivkmds.application.ass\src\com\dcx\ivkmds\_2501_change_log\pc\repository\hibernate\DefaultChangeLogRepository.java, E:\ws_rel17\com.dcx.ivkmds.application.ass\src\com\dcx\ivkmds\_2501_change_log\pc\repository\hibernate\DefaultChangeLogRepository.java, E:\ws_rel17\com.dcx.ivkmds.application.ass\src\com\dcx\ivkmds\_2501_change_log\pc\repository\hibernate\DefaultChangeLogRepository.java, E:\ws_rel17\com.dcx.ivkmds.application.ass\src\com\dcx\ivkmds\_2501_change_log\pc\repository\hibernate\DefaultChangeLogRepository.java, E:\ws_rel17\com.dcx.ivkmds.application.ass\src\com\dcx\ivkmds\_2501_change_log\pc\repository\hibernate\DefaultChangeLogRepository.java, E:\ws_rel17\com.dcx.ivkmds.application.ass\src\com\dcx\ivkmds\_2501_change_log\pc\repository\hibernate\DefaultChangeLogRepository.java, E:\ws_rel17\com.dcx.ivkmds.application.ass\src\com\dcx\ivkmds\_2501_change_log\pc\repository\hibernate\DefaultChangeLogRepository.java, E:\ws_rel17\com.dcx.ivkmds.application.ass\src\com\dcx\ivkmds\_2501_change_log\pc\repository\hibernate\DefaultChangeLogRepository.java, E:\ws_rel17\com.dcx.ivkmds.application.ass\src\com\dcx\ivkmds\_07_common\ass\usecase\DefaultRel2ProdLockCommonActivity.java, E:\ws_rel17\com.dcx.ivkmds.application.ass\src\com\dcx\ivkmds\_07_rel2prodlock\pc\repository\Rel2ProdLockRepository.java, E:\ws_rel17\com.dcx.ivkmds.application.ass\src\com\dcx\ivkmds\_07_rel2prodlock\pc\repository\Rel2ProdLockType.java, E:\ws_rel17\com.dcx.ivkmds.application.ass\src\com\dcx\ivkmds\_07_rel2prodlock\pc\repository\hibernate\StoredProcedureBasedRel2ProdLockRepository.java] Not sure why the same file is repeated over and over.
Hi Andrew, unfortunately our client owns the source code, so I cannot give it to you. But if you want me to do some changes to an aspect or Java class or modify a configuration to isolate the problem, I'll be happy to do so. If you whish, I can provide the list of plugins installed in our ide; maybe there is some interdependency...
Just to say I'm actively looking at this again Martin now I'm back from the christmas holidays. I might need you to run with further debug builds to collect targeted diagnostics.
I'm looking again at those statements which say "ClassFileChangeChecking: aspect found that has structurally changed : XXX". Seems like it would be a good idea to find out what it thinks has structurally changed. You could do this if you can get it into a reliable state where the problem occurs always mentioning the same aspect in the trace. It could be some brittleness in the name of a generated member that is changing on each build even though nothing in the source has changed (I thought these were all fixed but perhaps there is something left behind). What you need to do is: 1) get into a state where you know if you pull in a certain set of changes you are going to see this message for some aspect XXX.class 2) int this initial state take a copy of XXX.class 3) pull in the changes to trigger the build, take a copy of the new XXX.class Run 'javap -private' against the two files, does the output look different in any way? Failing that, use 'javap -private -verbose' which will produce a lot more stuff - what is the apparent difference between the files now?
I've just created a new AJDT that includes better diagnostics. They are better organized and when a structural change is detected the exact nature of it should be printed: 10:45:01 Preparing for build: planning to be an incremental build 10:45:01 Starting incremental compilation loop 1 of possibly 5 10:45:01 Time to first compiled message (took 51ms) 10:45:01 StructuralAnalysis[/Users/aclement/workspaces/runtime-New_configuration(6)/One/bin/B.class]: appears to have structurally changed, printing changes: 10:45:01 StructuralAnalysis[/Users/aclement/workspaces/runtime-New_configuration(6)/One/bin/B.class]: number of methods changed. old=[0x1 <init>()V 0x9 foo()V 0x1 m()V 0x0 n()V 0x0 o()V 0x0 p()V 0x0 qqp()V 0x0 qqp2()V 0x0 qq22pxxt()V 0x0 asdfasdfxxx()V] new=[0x1 <init>()V 0x9 foo()V 0x1 m()V 0x0 n()V 0x0 o()V 0x0 p()V 0x0 qqp()V 0x0 qqp2()V 0x0 qq22pxxt()V 0x0 asdfasdfxxx()V 0x0 foooo()V] 10:45:01 Time to first woven message (took 57ms) 10:45:01 Examining whether any other files now need compilation based on just compiling: '{/Users/aclement/workspaces/runtime-New_configuration(6)/One/src/B.java}' The format is a bit messy but the information is there to identify what structurally changed (here a new method called foooo() was added) This AJDT is for Eclipse 4.3 - are you able to setup your projects in an eclipse at that level just so we can test this out and identify the real issue? I'm waiting for the AJDT build to complete, I'll post the update site when it does.
Extra diagnostics should be in this build: http://download.eclipse.org/tools/ajdt/43aj17/dev/update
Cool; is this build also compatible with Eclipse 4.2? I have an RSA 9 instance which is based on 4.2.2. If not, I am sure I can setup an Eclipse 4.3 with our code. Btw I was not able yet to reproduce the "aspect has structurally changed" message, but I will try.
I just heard that their may have been problems uploading the most recent dev build, so the one there may not contain the extra diagnostics. I will fix that up today. I'm not sure when I'll be organized enough to create a new build for 4.2 (it is feasible) - I can't recall how old that level is, so it may be a bunch of work if the interface between the UI (AJDT) and the compiler (AspectJ) have changed a lot.
ok, no problem. In the meantime, I am setting up an Eclipse 4.3 to compile our code. If it takes extra effort to include the diagnostics info in another release, the Eclipse 3.6.2 build would be better, actually (don't know if that's possible). But let's try with Eclipse 4.3 first.
Finally! The dev build is now up at the update site I mentioned, please try it out. Our build machine was blacklisted from uploading to eclipse.org but that is all fixed now.
I have Eclipse 4.3 setup with our code and it compiles without errors. I have also installed the 20140110 build. Problem is, I cannot connect Eclipse 4.3 with our JazzScm (it's a V2 and there is no V2 client for Kepler) so I need to trigger the compilation through other ways. Until now, the long build times did not occur; I keep on trying...
Created attachment 239051 [details] trace: incremental build with 4.3.1
I created a trace of an incremental build taking 24 min after updating some Java files (20140116_1013_trace.txt). There are no "aspect has structurally changed" messages, but I can see a lot of those: 9:51:11 ClassFileChangeChecking: structural change detected in : E:\ws_431\...\XY.class although XY has not changed.
I had a quick look and I'm not sure that AJDT build included all the necessary diagnostics from what I see in your latest trace. I'm digging into that right now.
Finally! It turns out the build process was accessing a somewhat out of date fork of the repo so didn't contain all my changes. Can you try updating again from that update site? If you are running the new version you should see the trace as indented (in addition to extra diagnostics I'm also trying to tweak what it already creates to make it easier to understand when there is a lot of output)
Created attachment 239215 [details] trace: another incremental build with latest AspectJ dev build I created another trace with the latest build.
Did the trace provide any new insights? I did a lot of updates in the Kepler workspace, but I did not see any long build times... Is there any possible way to include the diagnosis in an AJDT 2.1.3 build? With that I could easily reproduce the problem.
Hi Martin, glad you pinged me on the bug! I hadn't noticed you had already appended a trace and I've been waiting for it to come in. I can see it is in the new format (although looks like some of the indenting needs tweaking!). I am specifically looking for a message like this in the trace: "XXX appears to have structurally changed, printing changes:". (This is triggered when information is recorded about a type after compilation, rather than when it is consumed by a dependant project) But in the trace you attached I see this for the first project in it: 10:39:56 Project=com.dcx.ivkmds.fwk.common.ass.persist, kind of build requested=Incremental AspectJ compilation 10:39:56 Preparing for build: not going to be incremental because no successful previous full build that implies you hadn't gotten a good full build of the projects before trying this incremental build? The build of the persist project doesn't have to finish without errors necessarily, but it does have to have finished. The build state is lost across eclipse restarts so the first builds are always full when you start up the workspace - is that what happened here? (We should try and trim down these traces too, by tweaking the options in the console view so we don't have too much junk in there - the addSourcelineTask entries are not useful so we should remove them (can't remember the option that skips them though). The weaveinfo messages aren't helpful either.)
Created attachment 239513 [details] incremental build with previous successful build
Hi Andrew, I added another trace showing an incremental build with a successful previous build. The last trace was in fact taken from a startup build - sorry.
In the meantime, I am working with Eclipse 4.3.2 on a regular basis, so I can install the diagnosis build there and hopefully get some meaningful traces. My suspicion closes in on the PMD plugin. As long as leave "check code after saving" unchecked, everything is fine. But as soon as I check the option and pull in changes from the scm, my impression is the AspectJ build is nearly stuck. Maybe there is some interference? I will try to reproduce and trace this.
Created attachment 241498 [details] full build with "check code after saving"
Hi Andrey, it's definitive: Without the option, I can do a full build in 10-15min. With "check code after saving", the full build takes 4 hours, including one 30min-break and one 3h-break (!). Can you interpret the trace, if AspectJ may be waiting for PMD (although nothing was saved), or what is happening from 20:24-20:52 and from 20:52-00:02 ? Knowing this doen't really look like an AspectJ problem anymore, do you have any hints where to go from here?
