Bug 176808 - 4% regression in build performance test #testFullBuildProjectAllWarnings
Summary: 4% regression in build performance test #testFullBuildProjectAllWarnings
Status: VERIFIED FIXED
Alias: None
Product: JDT
Classification: Eclipse Project
Component: Core (show other bugs)
Version: 3.3   Edit
Hardware: PC Windows XP
: P1 normal (vote)
Target Milestone: 3.3 RC1   Edit
Assignee: Frederic Fusier CLA
QA Contact:
URL:
Whiteboard:
Keywords: performance, test
Depends on:
Blocks:
 
Reported: 2007-03-09 06:25 EST by Frederic Fusier CLA
Modified: 2007-11-08 03:49 EST (History)
5 users (show)

See Also:


Attachments
Proposed patch (5.33 KB, patch)
2007-04-16 14:53 EDT, Kent Johnson CLA
no flags Details | Diff

Note You need to log in before you can comment on or make changes to this bug.
Description Frederic Fusier CLA 2007-03-09 06:25:48 EST
Releng results on performance test #testFullBuildProjectAllWarnings of FullSourceWorkspaceBuildTests suite shows a regression between 0% and 9% depending on test box.

Our local results confirm this regression which seems to be around 4%...
Comment 1 Frederic Fusier CLA 2007-03-09 09:45:43 EST
First investigation shows that options are not the same:
3.2:
- org.eclipse.jdt.core.compiler.problem.rawTypeReference
  -> ignore
3.3:
- org.eclipse.jdt.core.codeComplete.suggestStaticImports
  -> enabled
- org.eclipse.jdt.core.compiler.generateClassFiles
  -> enabled
- org.eclipse.jdt.core.compiler.problem.overridingMethodWithoutSuperInvocation 
  -> ignore
- org.eclipse.jdt.core.compiler.problem.potentialNullReference
  -> ignore
- org.eclipse.jdt.core.compiler.problem.rawTypeReference
  -> warning
- org.eclipse.jdt.core.compiler.problem.redundantNullCheck
  -> ignore
- org.eclipse.jdt.core.compiler.processAnnotations
  -> disabled

But these differences cannot explain the increase of time as they do not really concern the build on 1.4 sources but only completion, annotations or raw types.

Reported warnings are also different between the 2 versions:
3.3:
 - resource CodeSnippetCodeStream.java:
 - resource CompletionEngine.java:
 - resource CorrectionEngine.java:
		-> Empty block should be documented
 - resource BinaryType.java:
 - resource IType.java:
 - resource JavaCore.java:
 - resource SearchEngine.java:
 - resource SourceType.java:
		-> The type IWorkingCopy is deprecated

3.2:
 - resource ASTParser.java:
		-> Javadoc: Missing return type description
 - resource DOMBuilder.java:
		-> The type IDOMField[] is deprecated
 - resource BinaryType.java:
 - resource IType.java:
 - resource JavaCore.java:
 - resource SearchEngine.java:
 - resource SourceType.java:
		-> The type IWorkingCopy[] is deprecated

The javadoc warning disappeared due to bug 166365.
Empty block warning appeared due to bug 160337.
Deprecation message range has been changed (cannot retrieve the associated bug).
However, all these changes also cannot explain the time difference...
Comment 2 Kent Johnson CLA 2007-04-16 12:08:01 EDT
So how many errors & warnings were reported before in 3.2?

