Bug 85297 - Improvements to incremental compilation
Summary: Improvements to incremental compilation
Status: RESOLVED FIXED
Alias: None
Product: AspectJ
Classification: Tools
Component: Compiler (show other bugs)
Version: DEVELOPMENT   Edit
Hardware: PC Windows XP
: P3 normal (vote)
Target Milestone: 1.5.3   Edit
Assignee: Andrew Clement CLA
QA Contact:
URL:
Whiteboard:
Keywords:
Depends on:
Blocks:
 
Reported: 2005-02-15 12:31 EST by Andrew Clement CLA
Modified: 2006-09-25 11:19 EDT (History)
5 users (show)

See Also:


Attachments
Unusual behavior on 2-17 AJDT (95.27 KB, image/png)
2005-02-21 15:56 EST, Nicholas Lesiecki CLA
no flags Details

Note You need to log in before you can comment on or make changes to this bug.
Description Andrew Clement CLA 2005-02-15 12:31:18 EST
This bug is to track compiler improvements to incremental compilation.

There are multiple scenarios to think about but the first focus is changing one
source file for a class/interface that is affected by an Aspect - it should
compile/weave almost instantly.  Recently response times have been reported of
>3seconds (and worse...) and this is not reasonable.

I've put the following improvements in today:
- Caching classpath calculations rather than performing them repeatedly.
- Improved logic to detect weaver completion.
- Removed unnecessary serialization of the structure model.

These are available in dev builds right now:  	ajdt_1.2.0.20050215161840

I'd be interested in user feedback on whether they see noticeable improvements
in their particular projects.

more improvements to follow shortly.
Comment 1 Nicholas Lesiecki CLA 2005-02-16 11:44:40 EST
Oh. My. God.

The sort of good news: an unscientific average of new incremental compile times
is about 1.8 seconds, which represents a 25% time reduction over the previous
average of 2.5.

The REALLY REALLY good news: My full build times have dropped from aroung 80s.
to around 40s. I can't emphasize how huge this is for our team. This level of
speed increase represents a productivity gain of *hours* per week per developer.

You guys are awesome!
Comment 2 Mik Kersten CLA 2005-02-16 12:06:56 EST
The structure model was getting serialized so that the crosscutting structure 
would be visible when you opened an IDE or when you switched projects in the 
IDE.  I guess that the first case is less important, but the second case does 
seem important.  Won't it be confusing if people switch projects, and all of 
the sudden it looks like nothing has advice?

Or perhaps you've alreayd mad the obvious update that should would mean both a 
performance improvement, little memory overhead, and no need for serialization:
- keep a HashMap from build config to relationship map in memory
- when the active build config (i.e. project) changes swap the active map, or 
instead wjust do a 2-step lookup of the relationship

I'm guessing that the memory requirements of this would be <5 MB on workspaces 
with tens of thousands of classes, and under a dozen projects but it might be 
worth checking.  With workspaces that have dozens of projects we could get 
into a situation where it's better to purge the least recently used 
relationship maps.
Comment 3 Andrew Clement CLA 2005-02-18 12:12:46 EST
I've changed the timers reported to AJDT Event Trace, you don't get meaningless
weaver metrics now, you get:

- total time spent in the AJDT build() method
- within that, the time spent in AJDE (i.e. compiling and weaving)
- number of types affected by what you just did.  (You change an aspect this
will be a high number, you change a single class, it should be 1)

Difference between those first two times is the time spent fiddling with markers
and structure model.

(I've also changed some String handling to String buffers - tiny optimization)

There is still a lot of scope for bringing times down, but I'm going to focus
for the next little while on inter-project dependencies and ensuring when you
change an AspectJ project we don't force an unnecessary build of any Java
project depending on it.
Comment 4 Nicholas Lesiecki CLA 2005-02-21 15:56:32 EST
Created attachment 18149 [details]
Unusual behavior on 2-17 AJDT

I checked out the latest build for the above described better metrics.
Unfortunately, it performs a full rebuild every time a file is saved (though it
claims its doing an autobuild). It does this even with non-Java, non-AJ files.
The most amusing consequence is gutter annotations for my Tapestry files :)
Comment 5 Matt Chapman CLA 2005-02-21 18:08:56 EST
Nicholas, that's very weird! There is a newer build which is worth trying, as
soon as I can get it uploaded - the eclipse infrastructure changed over the
weekend, and we have to change the way we upload, which wasn't working. I'll
append here when it's available - should be tomorrow.
Comment 6 Andrew Clement CLA 2005-03-11 05:30:20 EST
I have just put a new change in CVS that may affect people building in batch
mode (i.e. outside of the IBM) - it will be in the next dev build.  I'd be
interested in whether Nick notices any difference at all.  there was a rogue bit
of structure model still being generated even from the command line when
-emacssym was not specified, I've hopefully now stopped this happening.  Might
reduce memory consumption a bit too.
Comment 7 Adrian Colyer CLA 2005-03-23 09:44:50 EST
batching up a whole set of incremental things under aj5m4...
Comment 8 Nicholas Lesiecki CLA 2005-03-30 13:56:50 EST
I've been poking the 2005-03-25 build, and it seems to have discarded the
incremental mode completely. In other words, it weaves every type in the system
rather than ever doing a true incremental build, despite CLAIMING that it's
doing an incremental. Here's an example trace resulting in changing a Java file
in a trivial way (changing the value of a local variable):

