Bug 8528 - Is it possible to trace build activity?
Summary: Is it possible to trace build activity?
Status: RESOLVED FIXED
Alias: None
Product: Platform
Classification: Eclipse Project
Component: Resources (show other bugs)
Version: 1.0   Edit
Hardware: PC Windows 2000
: P1 normal (vote)
Target Milestone: 2.0 M3   Edit
Assignee: John Arthorne CLA
QA Contact:
URL:
Whiteboard:
Keywords:
Depends on:
Blocks:
 
Reported: 2002-01-25 20:48 EST by OTI Support CLA
Modified: 2002-02-15 16:23 EST (History)
2 users (show)

See Also:


Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description OTI Support CLA 2002-01-25 20:48:06 EST
This is regarding some of the problems being investigated by
an IBM support member at customer.   There aren't alot of specifics
yet so this question is a 'feeler' that will hopefully help the 
investigative process along.

Is it possible to trace build activity?

It is not much to go on and is the context of WSAD. I am just
hunting for directions at this point. Specifically, if you have any
information concerning what is occurring internally when the customer does
the incremental compile and what specifically is occurring when the
"Reading resource change information for: <Project Name>" message appears.

A user had WSAD 4.0 installed on their machine and was seeing forty
   minute compile times after changing a single file (i.e. the user had the
   "Perform build automatically on resource modification" option checked in
   WSAD and was hitting CTRL - B to do an incremental compile).
   The user then migrated to WSAD 4.02 and is now seeing either very short
   build times (approximately 20 seconds) or longer times (between four to
   six minutes). So far a pattern has not been discovered regarding when
   the problem does or does not occur. The customer has the "Perform build
   automatically on resource modification" option checked in WSAD, was
   changing and saving a single file Java file, and was then hitting CTRL -
   B to do the incremental compile. Note: when the long build scenario
   occurs, the progress dialog appears to move through the dependent
   projects multiple times and the following text appears in the progress
   dialog: "Reading resource change information for: <Project Name>". The
   customer noticed this issue when compiling a class in a Java project.
   The projects on the 'Java Build Path' are correct and complete. The
   ClearCase 'cc-meta' file matches the dependencies on the 'Java Build
   Path' (there was a previous WSAD 4.0 issue concerning the ClearCase
   meta-data becoming corrupt).
Comment 1 Philipe Mulet CLA 2002-01-27 12:29:23 EST
The Java builder displays "Reading resource change information for: <Project 
Name>" for the duration of the computation of project deltas by Platform/Core. 
These deltas are then used to compute the set of affected compilation units 
then thrown into the recompilation loop.

If all the time is in this operation, then this might rather expose a platform 
defect.
Comment 2 Philipe Mulet CLA 2002-01-28 12:05:33 EST
To answer the question on build activity tracing, there is unfortunately no 
trace available for jdtcore 1.0 (these where added in 2.0 only).

We would have to produce a jdtcore patch to add these traces. This is doable if 
critical.
Comment 3 Philipe Mulet CLA 2002-01-30 07:25:48 EST
John - does the slow delta retrieval ring any bell to you ? If so, please 
acquire this bug.
Comment 4 John Arthorne CLA 2002-01-30 10:36:55 EST
I've never seen anything like this -- forty minute compile times is 
unbelievable!!  I have some questions/comments:

- It's strange that the customer had autobuild turned on, but was hitting 
Ctrl+B.  It was my understanding that Ctrl+B had no effect at all when autobuild 
is on.

- Can anyone give the corresponding Eclipse platform build numbers for WSAD 4.0 
and 4.02?

- There was minimal build trace support in 1.0, see the .options file under 
org.eclipse.core.resources.  Turning those options on will provide debug info 
only if there was a failure to compute deltas.

- Rough information on the size of the customer's workspace might be 
interesting: number of projects, approx number of resources/project.  Also, is 
it just the Java builder that is running in WSAD, or are there other builders 
involved?

- We can also generate a trace-enabled patch of Platform/Core if required.
Comment 5 OTI Support CLA 2002-01-30 19:32:47 EST
I am importing an 8Meg source file and it has been grinding away
for over 6hours so far and its not done yet.  I believe I have the
4.02 version and I'll verify that once the import is done.

I'll ask for the build numbers from IBM support.  They should have
that information.
Comment 6 Philipe Mulet CLA 2002-01-31 05:59:07 EST
I am guessing that 4.0 is our SDK1.0, and 4.02 is our SDK1.0 Rollup ?
Comment 7 OTI Support CLA 2002-01-31 18:07:30 EST
Latest from support at customer:

