Bug 273157 - [performance] ManifestAnalyzer is causing a 2x performance drop in the updating of classpath of JavaProjects in comparison with 3.4
Summary: [performance] ManifestAnalyzer is causing a 2x performance drop in the updati...
Status: VERIFIED FIXED
Alias: None
Product: JDT
Classification: Eclipse Project
Component: Core (show other bugs)
Version: 3.5   Edit
Hardware: All All
: P2 major (vote)
Target Milestone: 3.5 RC1   Edit
Assignee: Olivier Thomann CLA
QA Contact:
URL:
Whiteboard:
Keywords: performance
: 274845 (view as bug list)
Depends on:
Blocks:
 
Reported: 2009-04-21 19:08 EDT by Chris Aniszczyk CLA
Modified: 2009-05-14 11:17 EDT (History)
8 users (show)

See Also:
david_audel: review+


Attachments
CPU usage of methods for JDT UI (YourKit) (1.06 MB, text/plain)
2009-05-04 16:07 EDT, Michael Rennie CLA
no flags Details
Usage hotspots for JDT UI (YourKit) (3.28 KB, text/plain)
2009-05-04 16:08 EDT, Michael Rennie CLA
no flags Details
Proposed fix (8.77 KB, patch)
2009-05-06 21:16 EDT, Olivier Thomann CLA
no flags Details | Diff

Note You need to log in before you can comment on or make changes to this bug.
Description Chris Aniszczyk CLA 2009-04-21 19:08:37 EDT
when we save a manifest or pde artifact, I'm noticing it's taking a long time, we need tests and profile this before 3.5 is out the door

Something is causing a longer time than usual.
Comment 1 Chris Aniszczyk CLA 2009-04-21 19:09:25 EDT
Anyone inside of big blue still have access to YourKit? A snapshot of what happens during a manifest save would be interesting to see. We're spinning our wheels somewhere.
Comment 2 Chris Aniszczyk CLA 2009-05-04 11:37:29 EDT
*** Bug 274845 has been marked as a duplicate of this bug. ***
Comment 3 Jeff McAffer CLA 2009-05-04 14:20:12 EDT
I see the same thing.
Comment 4 Benjamin Cabé CLA 2009-05-04 15:22:17 EDT
I'm gonna try to profile the issue using JProfiler. Stay tuned
Comment 5 Chris Aniszczyk CLA 2009-05-04 15:32:47 EDT
Thanks Benjamin.
Comment 6 Michael Rennie CLA 2009-05-04 16:07:54 EDT
Created attachment 134302 [details]
CPU usage of methods for JDT UI (YourKit)
Comment 7 Michael Rennie CLA 2009-05-04 16:08:54 EDT
Created attachment 134303 [details]
Usage hotspots for JDT UI (YourKit)
Comment 8 Michael Rennie CLA 2009-05-04 16:11:34 EDT
I took a couple of quick traces using YourKit 7.5.11 and a Sun 1.5 VM making a trivial change to the manifest for JDT UI - I made a one character change to the ID of the bundle (org.eclipse.jdt.ui -> org.eclipse.jdt.ui1).
Comment 9 Benjamin Cabé CLA 2009-05-04 17:43:29 EDT
Michael, thanks for the data, it helped (jProfiler absolutely wanted to deadlock while saving a manifest.....)
I found the guilty code but because of a crappy wireless connection in this hotel room, expect a fix tomorrow...
Comment 10 Chris Aniszczyk CLA 2009-05-04 17:45:00 EDT
(In reply to comment #9)
> Michael, thanks for the data, it helped (jProfiler absolutely wanted to
> deadlock while saving a manifest.....)
> I found the guilty code but because of a crappy wireless connection in this
> hotel room, expect a fix tomorrow...

details ;)?
Comment 11 Benjamin Cabé CLA 2009-05-04 17:52:23 EDT
PluginModelManager line 164: stateDelta contains a looooot of bundles... Thus we update classpath of something like every project in the ws instead of just the relevant set...
Comment 12 Benjamin Cabé CLA 2009-05-06 15:44:47 EDT
I've been a bit hasty with my conclusions...
Even if we could probably do things better with regard to the updating of the classpaths of plug-in projects associated to bundles stored in stateDelta (see comment 11), the issue may actually come from a perf. regression in JDT/Core, perhaps due to the fix of bug 265103... I need to investigate a bit more; CC'ing Olivier in the meantime, he may have some good ideas :)
Comment 13 Chris Aniszczyk CLA 2009-05-06 16:12:36 EDT
Olivier, looks like we may have a performance issue with JDT?
Comment 14 Benjamin Cabé CLA 2009-05-06 16:22:24 EDT
(thx for the CC Chris)