11:35:15 AM	 build: Kind=AUTOBUILD Project=Adbase Mode=Incremental AspectJ
compilation
11:35:20 AM	 Time to first 'compiled:' message: 5344ms
11:35:25 AM	 Time to first 'woven' message: 10656ms
11:35:51 AM	 Time spent in ajde = 36030ms
11:35:55 AM	 Types affected during build = 845 <--- Nota Bene
11:35:57 AM	 Time spent in build() = 42170ms


This has been happening consistently all morning, so I'm forced to downgrade to
the last milestone, or face the wrath of my boss.
Comment 9 Andrew Clement CLA 2005-04-04 06:48:32 EDT
Hmmm.  This could be related to a change Adrian put in just before the easter
break.  There was a problem in the code to do with determining whether to do a
full build or not.  Before the fix there was a crude check to compare the
previous classpath used to build the project with the new classpath being used.
The comparison was:

- Do the classpaths consist of the same elements in the same order
- For a jar or directory, confirm the last mod time is older than the previous
time we built.

If either of these tests fail, we do a full build instead of an incremental one.
What we didn't do, in the case of a directory on the classpath, is check all the
entries in the directory and any subdirectories, to see if anything has changed.
 It was this check that was added.  If this is affecting Nick then the only
reason I can imagine is that between incremental builds the contents of a
directory on the project classpath are changing.  However, if building just that
single project over and over with only a simple change to a class, then the
classpath contents shouldnt be changing *unless* the output directory for the
project is on the classpath - as each incremental build will then be affecting
the following incremental build.  Is there anyway you can check this Nick?
Comment 10 Andrew Clement CLA 2005-04-05 11:10:32 EDT
I have recreated this problem using the AJDT plugins themselves as test code -
and it is what I thought.  The output location is on the input classpath.  I've
put in a fix, should appear in next AJDT.  Does this mean we have reached
1.5.0M2 ... surely not...
Comment 11 Nicholas Lesiecki CLA 2005-04-05 16:05:04 EDT
Glad to hear it's fixed. Sorry I couldn't try anything myself, my boss
threatened to have me professionally killed if I waste another morning
downloading eclipse, ajdt, and trying things out--I'm too busy to try at night.
(Stupid AOP evangelism, I should be working on this ! ) _grin_
Comment 12 Nicholas Lesiecki CLA 2005-04-07 13:38:54 EDT
I just tried the april 7 (i.e. M2 build). The recompile everything bug is gone,
but the overall incremental times are still slow. e.g.(s). Keep up the improvements!


10:31:54 AM	 build: Kind=AUTOBUILD Project=Adbase Mode=Incremental AspectJ
compilation
10:31:55 AM	 Time to first 'compiled:' message: 1171ms
10:31:56 AM	 Time to first 'woven' message: 1312ms
10:31:58 AM	 Time spent in ajde = 4031ms
10:32:00 AM	 Types affected during build = 16
10:32:01 AM	 Time spent in build() = 6953ms
10:32:59 AM	 build: Kind=AUTOBUILD Project=Adbase Mode=Incremental AspectJ
compilation
10:33:01 AM	 Time to first 'compiled:' message: 1187ms
10:33:01 AM	 Time to first 'woven' message: 1296ms
10:33:04 AM	 Time spent in ajde = 4828ms
10:33:05 AM	 Types affected during build = 16
10:33:07 AM	 Time spent in build() = 7187ms
10:33:42 AM	 build: Kind=AUTOBUILD Project=Adbase Mode=Incremental AspectJ
compilation
10:33:44 AM	 Time to first 'compiled:' message: 1187ms
10:33:44 AM	 Time to first 'woven' message: 1672ms
10:33:44 AM	 Time spent in ajde = 1953ms
10:33:46 AM	 Types affected during build = 2
10:33:47 AM	 Time spent in build() = 4875ms
Comment 13 Matt Chapman CLA 2005-04-07 15:03:40 EDT
Nick, are those timings from three builds of the same project without
significant changes inbetween? They seem to vary quite a bit. Also, a greater
than usual amount of time is spent in AJDT, so I will look into that, but we
need to figure out what is different about your project to cause this. Can you
give us an appropriate count of the number of classes and number of aspects in
your project?
Comment 14 Nicholas Lesiecki CLA 2005-04-08 17:35:29 EDT
Yes, I made a change to a different source file for each build. The times _are_
fairly variable... Maybe my computer was affected by solar radiation that day.
Here are two more changes, both adding a new, unused field to a testcase:

2:25:13 PM	 build: Kind=AUTOBUILD Project=Adbase Mode=Incremental AspectJ
compilation
2:25:14 PM	 Time to first 'compiled:' message: 1296ms
2:25:15 PM	 Time to first 'woven' message: 1750ms
2:25:15 PM	 Time spent in ajde = 2015ms
2:25:16 PM	 Types affected during build = 1
2:25:18 PM	 Time spent in build() = 4516ms

