Bug 234718 - JarPackageFragmentRoot.computeChildren(..) is slow
Summary: JarPackageFragmentRoot.computeChildren(..) is slow
Status: VERIFIED FIXED
Alias: None
Product: JDT
Classification: Eclipse Project
Component: Core (show other bugs)
Version: 3.4   Edit
Hardware: PC Windows XP
: P3 blocker (vote)
Target Milestone: 3.4 RC4   Edit
Assignee: Jerome Lanneluc CLA
QA Contact:
URL:
Whiteboard:
Keywords: performance
Depends on:
Blocks:
 
Reported: 2008-05-29 16:17 EDT by Bevon Palod CLA
Modified: 2008-06-04 11:08 EDT (History)
6 users (show)

See Also:
philippe_mulet: review+
martinae: review+
frederic_fusier: review+
david_audel: review+


Attachments
Merged callee stack (6.59 KB, application/octet-stream)
2008-05-29 16:17 EDT, Bevon Palod CLA
no flags Details
Proposed fix (772 bytes, patch)
2008-06-02 11:23 EDT, Jerome Lanneluc CLA
no flags Details | Diff

Note You need to log in before you can comment on or make changes to this bug.
Description Bevon Palod CLA 2008-05-29 16:17:07 EDT
Build ID: org.eclipse.jdt I20080516-1333

Steps To Reproduce:
Profiling a performance issue with my product, so cannot add product-specific steps here.

More information:
During one profiling session, my scenario took 249640ms.  Most of time was spent 
in:
org.eclipse.jdt.internal.core.JarPackageFragmentRoot.computeChildren(OpenableElementInfo, IResource)

The aggregate time spent in that method was 154312ms (62%).  I've attached my 
profiling tool's merged callee stacks (starting at the point where my product's 
code ends) exported as an HTML file.

My profiling tool captures a tonne of information, and I'm not experienced with 
debugging performance issues, so I'm not sure what other information I should be 
adding to help investigate this further.  If you need more information, please 
let me know and I'll try my best to get it to you.
Thanks in advance,
Bevon
Comment 1 Bevon Palod CLA 2008-05-29 16:17:50 EDT
Created attachment 102741 [details]
Merged callee stack
Comment 2 Jerome Lanneluc CLA 2008-05-30 04:57:18 EDT
According to your trace, 74% of the time is spent reading the zip file entries. This is odd. Are you jars on a slow drive (or a netword drive)?

Also how much memory do you give to the VM? Have you tried playing with the "-Xmx" VM option?
Comment 3 Philipe Mulet CLA 2008-05-30 12:37:45 EDT
Jerome identified a weakness in the cache refresh policy, leading to the cache being cleared many times unnecessarily in this situation. This means that the performance is degradating, since the cache is no longer filling its role under these circumstances.
Comment 4 Bevon Palod CLA 2008-05-30 15:26:52 EDT
Hi Jerome,
I have the following -Xmx VM option set in my eclipse.ini:
-Xmx768m


My HD is a Hitachi HTS7220 and is fairly new, so I'm thinking this is not slow.


