Some Eclipse Foundation services are deprecated, or will be soon. Please ensure you've read this important communication.
Bug 318410 - Invoking CDT Builder takes over 1 minute for managed project
Summary: Invoking CDT Builder takes over 1 minute for managed project
Status: RESOLVED FIXED
Alias: None
Product: CDT
Classification: Tools
Component: cdt-build-managed (show other bugs)
Version: 7.0   Edit
Hardware: PC Windows XP
: P3 major (vote)
Target Milestone: 7.0.1   Edit
Assignee: James Blackburn CLA
QA Contact: Chris Recoskie CLA
URL:
Whiteboard:
Keywords:
: 326687 (view as bug list)
Depends on: 321892
Blocks:
  Show dependency tree
 
Reported: 2010-06-30 01:53 EDT by Missing name CLA
Modified: 2013-06-14 05:25 EDT (History)
5 users (show)

See Also:


Attachments
Stacktrace of eclipse helios start and build of labbcan project (20.23 KB, text/plain)
2010-07-06 01:53 EDT, Missing name CLA
no flags Details
patch 1 (6.76 KB, patch)
2010-08-05 13:37 EDT, James Blackburn CLA
jamesblackburn+eclipse: iplog-
jamesblackburn+eclipse: review?
Details | Diff

Note You need to log in before you can comment on or make changes to this bug.
Description Missing name CLA 2010-06-30 01:53:41 EDT
After upgrading to eclipse Helios I have a problem with one of my managed eclipse projects. If I invoke the "build" command I get the following message on the console

**** Internal Builder is used for build ****

and the progress bar in the lower right corner starts spinning around for approximately 70 seconds displaying the message "Build Project: (0%)". After 70 seconds I see the next message on the console (i.e. if I changed nothing: "Nothing to build for ....") and the build process continues.

The time between the invocation of the build command and the first action was substantially lower in eclipse Galileo for this project (only some seconds).

The interesting thing is, that the 70 seconds only occur, if the indexer has completely indexed the project. If I select Index -> Rebuild and interrupt the indexing process so that I have a clean indexer cache, then the build action starts almost immediatelly after invoking the "build" command. Than means, if the project is properly indexed, the time between the build invocation and the first action is 70 seconds. If the project is not properly indexed, the build action starts almost immediatelly after build command invocation.

The project is a simple MinGW managed shared library project. The project itself does not contain any source files but links to a folder that is based on a linked resource. If I right click onto the linked folder, I see the following properties:

Path: /labbcan/labbcan
Type: Linked Folder
Location: cetoni_repository\usl\service\labbcan\labbcan
Resolved Location: D:\CodingXP\cetoni_repository\usl\service\labbcan\labbcan

The linked folder contains a number of sub folders that contain the source code. I can reduce the time between the invocation of the build command and the first action if I manually exclude some sub folders (Right click -> Resource Configuration -> Exclude from Build) and rebuild the index.