vs. how many errors & warnings are reported now in 3.3?
Comment 3 Frederic Fusier CLA 2007-04-16 12:18:04 EDT
(In reply to comment #2)
> So how many errors & warnings were reported before in 3.2?
> 
0 errors, 19004 warnings

> vs. how many errors & warnings are reported now in 3.3?
> 
0 errors, 19014 warnings
Comment 4 Kent Johnson CLA 2007-04-16 13:49:40 EDT
Looking back at the elapsed times of the full build tests (all warnings) of JDT/Core between Nov. 28 & Dec. 14:

1.2% - Win XP Sun 1.4.2_10 (3 GHz 2 GB) went from 11.51 to 11.65

2.3% - Win XP Sun 1.4.2_10 (2 GHz 512 MB) went from 16.03 to 16.4

2.3% - RHEL 4.0 Sun 1.4.2_10 (3 GHz 2.5 GB) went from 8.19 to 8.38

2.5% - RHEL 3.0 Sun 1.4.2_10 (3 GHz 2 GB) went from 9.51 to 9.75

2.3% - RHEL 3.0 Sun 1.4.2_10 (2 GHz 512 MB) went from 14.26 to 14.59

This seems to be the only consistent jump in the test. All the other results seem to be within a reasonable range.
Comment 5 Kent Johnson CLA 2007-04-16 14:53:15 EDT
Created attachment 63940 [details]
Proposed patch

The only significant change in the builder between v_725 (Nov.28) & v_728 (Dec. 19) was the introduction of the IMarker.GENERATED_BY attribute.

Can setting an attribute on 19000 markers account for a 2.5% slowdown?

The call to set an attribute seems to be fairly expensive (see Marker.setAttribute()).

I've released this patch to speed up Marker creation.

Maxime, do you have any other suggestions?
Comment 6 Maxime Daniel CLA 2007-04-17 02:41:40 EDT
(In reply to comment #5)
> Can setting an attribute on 19000 markers account for a 2.5% slowdown?
The difference between all warnings and no warning at all amounts to roughly 30% or the elapsed time. Accordingly, your question is: could a(n extra) call to Marker.setAttribute account for (a bit less than) 10% of the time needed to handle a warning?
> 
> The call to set an attribute seems to be fairly expensive (see
> Marker.setAttribute()).
Agreed, and the change your patch brings (roughly, batch attributes changes by calling Marker.setAttributes once) makes sense.
> 
> I've released this patch to speed up Marker creation.
> 
> Maxime, do you have any other suggestions?
> 
I have no clue how the extra setAttribute can balance with other warning reporting activities (especially IOs), but it does not sound plain stupid at first glance to consider that this could be enough to bring us back in good shape (assuming that each setAttribute* call costs roughly 10% of raising a warning, two cost 20%, leaving 80% for the other activities). Since your patch is released, I would defer further investigations until we get the perf results with it. Sounds reasonable?
Comment 7 Jerome Lanneluc CLA 2007-04-18 05:01:58 EDT
Performance tests for I20070416-0800 indicates that we are now between -0.5% and +2.2%. That's very good. If we can get 2-3 % more to get a solid green, that would be awesome.
Comment 8 Philipe Mulet CLA 2007-04-18 20:38:38 EDT
Impressive.
Comment 9 Frederic Fusier CLA 2007-05-02 07:26:10 EDT
Here are the new numbers on this tests since I20070424-0930 build results:
 - lnx3_R3.3: -4.7% < time < -4.2%
 - win2_R3.3: +0.6% < time < +2.0%
 - lnx2_R3.3: -0.4% < time < +0.3%
 - win1_R3.3: -1.9% < time < -0.9%
 - lnx1_R3.3: -2.6% < time < -1.1%

So, consider this issue fixed as, except for one box, results are back to acceptable level. Note that on lnx3_R3.3, error is noticeable (around 1.5%) and moderate a little bit this inconsistent results vs other boxes...

Of course, as results are not all green, I'll keep an eye on this test in the future...
Comment 10 Frederic Fusier CLA 2007-05-02 10:43:09 EDT
M7 is closed for JDT/Core now => move target to RC1 (and add 2 weeks to have a chance to make the numbers even better...)
Comment 11 Maxime Daniel CLA 2007-05-15 04:59:26 EDT
Both latest I build with published performance results (I20070508-0800) and our local results circa v_757 are reasonably good on the considered scenario.
Verified for 3.3 RC1 using I20070508-0800.