Bugzilla – Full Text Bug Listing
| Summary: | [perfs] Big regression on FullSourceWorkspaceModelTests#testCloseProjects() test | ||||||||
|---|---|---|---|---|---|---|---|---|---|
| Product: | [Eclipse Project] JDT | Reporter: | Frederic Fusier <frederic_fusier> | ||||||
| Component: | Core | Assignee: | Frederic Fusier <frederic_fusier> | ||||||
| Status: | VERIFIED FIXED | QA Contact: | |||||||
| Severity: | normal | ||||||||
| Priority: | P3 | CC: | david_audel, jerome_lanneluc, Szymon.Brandys | ||||||
| Version: | 3.5 | Keywords: | performance, test | ||||||
| Target Milestone: | 3.5 M7 | ||||||||
| Hardware: | PC | ||||||||
| OS: | Windows XP | ||||||||
| Whiteboard: | |||||||||
| Bug Depends on: | 273308 | ||||||||
| Bug Blocks: | 270824 | ||||||||
| Attachments: |
|
||||||||
|
Description
Frederic Fusier
I reproduced once locally but since then it never happened again. What I saw from the failing test is that there were 2 measures on 10 out of the bounds (around 2s for 8 measures and more than 40s for the 2 other ones). That would explain the systematic yellow color on this test when it's failing. So, I guess this is a problem with the test itself, but try to spend more time to find the origin of the problem... Here are the numbers for this test bewteen M6 and last I-build: Win XP Sun 1.5.0_10 (2 x 3.00GHz - 3GB RAM) M6 I20090313-0100 -5.6% N20090314-2000 2.7% I20090317-1029 -46.8% N20090319-2000 -45.2% N20090321-2000 -45.4% I20090324-0800 -51.7% I20090324-1325 -111.9% I20090325-1135 -116.0% N20090326-2000 -113.6% N20090328-2000 -113.3% I20090331-0901 -47.4% I20090401-1325 -47.6% N20090402-2000 -51.7% N20090404-2000 -48.4% I20090407-1430 -47.7% N20090411-2000 -49.6% I20090414-0800 -61.8% SLED 10 Sun 1.5.0_10 (2 x 3.00GHz - 3GB RAM) M6 I20090313-0100 -2.1% N20090314-2000 3.1% I20090317-1029 -48.2% N20090319-2000 -45.2% N20090321-2000 -55.2% I20090324-0800 -67.0% I20090324-1325 -63.2% I20090325-1135 -67.6% N20090326-2000 -58.8% N20090328-2000 -64.2% I20090331-0901 -53.6% I20090401-1325 -56.2% N20090402-2000 -64.9% N20090404-2000 -47.1% I20090407-1430 -46.6% N20090411-2000 -56.8% I20090414-0800 -53.9% RHEL 5.0 Sun 6.0_04 (2 x 3.00GHz - 3GB RAM) M6 I20090313-0100 8.0% N20090314-2000 5.2% I20090317-1029 -50.6% N20090319-2000 -54.2% N20090321-2000 -57.0% I20090324-0800 -56.0% I20090324-1325 -66.2% I20090325-1135 -61.6% N20090326-2000 -53.9% N20090328-2000 -61.7% I20090331-0901 -37.5% I20090401-1325 -36.9% N20090402-2000 -46.7% N20090404-2000 -60.8% I20090407-1430 -65.5% N20090411-2000 -58.0% I20090414-0800 -50.7% This regression is really strange because: 1. no change has been done in this area in JDT/Core between N20090314-2000 and I20090317-1029. 2. I cannot reproduce on my thinkpad while running from a SDK 3. I get it while running JDT/Core tests using the test framework 4. I can see the same regression on a baseline run when I start the test from an existing full source workspace instead of creating it during the test run Starting with these clues, I got yourkit snapshots on point 4) and saw that the extra time was spent in the Project.close(IProgressMonitor) method (I'll attach the snapshots to this bug later). So, I made the assumption that the problem may come from the Platform/Resources plugin and run the test using all JDT/Core projects from HEAD but against a 3.5 M6 platform. With this configuration, I retrieve the baseline behavior: the test duration is normal when the full source workspace is not created before but it takes around 50% more time when the workspace already exists before the test is launched. Finally, the conclusions of these tries are: a. the problem is not in JDT/Core (see 1.) and seems to be in Platform/Resources b. the open and close project operation take less time before I20090317-1029 when the session was started on an unexisting workspace (or without any metadata) c. looking at difference before and after I20090317-1029 for org.eclipse.core.* projects in the repository, the only spot I can see is a change in the SaveManager.restoreMetaInfo(Project, IProgressMonitor) to fix bug 266907. Szymon, I will move this bug to Platform/Resources after having finished some complementary tests to know whether the fix for bug 266907 is really involved in this regression or not... Created attachment 132215 [details]
View of differnece using yourkit for open/close with or without exisiting metadata
I cannot attach the yourkit snapshots as even compressed the file is still more than 12Mb! Szymon, I can send it to you if you need them.
Instead here's a view of the comparison showing that close operation takes more time...
That's weird. IMO fix for bug 266907 could affect only opening a project. It does some extra work, when there are any problems when project is being opened. And the fix should not affect the performance of open/close if everything goes well. I have to look at it closer. (In reply to comment #5) > That's weird. IMO fix for bug 266907 could affect only opening a project. It > does some extra work, when there are any problems when project is being opened. > And the fix should not affect the performance of open/close if everything goes > well. I have to look at it closer. > I confirm that the line added to fix bug 266907 is never called while running our performance test, hence it does not seem to be the origin of the regression. Moreover, trying to complete my snapshots using yourkit, I saw a possible origin in our code. I changed some things in our performance full source workspace initialization which may have exhibit this regression due to an older change in the JavaModelManager... I'll continue my investigatations (lucky guy Szymon, for now this bug stay in our land... ;-) ) My last investigations confirm that the regression while closing projects comes from our side. This has been introduced while fixing bug 260848 (another perf issue) but was not noticed until I changed the projects classpath in the full source workspace while fixing bug 267789. My last fix added 5 jars on the classpath instead of only one before hence makes the extra time to save the non-chaining jars cache visible... Created attachment 132263 [details]
Proposed patch
Note that with this patch, yourkit profiling numbers are back to the baseline ones. I'm currently more complete performance tests to have more precise numbers...
Released for 3.5M7 in HEAD stream. The results look worst than before the fix was applied although the results I got locally showed that it was really better. I'm completely lost here.... I'll investigate Here are the test I did in a workspace: 1. R3_4: ~1000ms 2. v_949: ~2000ms 3. v_950: ~6000ms 4. v_950-released fix: ~6000ms 5. v_949+released fix: ~1000ms So, there's obviously another change in JDT/Core between v_949 and v_950 which definitely slows down the model (and especially this test...). Jerome, you did release changes in the model after this fix for bug 266771 and bug 271102. Could you please verify whether they may have strong performance impacts in this area? TIA BTW, I still continue to investigate to narrow more precisely the change which causes this grief... Close as we can consider the original issue fixed. The observed regression was likely due to fix for bug 271102 and is handled by bug 273308... Verified for 3.5M7 |