Bug 34040 - It takes a minute to expand a project in Package explorer
Summary: It takes a minute to expand a project in Package explorer
Status: VERIFIED FIXED
Alias: None
Product: JDT
Classification: Eclipse Project
Component: Core (show other bugs)
Version: 2.1   Edit
Hardware: PC Windows 2000
: P3 major (vote)
Target Milestone: 2.1 RC3   Edit
Assignee: Philipe Mulet CLA
QA Contact:
URL:
Whiteboard:
Keywords:
Depends on:
Blocks:
 
Reported: 2003-03-06 18:57 EST by Wassim Melhem CLA
Modified: 2003-03-21 09:57 EST (History)
6 users (show)

See Also:


Attachments
trace (13.34 KB, text/plain)
2003-03-18 14:48 EST, Adam Kiezun CLA
no flags Details
trace expanded into getRawClasspathEntry (17.50 KB, text/plain)
2003-03-19 05:12 EST, Adam Kiezun CLA
no flags Details

Note You need to log in before you can comment on or make changes to this bug.
Description Wassim Melhem CLA 2003-03-06 18:57:46 EST
Build: RC1
For scalability testing, I'm developing against WSADIE.
I imported a plug-in whose classpath contains >200 external jar entries.
The project is initially collpsed.  In the package explorer view, if you click 
on the + to expand the project, it will take about 60 seconds for the project 
to expand.
After it expanded, I went into the view filters and changed it so that I could 
see the hidden '.*' files, it will take another minute to update the view.
Comment 1 Erich Gamma CLA 2003-03-08 18:19:29 EST
Need to investigate. 

Computing the "+" should not be the problem. JarPackageFragmentRoot implement 
hasChildren to return true when the element isn't open.
Comment 2 Erich Gamma CLA 2003-03-11 10:57:35 EST
We tried to reproduce the performance problem with a project that has all the 
websphere 5.0 on the build class path (168 JARs). It takes on the order of 3-5 
seconds to open this project (in both the local and network scenarios for the 
JARs). Can you zip up this project and make it available so that we can 
reproduce the scenario.

Comment 3 Wassim Melhem CLA 2003-03-14 16:09:53 EST
In your test case with 168 external JARS, did the labels for these jars in the 
tree contain the ECLIPSE_HOME variables?
I, along with the WSADIE team members, experience the 1-minute delay/project, 
when the project's classpath contains entries whose path contain the 
ECLIPSE_HOME variable.
When I use PDE's alternate way of computing classpaths (i.e. classpath 
containers), expanding the project is pretty quick.  In this case, all the 
labels for the external jars in the tree have an absolute path.  
So I speculate that the delay might have something to do with resolving 
variable names over and over again.
Comment 4 Adam Kiezun CLA 2003-03-18 14:40:40 EST
this seems indeed to be the culprit here
will have a profile in a few minutes
Comment 5 Adam Kiezun CLA 2003-03-18 14:48:34 EST
Created attachment 4215 [details]
trace

i stopped expanding at getRawClasspathEntry
please let me know if you're interested what's going on inside of that call
Comment 6 Erich Gamma CLA 2003-03-18 16:23:37 EST
The time is spent in PackageFragmentRoot.getRawClasspathEntry().
It is called many times from 2 locations and both locations contribute to 50% 
of the execution time:
a) PackageExplorerContentProvider.rootsAndContainers()
b) JavaElementLabels.getVariableLabel()

a) got introduced in 2.1. We have changed the algorithm so that 
getRawClassPathEntry is called only once. This fix got released for RC3 
(reviewed by Adam) and gives a 50% speed-up.

b) is an existing 2.0 performance problem. For Variable class path entries we 
want to include the variable name in the label. To do so we have to map the 
resolved class path entry back to the raw classPath entry. Once we have the raw 
class path entry we can render the entry like:
   ECLIPSE_HOME - absolute path name to the entry
As simple fix is to only render the absolute path name, but this is a loss of 
function. 

Before doing this JDT-Core should investigate whether the call to 
getRawClassPathEntry can be improved. The expensive part is the 
canonicalization of the path File.getCanoncalPath.

Moving to JDT-CORE for investigation.
Comment 7 Philipe Mulet CLA 2003-03-18 17:45:32 EST
Adam - can you provide the expanded profile of #getRawClasspathEntry ?

Accessorily, we will need the testcase to check.
Comment 8 Philipe Mulet CLA 2003-03-18 17:59:45 EST
One thing we could try is to cache a backpointer as we compute the direct 
children roots. This way, reverse mapping would almost be free.

The current implementation is walking the original project raw path 
iteratively, which is extremly slow in this particular scenario.
Comment 9 Erich Gamma CLA 2003-03-19 04:14:21 EST
Here is the test case (assuming you have a WSAD build available)
I was using the WS runtime libraries to get easy access to lots of JARs.

Here are the steps:
1) create a class path variable WSAD_HOME and
   point it to the folder ${WSAD_HOME}\runtimes\base_v5\lib
