Bug 146577 - [scaling] Initialize Java Tooling is slow when using a big workspace
Summary: [scaling] Initialize Java Tooling is slow when using a big workspace
Status: VERIFIED WORKSFORME
Alias: None
Product: JDT
Classification: Eclipse Project
Component: Core (show other bugs)
Version: 3.2   Edit
Hardware: PC Windows XP
: P3 normal (vote)
Target Milestone: 3.3 M7   Edit
Assignee: Frederic Fusier CLA
QA Contact:
URL:
Whiteboard:
Keywords: performance
Depends on:
Blocks:
 
Reported: 2006-06-12 10:37 EDT by David Audel CLA
Modified: 2007-04-27 13:26 EDT (History)
4 users (show)

See Also:


Attachments
thread dump (7.37 KB, application/x-zip-compressed)
2006-06-12 10:41 EDT, David Audel CLA
no flags Details
CPU Snapshots (297.34 KB, application/x-zip-compressed)
2006-06-13 07:56 EDT, David Audel CLA
no flags Details

Note You need to log in before you can comment on or make changes to this bug.
Description David Audel CLA 2006-06-12 10:37:54 EDT
build 3.2RC7

When i launch eclipse 3.2RC7 with the monster workspace (more than 1800 projects) the Java Tooling initialization take a long time, around 1 minutes. Sometimes the initialization is slower and take more than 5 minutes

I will attach some thread dumps of the 5 minutes case.
Comment 1 David Audel CLA 2006-06-12 10:41:07 EDT
Created attachment 44145 [details]
thread dump

This zip file contains 3 thread dump
stack01 is around 2 minutes after the beginning of the java tooling initialization
stack02 is around 40 secondes later
stack03 is around 40 secondes later
Comment 2 David Audel CLA 2006-06-13 07:56:15 EDT
Created attachment 44256 [details]
CPU Snapshots

This is CPU snapshots made with Yourkit
monster-slow-2006-06-13.cpu is a snapshot of a slow initialization with CompletionEngine.java opened
monster-noCU-2006-06-13.cpu is a snapshot of a less slow initialization without opened compilation unit.

I am not sure that the opened compilation unit is really the cause of the slowness.
Comment 3 Sylvain Le Petit CLA 2006-08-31 04:10:40 EDT
Hi,

I'm on eclipse 3.2 released, and the Java Tooling initialization seem blocked at 59% during 5 minutes before finalized. I have no file opened, only 4 projects opened on 35 (less than 1800). But all my project have been created on a 3.1 eclipse version. 
I have the problem only with one PC (512Mo Ram, XP Family), I have another PC (1Go ram XP Pro) without problem (same workspace).

Perhaps this note would help to resolve the bug.

(In reply to comment #2)
> Created an attachment (id=44256) [edit]
> CPU Snapshots
> This is CPU snapshots made with Yourkit
> monster-slow-2006-06-13.cpu is a snapshot of a slow initialization with
> CompletionEngine.java opened
> monster-noCU-2006-06-13.cpu is a snapshot of a less slow initialization without
> opened compilation unit.
> I am not sure that the opened compilation unit is really the cause of the
> slowness.

Comment 4 Eric Jodet CLA 2007-03-27 02:59:24 EDT
see also bugs 161704 and 171653, related to the InitializeAfterLoad operation.
Since the above bugs have been integrated, may you please have another go and try to reproduce this issue with a build > 3.3 M6.
Comment 5 Frederic Fusier CLA 2007-03-30 13:09:04 EDT
I looked closely at the snapshots and here are what can we say about this performance issue:

1) monster-noCU-2006-06-13.cpu: total time=30,243ms
   + 27,579ms (91.2%) in JavaCore.initializeAfterLoad
     + 22,932ms (83.2%) in BasicSearchEngine.createWorkspaceScope()
       Most of this is time (72.6%) is spent in org.eclipse.pde.internal.core
       (problem tracked down by bug 179685):
       + 5,979ms (18,406-12,427) (26.1%) in 
         RequiredPluginsInitializer.initialize(IPath, IJavaProject)
       + 10,657ms (46.5%) in 
         RequiredPluginsClasspathContainer.getClasspathEntries()
     + 4,516ms (19.7%) in SearchEngine.searchAllTypeNames
       This point has been addressed in 3.3 M6 (see bug 171653)

2) monster-slow-2006-06-13.cpu: total time=388,126ms
   + 236,069ms (60.8%) in Main for JDT/UI views refresh
   + 127,121ms (32.6%) in Worker.run() dispatched as follows:
     + 68,568ms (53,9%) in JavaCore.initializeAfterLoad
       + 66,244ms (96.6%) in BasicSearchEngine.createWorkspaceScope()
         Same conclusion than in snapshot (1)
     + 32,817 (25.8%) in JavaBuilder.build
       Note that ratio to global time is only 8.5% but it seems interesting to
       investigate if something could not be done in this area. Typically, why
       JavaProject.getExpandedClasspath is called twice with different params
       but consumes the same time approximatively...
     + 18,776ms (14.8%) in OverrideIndicatorLabelDecorator.decorate
       + 18,336ms (97.8%) in SourceType.newSupertypeHiearchy
         + 16,743ms (91.2%) in SearchEngine.createWorkspaceScope
           Same conclusion than in snapshot (1)
         + 1,582ms (8.4%) in TypeHiearchy.compute
           Ratio to global time is only less than 1% => nothing to gain here...
   + 24,334ms (6.3%) in reconciling strategy
     This time show be improved with fix for bug 179684
Comment 6 Frederic Fusier CLA 2007-04-02 06:47:44 EDT
Martin, what's your mind about the line in comment 5:
   + 236,069ms (60.8%) in Main for JDT/UI views refresh
Comment 7 Martin Aeschlimann CLA 2007-04-02 07:11:47 EDT
Most of the UI time should be gone now (since 3.3 M3) with the fix for bug 157639. It would be good to run the same test again on a current version.

Comment 8 Frederic Fusier CLA 2007-04-02 09:29:20 EDT
Kent, what's your mind on comment 5 JavaBuilder point?
Comment 9 Kent Johnson CLA 2007-04-03 11:26:54 EDT
Do we have more up to date numbers which have the same issues?

I thought the builds on startup were removed with Jerome's changes that no longer 'touch' projects.
Comment 10 Frederic Fusier CLA 2007-04-03 11:33:55 EDT
(In reply to comment #9)
> Do we have more up to date numbers which have the same issues?
> 
> I thought the builds on startup were removed with Jerome's changes that no
> longer 'touch' projects.
> 
Currently not, but David should replay this test with last I-build soon...
Comment 11 David Audel CLA 2007-04-05 11:39:21 EDT
I did the test with the same workspace and with two different computers. The results are

Pentium M 1.7GHz ram 2.0GB WINXP
3.2 RC7 - 1m45s or 13s
3.3 I20070403-1110 - always 10s

Pentium 4 2.0GHz ram 768MB WINXP
3.2 RC7 - always 5m
3.3 I20070403-1110 - always 25s

now performances seem good, we could close this bug as WORKSFORME.
Comment 12 Frederic Fusier CLA 2007-04-05 11:42:14 EDT
agreed
Comment 13 Martin Aeschlimann CLA 2007-04-10 05:06:04 EDT
Do you happen to have CPU snapshots again? It's always interesting to have them to get an understanding where time is spent.
Comment 14 Frederic Fusier CLA 2007-04-27 13:26:53 EDT
Initialize Java Tooling never exceeds 10s while starting monster workspace.
Verified for 3.3 M7 using build I20070427-0010.