I'm now sure this is a performance regression in JDT, and it was not introduced with bug bug 265103, but with bug 198572 (the one that led to the creation of the ManifestAnalyzer class...).
If I switch to org.eclipse.jdt.core v_916 (i.e. just before the release of the fix of ManifestAnalyzer), I am able to obtain much more reasonable saving times!
Comment 15 Benjamin Cabé CLA 2009-05-06 16:38:27 EDT
As I said before, we could propably do things better to not reset a "plugin classpath container" of projects already up-to-date.

However, for a workspace containing 235 bundles (plug-ins imported as source from my current target platform: Eclipse 3.5 M7 SDK + all the Mylyn plug-ins), "touching" com.ibm.icu plug-in (on which a lot of other bundles directly or indirectly depend) and then saving it takes about 2s (this is quite much, I know and I repeat that we can certainly optimize the PluginModelManager logic!) with v_916, and *4s* with v_917.

Reassigning to JDT/Core for further investigation...
Comment 16 Olivier Thomann CLA 2009-05-06 17:12:34 EDT
I'll have a look.
Comment 17 Olivier Thomann CLA 2009-05-06 21:16:41 EDT
Created attachment 134722 [details]
Proposed fix

Could you please check this patch to see if it improves performances with YourKit
or you tell me what is your test case to collect the YourKit data?
Comment 18 Olivier Thomann CLA 2009-05-07 10:07:30 EDT
Targetting 3.5RC1 if we can verify that this improves performance.
David, please review the patch.

Michael, could you please get new numbers with YourKit using the patch ?
Comment 19 Michael Rennie CLA 2009-05-07 10:47:58 EDT
(In reply to comment #18)
> Targetting 3.5RC1 if we can verify that this improves performance.
> David, please review the patch.
> 
> Michael, could you please get new numbers with YourKit using the patch ?
> 

Certainly.

Comment 20 David Audel CLA 2009-05-07 11:02:59 EDT
The patch looks good because the code of analyzeManifestContents() is equivalent to the previous code and looks more efficient.
Comment 21 Olivier Thomann CLA 2009-05-07 14:04:57 EDT
Released for 3.5RC1.
Michael, please provide new profiling datas with this code.
Comment 22 Michael Rennie CLA 2009-05-07 14:06:35 EDT
(In reply to comment #19)
> Certainly.
> 

The latest method timings for ManifestAnalyzer is:

Method list

+----------------------------------------------------------------------------------------------------+-------------+------------------+-----------------+--------------------+
|                                                Name                          
                     |  Time (ms)  |  Avg. Time (ms)  |  Own Time (ms)  | 
Invocation Count  |
+----------------------------------------------------------------------------------------------------+-------------+------------------+-----------------+--------------------+
| 
+---org.eclipse.jdt.internal.compiler.util.ManifestAnalyzer.analyzeManifestContents(InputStream)
 |   125  0 %  |               1  |        15  0 %  |               104  |
+----------------------------------------------------------------------------------------------------+-------------+------------------+-----------------+--------------------+

Generated by __PRODUCT_NAME__  May 7, 2009 1:03:39 PM

compare to:

+----------------------------------------------------------------------------------------------------+-----------------+--------------------+
| Name | Time (ms) | Invocation Count |
+----------------------------------------------------------------------------------------------------+-----------------+--------------------+
|
+---org.eclipse.jdt.internal.compiler.util.ManifestAnalyzer.analyzeManifestContents(InputStream)
| 29,500 12 % | 466 |
| | | | |
| +---java.io.BufferedReader.read() | 18,312 7 % | 15,490,260 |

in the attached report

Comment 23 Kent Johnson CLA 2009-05-14 11:17:50 EDT
Verified for 3.5RC1 using I20090513-2000