Re: the discovered weakness in the cache policy -- can you confirm is this is the definite cause of the performance degradation?
Thanks,
Bevon
Comment 5 Philipe Mulet CLA 2008-05-31 03:27:37 EDT
Yes, most likely. The trick is now to decide whether this is a stopship issue vs. a bug (which was in 3.3 already) which we rather would address in 3.4.1/3.5.
We are in RC4 stage where only stop ship bugs are considered.
Comment 6 Jerome Lanneluc CLA 2008-06-02 07:44:21 EDT
A possible explanation for the performance problem reported in this bug is the fact that the project cache (containing the package names used by name lookup) are reset for each Java model operation when ran inside a batch operation in the following scenario:
- a Java batch operation is started
- a package fragment is created (as a result we remember to reset the project's cache)
- we reset the project cache (but we keep the information that the cache needs to be reset)
- each reconcile operation resets the cache as it is marked as "need reset"

This cache reset was introduced by the fix for bug 144776 during the 3.3 development cycle. So this is not a regression comparing to 3.3.

The fix consists in clearing the information that the cache needs to be reset once reset.

This fix would be a one-liner, and since the cache is lazily computed, it has no risk (i.e. if another package fragment is created during the batch operation, it will be reset again).
Comment 7 Philipe Mulet CLA 2008-06-02 07:52:38 EDT
Jerome - can you also summarize the performance impact of your proposed fix ? Also, could you pls attach a patch ?
Comment 8 Jerome Lanneluc CLA 2008-06-02 11:23:17 EDT
Created attachment 103141 [details]
Proposed fix

The scenario that Bevon profiled used to take 10 minutes and 15 seconds on my machine. With the fix it now takes 50 seconds.
Comment 9 Bevon Palod CLA 2008-06-02 15:35:43 EDT
Hi Jerome,
I rec'd a plugin jar containing your patch and applied it to my product.  I ran the scenario 3 times and each time it took no longer than 1 minute, so your fix looks good.

This is a stop-ship problem for us as our product will be shipping on 3.4 (3.4.1 is too late).  We did not see this on 3.3 since our previous product shipped on 3.2.2.
Thanks,
Bevon
Comment 10 Jerome Lanneluc CLA 2008-06-03 04:20:43 EDT
Philippe, Martin, since this is considered a stop-ship problem, can you please approve for 3.4RC4
Comment 11 Philipe Mulet CLA 2008-06-03 04:32:47 EDT
+1 for 3.4RC4
Comment 12 Jerome Lanneluc CLA 2008-06-03 04:38:35 EDT
Frederic, David can you please review?
Comment 13 Martin Aeschlimann CLA 2008-06-03 04:40:11 EDT
Patch is good. Should fix for 3.4.
One question, wouldn't it be better to clear projectCachesToReset inside 'resetProjectCaches()'? So callers of resetProjectCaches don't need to remember to clear the cache.
Comment 14 Jerome Lanneluc CLA 2008-06-03 04:47:06 EDT
(In reply to comment #13)
> Patch is good. Should fix for 3.4.
> One question, wouldn't it be better to clear projectCachesToReset inside
> 'resetProjectCaches()'? So callers of resetProjectCaches don't need to remember
> to clear the cache.
> 
Yes that would be better. I just wanted to have the very minimal change, i.e. don't impact other callers of resetProjectCaches(). This better change will be done in 3.5.
Comment 15 Martin Aeschlimann CLA 2008-06-03 04:57:38 EDT
Ok, thanks!
Comment 16 David Audel CLA 2008-06-03 04:59:28 EDT
Patch looks good: +1.
Comment 17 Frederic Fusier CLA 2008-06-03 06:31:17 EDT
Patch looks good: +1
Comment 18 Philipe Mulet CLA 2008-06-03 09:01:37 EDT
raising severity to match comment 9
Comment 19 Walter Harley CLA 2008-06-03 11:27:32 EDT
+1.  (I vote because of my involvement with bug 144776, and because BEA had significant issues with and experience with this cache.)

Slowdowns in JarPackageFragmentRoot.computeChildren are a serious perf issue in the real world and a >10x perf improvement is likely to be reflected in real applications, i.e., this is not concocted.  The bug is reported from a customer who needs the fix in 3.4.

Can a separate bug report be cloned for the fix in Comment 13 ?
Comment 20 Jerome Lanneluc CLA 2008-06-03 11:38:16 EDT
(In reply to comment #19)
> Can a separate bug report be cloned for the fix in Comment 13 ?
> 
Entered bug 235369
Comment 21 Jerome Lanneluc CLA 2008-06-03 11:41:56 EDT
A performance test is also needed. I entered bug 235370 for this. However since performance tests usually take several tries before getting the standard error right, I will release it early 3.5.
Comment 22 Jerome Lanneluc CLA 2008-06-03 11:43:52 EDT
Proposed fix released for 3.4RC4
Comment 23 Bevon Palod CLA 2008-06-04 11:08:07 EDT
Since I've verified the patch containing the fix is good, I'll assume the fix in the build will be good too.  Marking as verified.