Regarding: Reading resource change information for: <Project Name>"  customer
has reported and I have seen (once) a situation where an incremental build
went very slowly and most of the time the the build progress monitor stated
this msg. It restated it for the same project multiple times. Have not been
able to reproduce.

I sent John Wiegand the customer workspace to experiment with (as I have). I am
waiting for sufficient face time with the customer to observe first hand
what their build experiences are.

Their mode now is to run with incr. build off and invoke with control-B
when they want a build. If that is taking too long they cancel it and do a
Rebuild All.

As I mentioned to John W, getting a handle on this will require more
diagnostic information.  Barry Searle, WSAD IBM Toronto, has a headless
version of WSAD that allows him to run the workspace builds via the console
using ANT. He claims that quite of bit of build info is captured there. He
is refining his code and will share with me. It might be a useful
diagnostic aid. I anticipate getting something from him Thursday.

Here is a quick profile of the customer workspace.

If you think you can make use of the customer workspace let me know.
Comment 8 OTI Support CLA 2002-02-01 20:28:15 EST
Here are some raw timings collected while observing the customer. I plan to follow
up and put these in context using my notes (ran out of time Friday). In
each log his resource changes were confined to one or two classes.

Some findings:

Log: Mario_WSAD_1.txt: workbench internal error ocurred debugging servlet.
Had to restart WSAD

In file Mario_URLServiceImpl.txt (class he was working on). There is an
entry: build done 249531. This an instance of the very long build where not
much work occurs and the progress monitor only reports that is: Updating
resource changes <project> (or something like that). I believe it occurred
immediatly following a CC connection using CC plugin.

Full builds ran about between 50-60 seconds.

Incremental builds for the same resource had variances.

Hope to add commentary into the logs where I can using my notes. (It is
hard to keep the user context synced up with the build timings.

I don't know that these entries mean:

Snapshot took: 187 milliseconds.
Snapshot took: 453 milliseconds.
Snapshot took: 203 milliseconds.
Snapshot took: 187 milliseconds.
Snapshot took: 203 milliseconds.
Snapshot took: 187 milliseconds.

Any feedback would be helpful.
Comment 9 Philipe Mulet CLA 2002-02-02 06:44:30 EST
Moving to Platform/Core since it rather seems delta retrieval related. We can 
help upon request.
Comment 10 John Arthorne CLA 2002-02-04 09:50:27 EST
The snapshot timings you see are unrelated to build.  The snapshot is an 
incremental save routine that runs rougly every hundred operations.  The only 
interesting thing about this output is the frequency of the messages, which 
gives an indication of how many operations are being executed.

The message you see in the progress bar is an important hint though.  In the 
original problem report it was a, "Reading resource change information" message, 
but in the latest entry you noted an "Updating" message.  Please clarify the 
message if you can, because the "Reading" message and the "Updating" message 
happen at two different points in the build.
Comment 11 DJ Houghton CLA 2002-02-15 15:54:15 EST
Rollup2 and the latest 2.0 integration builds contain code which fixes a bug 
related to collapsing the element tree during snapshots when a lot of no-ops 
occurred.

It has been verified that this has fixed the problems with the really slow 
incremental build times.

As well more debug options for build tracing have been added to the 2.0 builds.

Closing PR.
Comment 12 John Arthorne CLA 2002-02-15 16:23:15 EST
For reference, there are also new trace options (2.0 stream only) provided by 
core to aid in debugging build times.  The file 
plugins/org.eclipse.core.resources/.options in any build will always give an up 
to date list of these options.  For convenience, the current set of options (as 
of build 20020215), is included below:

# Turn on debugging for the org.eclipse.core.resources plugin.
# Also displays snapshot (incremental save) times.
org.eclipse.core.resources/debug=true

# Debug build failure cases such as failure to retrieve deltas.
org.eclipse.core.resources/build/failure=true

# Reports the start and end of all builder invocations
org.eclipse.core.resources/build/invoking=true

# Reports the start and end of build delta calculations
org.eclipse.core.resources/build/delta=true

# For incremental builds, displays which builder is being run
# and because of changes in which project.
org.eclipse.core.resources/build/needbuild=false

# Reports configuration and deconfiguration of project natures
org.eclipse.core.resources/natures=false