2) create a new project
3) add the variable WSAD_HOME its build path and extend
   so that all the JARs in the lib folder are included 
   (notice you can multiple select)
Comment 10 Philipe Mulet CLA 2003-03-19 04:49:27 EST
Weird, I wrote a test to reproduce the reverse mapping on a project with 500 
roots available through a variable, and on my P3-850MHz machine, it only claims:
"1513ms for 500 roots"

public void testPackageFragmentRootRawEntry() throws CoreException {
	try {
		JavaCore.setClasspathVariable("MyVar", new Path("/P/lib"), 
null);
		IJavaProject proj =  this.createJavaProject("P", new String[] 
{}, "bin");
		this.createFolder("/P/lib");
		final int length = 500;
		IClasspathEntry[] classpath = new IClasspathEntry[length];
		for (int i = 0; i < length; i++){
			this.createFile("/P/lib/lib"+i+".jar", "");
			classpath[i] = JavaCore.newVariableEntry(new Path
("/MyVar/lib"+i+".jar"), null, null);
		}
		proj.setRawClasspath(classpath, null);
		
		long start = System.currentTimeMillis();
		IPackageFragmentRoot[] roots = proj.getPackageFragmentRoots();
		for (int i = 0; i < roots.length; i++){
			IClasspathEntry rawEntry = roots[i].getRawClasspathEntry
();
			assertEquals("unexpected root raw entry:", classpath
[i], rawEntry);
		}
		System.out.println((System.currentTimeMillis() - start)+ "ms 
for "+roots.length+" roots");
	} finally {
		this.deleteProject("P");
		JavaCore.removeClasspathVariable("MyVar", null);
	}
}
Comment 11 Adam Kiezun CLA 2003-03-19 05:12:06 EST
Created attachment 4238 [details]
trace expanded into getRawClasspathEntry

here's the trace expanded down unit java.io calls.
just 1 branch with getClasspathEntry is expanded - the other one must be the
same, i guess
Comment 12 Adam Kiezun CLA 2003-03-19 05:14:20 EST
it's very nasty - anything you do, the thing freezes for hal a minute 
Comment 13 Erich Gamma CLA 2003-03-19 06:08:42 EST
If you cannot reproduce easily then you can also send us a patch and we can 
verify.
Comment 14 Philipe Mulet CLA 2003-03-19 06:37:18 EST
I found an old WSAD build which has similar characteristics, and am able to 
reproduce. I suspect though that a couple of fixes will be necessary to get it 
into an ok state. Getting close for this particular defect, by using a reverse 
map to cache backpointers. Need to see if more is needed.
Comment 15 Philipe Mulet CLA 2003-03-19 08:48:14 EST
Previous test issue got resolved. In order to reflect the exact same situation, 
external JARs need to be targeted. The test is now targeting 200 external JARs, 
and with the caching strategy, the number drops from 13seconds to 15ms. Still 
time is spent elsewhere in WSAD case, but the #getRawClasspathEntry should no 
longer get in the way. Using WSAD scenario with patch, on my machine it drops 
from 30 seconds to 2 seconds to expand the project.

Patch available in JDT/Core 2.1 update area: 

http://dev.eclipse.org/viewcvs/index.cgi/%7Echeckout%7E/jdt-core-
home/r2.1/main.html#updates

Released for integration.
Comment 16 Philipe Mulet CLA 2003-03-19 08:48:31 EST
Fixed
Comment 17 Adam Kiezun CLA 2003-03-19 10:09:57 EST
i confirm that the 2 fixes together give 20x improvement
Comment 18 David Audel CLA 2003-03-20 09:55:49 EST
Verified.
Comment 19 Jed Anderson CLA 2003-03-20 16:38:26 EST
I have a test project which references 160 external jars using the ECLIPSE_HOME
variable.  Expanding this project in the Package Explorer using different builds
produces the following results.

14 seconds with 20020318
2 seconds with 20020319

This is not 20x, but is an improvement.
Comment 20 Jed Anderson CLA 2003-03-20 16:50:49 EST
I have a test project which references 160 external jars using the ECLIPSE_HOME
variable.  Expanding this project in the Package Explorer using different builds
produces the following results.

14 seconds with 20020318
2 seconds with 20020319

Note that this is not the reported 20x improvement, but rather ~7x.  Did the
entire fix get into 20020319?  Or is 20x an overestimate of the fix?
Comment 21 Philipe Mulet CLA 2003-03-20 17:23:30 EST
In my case, the speed up for more than 10x faster (with my only change). It 
probably has to do with various parameters (VM...).
Comment 22 Adam Kiezun CLA 2003-03-21 05:15:47 EST
don't take 20030318 for comparison - one part of the fix was already in there
take sth like 20030314 

anyways, i saw (under profiler) 2 minutes vs 6 seconds
(test case was a project with 168 JARs on the network drive) 
Comment 23 Jed Anderson CLA 2003-03-21 09:57:37 EST
With 20030312 I see 30 seconds.  Thanks for the pointer Adam.