2:28:17 PM	 build: Kind=AUTOBUILD Project=Adbase Mode=Incremental AspectJ
compilation
2:28:19 PM	 Time to first 'compiled:' message: 1281ms
2:28:19 PM	 Time to first 'woven' message: 1578ms
2:28:20 PM	 Time spent in ajde = 2109ms
2:28:21 PM	 Types affected during build = 2
2:28:22 PM	 Time spent in build() = 4515ms

A little more stable...

Here's adding a field to a Hibernate object:
2:29:37 PM	 build: Kind=AUTOBUILD Project=Adbase Mode=Incremental AspectJ
compilation
2:29:38 PM	 Time to first 'compiled:' message: 1032ms
2:29:38 PM	 Time to first 'woven' message: 1063ms
2:29:40 PM	 Time spent in ajde = 2500ms
2:29:41 PM	 Types affected during build = 4
2:29:43 PM	 Time spent in build() = 5344ms

As far as my project goes, it has:
58 aspects
793 Java source files

I will happily answer any other questions if it helps.
Comment 15 Andrew Clement CLA 2005-04-26 14:26:38 EDT
Good news for all users that have multiple AJ projects in their workspace - and
particularly for those who have multiple AspectJ projects in some kind of
dependency relationship with each other.  > We can now build all projects
incrementally simultaneously and depending projects resort to a full build far
less often.

An AJDT build will follow shortly...

<gory details>
Change #1:
Until this change, we only ever kept incremental state for one project at a
time.  If anything caused us to build a different project then we discarded the
incremental state we had been storing and did a full build of this different
project, from then on storing the incremental state for it - until we were
forced to change project again.  I've now committed a change so that we can
preserve multiple incremental states, indexed by the build config file being
used.  if you switch to a new config that has no state, we'll create one fresh,
if you switch back to one we do have a config for then the compiler will pick up
where it left off using the right world, weaver and structure model.

Change #2:
Change #1 makes this possible.  There is a bunch of clever stuff in how JDT
manages state and I'm starting to pull it into AJ(DT) where I can.  This change
is the first piece.  Basically there are two kinds of change you can make to a
class - a structural or a non-structural change.  if you change a method
signature, change visibility of something, add a method, delete a field - these
are all structural changes.  However, if you just change the body of a method or
add whitespace/comments then this is a non-structural change.  In the case of a
non-structural change the compiler will of course rebuild the code and write out
a class file to disk but effectively it hasn't changed for anyone consuming it.
 AspectJ used to just look at timestamps of class files.  This meant if project2
depended on project1 then project1 had its 'bin' directory on the classpath for
project2.  If you then made a non-structural change to project1 and built it - a
class on the bin dir would have a new timestamp.  Then project2 would build - it
would see a change on its classpath and do a full build !  The state object for
each project now manages a list of what has structurally changed since its last
full build.  Now when project2 builds and sees a change of the classpath it asks
the state manager if it should worry about it or not.  If the state manager says
no - we do a super quick build of project2 :)  

</gory details>

With the 3 projects I have in a dependency hierarchy in my eclipse, the
difference this makes is as follows:

before the changes: If I make a non-structural change to the project at the top
of the hierarchy, it used to do a quick (500ms) build of that project, then a
full build (12s) of the second project followed by another full build of (10s)
the third project.

Now I make that change, it does a 500ms build of the top project followed by
300ms incremental build of the second project (which notices you haven't
actually made a structural change in project one) and then a fast 300ms
incremental build of the third project (which also notices you haven't changed
anything structurally in the second project during its build).

So, down from 22.5s to 1.1s ... you can't argue with that ;)

<warning>
Keeping extra states requires extra memory.
</warning>

I have several possible next points of attack depending on feedback:

- bring in more of the JDT intelligence (when we notice a structural change,
check if we actual contain anything that cares about it)
- improve memory usage by dumping state into a temporary workarea when not in use
- in a single project, look at whether structural changes are made to an aspect
before assuming we have to full build.
- make the interactions work properly between Java and AJ projects.  The changes
documented above work best if all projects in a relationship are AJ projects !

But my immediate concern is incremental compilation of ITDs (including declares)
and I'm going to explore that with some tests over the next few days, I think
many of the peculiar exceptions that people see when incrementally compiling
relate to this.
Comment 16 Adrian Colyer CLA 2005-10-28 07:58:43 EDT
all of the enhancements scheduled for 1.5.0 are complete, but there's more we'll look at doing in 1.5.1.
Comment 17 Andrew Clement CLA 2006-09-25 11:19:36 EDT
For 1.5.3 we tackled pipelining - helping memory usage.  We also improved intelligence for recognizing changes to either dynamic (pointcuts/advice) or static (itd) crosscutting, and will do full builds far less frequently.  We even recognize changes to around advice bodies when advice is inlined - which require a full build.  The jdtlike handle provider we use also us to avoid recompilation on white space changes too.

I think i'm going to close this bug and track further changes we make in new bugs.