To check if this problem is related to some project settings, I created e new MinGW shared library project and did nothing more than linking to the source folder. After this action I invoked the build command. The build started immediatelly because the new project was not properlly indexed. Then I waited until the indexer finished indexing of the test project and restarted the build. Now it took again 70 seconds between the invocation of the build command and the first build action on the console.
Comment 1 Andrew Gvozdev CLA 2010-06-30 09:46:31 EDT
- To rule out scanner discovery, could you disable it in project properties->Builders->Scanner Configuration Builder. Does it have any effect on 70 sec?
- What is your linked folder, is it some kind of slow NFS?
- Do you have any recursive links in the linked folder?
Comment 2 Missing name CLA 2010-06-30 10:23:53 EDT
- Disabling the scanner discovery builder did not have any effect on the 70 seconds.
- The linked folder is a normal local folder on my Windows XP machine (Filesystem NTFS)
- The linked folder is part of a local source repository that is under version control. That means the linked folder is also under SVN version control.
- I do not have recursive links in linked folder (at least I don't know how to create a recursive link)
- Because the linked folder is under version control, I can see a SVN folder in each subfolder of the linked folder in eclipse. Now, for testing reasons, I manually excluded all these SVN folders from build via Resource Configurations -> Exclude from build - this did not have any effect on the 70 seconds.
Comment 3 Andrew Gvozdev CLA 2010-07-02 09:40:05 EDT
Hmm, I have hard time figuring what could cause that. I would try following to eliminate some of the factors:
- Remove the link and copy the source folder to the workspace and see if it helps
- Change permissions of all the files in the folder, restart eclipse and try again
How big is your project?
Comment 4 Missing name CLA 2010-07-05 01:53:21 EDT
I created a new managed shared library project and copied the source code into the project folder to remove the linked folder. The delay between build invocation and first build step is still 70 seconds (after the indexer finished indexing the project)

The project consists of 226 files - only h, c, and cpp files.

I will send you a copy of the source code via private mail because it is no open source.
Comment 5 Andrew Gvozdev CLA 2010-07-05 11:04:44 EDT
Thanks for the source code. I still cannot reproduce the issue. I created a new managed MinGW  shared library project. Then copied the sources in there. Then refreshed the project. Waited out for indexer to finish. Built the project. It took less than a second before it hit missing include file. I do not see any delay. My output is as following:

**** Rebuild of configuration Debug for project xxx ****

**** Internal Builder is used for build               ****
...
Do you get the "Rebuild..." message in your logs as well?
Comment 6 Andrew Gvozdev CLA 2010-07-05 13:12:30 EDT
It would be interesting to see what it's doing during those 70 sec. Could you post a stack trace? See http://wiki.eclipse.org/How_to_report_a_deadlock how to generate one.
Comment 7 Missing name CLA 2010-07-06 01:53:28 EDT
Created attachment 173495 [details]
Stacktrace of eclipse helios start and build of labbcan project

The stacktrace contains the eclipse 3.6 startup and the stacktrace 30 seconds after invocation of build command.
Comment 8 Missing name CLA 2010-07-06 01:58:59 EDT
I created a stacktrace file that contains the eclipse 3.6 startup and a stacktrace ca. 30 seconds after invocation of eclipse build command.

This was the console output at the time of the stack trace:

**** Rebuild of configuration Debug for project labbcan ****

**** Internal Builder is used for build               ****

The build problem seems to be workspace related. I created a completely new and empty workspace and created a managed shared library MinGW build project. I copied the source code into the project folder. The build process starts 1-2 seconds after invocation of the build command - even if the indexer has properly indexed the project. That means the problem is not reproducible with a new workspace.

When I upgraded my eclipse installation I did not update my eclipse 3.5 installation but did a complete new installation of the eclipse 3.6 CDT installation package from the released archive on eclipse.org. On first start I pointed the new eclipse to my eclipse 3.5 workspace - is this procedure o.k.?
Comment 9 Andrew Gvozdev CLA 2010-07-06 11:10:23 EDT
(In reply to comment #8)
> When I upgraded my eclipse installation I did not update my eclipse 3.5
> installation but did a complete new installation of the eclipse 3.6 CDT
> installation package from the released archive on eclipse.org. On first start I
> pointed the new eclipse to my eclipse 3.5 workspace - is this procedure o.k.?
We do not specifically take care about transition of a workspace from previous release. I am not aware of any testing along these lines, so YMMV. I personally recreate a workspace once in a while just to avoid problems like that.
Can you send me the broken workspace in private email? I don't think I need any of your projects, just .metadata folder.
Comment 10 Missing name CLA 2010-07-06 12:24:26 EDT
The size of my .metadata folder is around 520 MByte. The biggest part is org.eclipse.cdt.core with 488 MByte. Is there a special file you are interested in or are there some files I can remove?

What do you mean with "I personally
recreate a workspace once in a while just to avoid problems like that". How do you recreate a workspace. Does it mean, you simplay create a new workspace and import all projects?
Comment 11 Andrew Gvozdev CLA 2010-07-06 12:53:12 EDT
(In reply to comment #10)
> The size of my .metadata folder is around 520 MByte. The biggest part is
> org.eclipse.cdt.core with 488 MByte. Is there a special file you are interested
> in or are there some files I can remove?
I think you could get rid of those pdom files in .metadata/.plugins/org.eclipse.cdt.core/. Hmm, actually they could be a part of the problem, I saw a similar effect investigating a different bug. Can you check if removing those has any effect on the delay?
 
> What do you mean with "I personally
> recreate a workspace once in a while just to avoid problems like that". How do
> you recreate a workspace. Does it mean, you simplay create a new workspace and
> import all projects?
I just move my workspace to backup folder and let eclipse create a new one. Then check out my projects anew from CVS. Or copy an old project to the new workspace and export if I have to.
Comment 12 Andrew Gvozdev CLA 2010-07-06 13:00:23 EDT
(In reply to comment #11)
> (In reply to comment #10)
> > The size of my .metadata folder is around 520 MByte. The biggest part is
> > org.eclipse.cdt.core with 488 MByte. Is there a special file you are
> interested
> > in or are there some files I can remove?
> I think you could get rid of those pdom files in
> .metadata/.plugins/org.eclipse.cdt.core/. Hmm, actually they could be a part of
> the problem, I saw a similar effect investigating a different bug. Can you check
> if removing those has any effect on the delay?
Actually that might explain why you are having a delay after indexer finished because those are index files created by it.
Comment 13 Missing name CLA 2010-07-06 13:08:56 EDT
Removing all pdom files does not solve the problem. I removed all files and restarted eclipse. After the indexer finished indexing labbcan project I invoked build command - 70 seconds delay.

The labbcan project is the only project that has such a delay. I will try to upload the .metadata folder without the pdom files on my webpage and send you a download link.
Comment 14 Andrew Gvozdev CLA 2010-07-09 10:06:35 EDT
Thanks. I don't have 70 sec delay using your workspace but just 40 which is pretty damning too.
Comment 15 Keith W. Campbell CLA 2010-08-04 14:39:30 EDT
I did some research into the behavior of managed build some time back and found that a great deal of time was spent in WorkspaceRoot.findFilesForLocationURI() as *.d files were processed in trying to decide whether they referenced any non-existent or modified files. This is particularly expensive in large workspaces or with large numbers of references to files outside the workspace. To make things worse, the same locations are considered over and over again (e.g. system header files).
Comment 16 James Blackburn CLA 2010-08-05 04:44:38 EDT
Great find.  Interestingly a user reported just this yesterday -- builds taking up to a minute to get going. 

I took VM backtraces every 2 seconds, and sure enough I found it spending 30s+ finding files for location.

I've seen this before, and what I don't get is why it's transient. If the user restarts his Eclipse I believe the problem goes away for a bit.  Perhaps there's an underlying platform issue - I've got a heapdump of the workspace in pain, so will take a look to see if there's anything obvious.



2010-08-04 18:11:19
Full thread dump Java HotSpot(TM) 64-Bit Server VM (16.0-b13 mixed mode):
...
"Worker-621" prio=10 tid=0x0000002ae7d39000 nid=0x2ca1 runnable [0x000000004587e000]
   java.lang.Thread.State: RUNNABLE
...
at org.eclipse.core.internal.resources.WorkspaceRoot.findFilesForLocationURI(WorkspaceRoot.java:103)
at org.eclipse.core.internal.resources.WorkspaceRoot.findFilesForLocation(WorkspaceRoot.java:96)
at org.eclipse.cdt.managedbuilder.internal.buildmodel.BuildDescription.addInput(BuildDescription.java:1904)
at org.eclipse.cdt.managedbuilder.internal.buildmodel.BuildDescription.calculateDeps(BuildDescription.java:1689)
at org.eclipse.cdt.managedbuilder.internal.buildmodel.BuildDescription.calculateInputs(BuildDescription.java:1668)
at org.eclipse.cdt.managedbuilder.internal.buildmodel.BuildDescription.composeOutputs(BuildDescription.java:650)
...

And 30s later:

2010-08-04 18:11:48
Full thread dump Java HotSpot(TM) 64-Bit Server VM (16.0-b13 mixed mode):
...
at org.eclipse.core.internal.resources.WorkspaceRoot.findFilesForLocationURI(WorkspaceRoot.java:112)
at org.eclipse.core.internal.resources.WorkspaceRoot.findFilesForLocationURI(WorkspaceRoot.java:103)
at org.eclipse.core.internal.resources.WorkspaceRoot.findFilesForLocation(WorkspaceRoot.java:96)
at org.eclipse.cdt.managedbuilder.internal.buildmodel.BuildDescription.addInput(BuildDescription.java:1904)
at org.eclipse.cdt.managedbuilder.internal.buildmodel.BuildDescription.calculateDeps(BuildDescription.java:1689)
at org.eclipse.cdt.managedbuilder.internal.buildmodel.BuildDescription.calculateInputs(BuildDescription.java:1668)
at org.eclipse.cdt.managedbuilder.internal.buildmodel.BuildDescription.composeOutputs(BuildDescription.java:650)
at org.eclipse.cdt.managedbuilder.internal.buildmodel.BuildDescription.access$1(BuildDescription.java:545)
...
Comment 17 James Blackburn CLA 2010-08-05 09:55:42 EDT
Bug trade with Andrew.  This is bugging us now so I'll take this.
Comment 18 Keith W. Campbell CLA 2010-08-05 11:41:30 EDT
The performance may be worse when linked resources are present, but CDT still uses WorkspaceRoot.findFilesForLocationURI many times for the same locations: once each should be sufficient.
Comment 19 James Blackburn CLA 2010-08-05 11:54:12 EDT
Completely agree, I'll fix the CDT side of things. 

Just filed the platform bug while I have the backtraces handy.  Any optimizations core.resources can make will speed up all the other places we have that use findFilesForLoc.
Comment 20 James Blackburn CLA 2010-08-05 13:37:07 EDT
Created attachment 175966 [details]
patch 1

BuildDescription already has a URI -> Build Resource cache.  This patch uses that, short-circuiting the findFilesForLocation.

Unfortunately this is all a bit messy. I've just tweaked the parts that impact this bug...

- Bug 273636 added getURIForFullPath which seems to be badly misnamed.  It actually turns a *location* IPath -> URI.  I've renamed this as leaving it as is really confuses matters when actual IResource full paths are being used.

- Simplified #addInput. 
   + Use IResource.equals
   + use #findFilesForLocationURI 
   + remove a few of the unnecessary IPath concatenations. 
   + short-circuit findFilesForLocationURI by looking in the map.

- Looks like Andrew's fix for JUnit failures bug 285347 switched to URIs completely (good), but used URIUtil.toURI for #getBuildResource(IPath). For Bug 273636 Chris seems to be generating these URIs using his getURIFor... method, so fixed this for consistency.

JavaDoc the methods concerned.

I believe the transformation is safe and should seriously reduce the number of calls to core.resources findFilesForLocation.

Comments welcome.
Comment 21 James Blackburn CLA 2010-08-06 05:41:23 EDT
Path committed to HEAD & 7.0.x.  Do let us know if the pause has been alleviated. 

It's still a bit bemusing how much work is done before build:
  - calculateDeps() uses the PDOM for generating the dependencies. This will be wrong if the indexed configuration doesn't match the build configuration, the index is out of date, etc.
  - This dependency calculation shouldn't be needed for the generated makefile builds
  - The indexer itself does a bunch of findFilesForLocation.

Leaving open while we confirm whether the fix has made a substantial difference.
Comment 23 Missing name CLA 2010-08-06 16:33:29 EDT
I tested cdt-master-7.0.1-I201008060605.zip. The pause between invocation of build command and start of build decreased from 70 seconds to 17 seconds for my project that caused the problem.

Thank you - now it is possible again to build the project when it is completely indexed.
Comment 24 James Blackburn CLA 2010-08-07 04:44:07 EDT
Thanks for confirming. That's still quite slow though... Could you collect some backtraces while it's starting the build?

Something like:
while [ true ] ; do  jstack java_pid > `date "+%Y%m%d.%H%M.%S"` ; sleep 1; done
Will produce a backtrace per second or thereabouts. You could tar them up and attach them to the bug. It's quite course but may highlight other big areas of wastage.
Comment 25 James Blackburn CLA 2010-08-20 13:43:05 EDT
Not heard back. 

Platform has optimised this significantly too so the location resolution we do now should have much less impact.

Please open separate bugs for any further issues.
Comment 26 James Blackburn CLA 2011-01-31 09:44:00 EST
*** Bug 326687 has been marked as a duplicate of this bug. ***