Bug 213421 - [performance] Possible performance regression shown by JavaFormatterTest#test()
Summary: [performance] Possible performance regression shown by JavaFormatterTest#test()
Status: VERIFIED FIXED
Alias: None
Product: JDT
Classification: Eclipse Project
Component: Text (show other bugs)
Version: 3.4   Edit
Hardware: PC Windows XP
: P1 normal (vote)
Target Milestone: 3.4 M7   Edit
Assignee: JDT-Text-Inbox CLA
QA Contact:
URL:
Whiteboard:
Keywords: performance, test
Depends on:
Blocks:
 
Reported: 2007-12-19 03:12 EST by Frederic Fusier CLA
Modified: 2008-05-08 12:23 EDT (History)
3 users (show)

See Also:


Attachments
yourkit memory snapshot, biggest retained sizes after the test (44.21 KB, image/png)
2008-05-08 11:17 EDT, Benno Baumgartner CLA
no flags Details

Note You need to log in before you can comment on or make changes to this bug.
Description Frederic Fusier CLA 2007-12-19 03:12:13 EST
Looking at results for JDT/Text formatter performance test org.eclipse.jdt.text.tests.performance.JavaFormatterTest#test(), it looks like there's a regression in this area since 3.3. I didn't warn about this test before because the results had noticeable variations, but as there are now negative on all test boxes, I think some times may be spent to investigate if some changes had caused this regression or if some improvements could be done to get the results back to positive...

Not for sure, but it seems that there's a gap in the results of this test since I20071127-0800. Before, results varied between +3 and -4%, after the variations shifted to always negative values: between -3% and -13%.
Comment 1 Dani Megert CLA 2007-12-19 03:45:33 EST
Fréderic, as far as I can see JDT Core does not seem to have formatter performance tests. This makes it hard to tell whether the regression is in the UI or Core. I know that work is/was done in JDT Core on the formatter. Could you investigate and also add JDT Core tests?
Comment 2 Frederic Fusier CLA 2007-12-19 04:08:02 EST
If you look in Scenario Status table of JDT/Core perf results page, you'll see that we already have 2 tests for the formatter:
FullSourceWorkspaceFormatterTests.testFormatDefault() 
FullSourceWorkspaceFormatterTests.testFormatDefaultBigFile()

The results are respectively:
-2.2% [±1.5] 	-2.5% [±1.4] 	-1.6% [±1.4] 	-2.5% [±1.8] 	+0.8% [±2.2]
-1.3% [±0.3] 	+0.5% [±0.1] 	-0.9% [±0.1] 	-1.3% [±0.2] 	-0.7% [±0.4]

This shows a small regression and I've already opened bug 210543 about this.

I opened a new bug against JDT/Text as the results seemed to be more important than this thin regression in JDT/Core formatter and perhaps it may be interesting to understand why.
Comment 3 Dani Megert CLA 2007-12-19 04:14:49 EST
I see. I was probably on the wrong component when I searched for 'format'.
Comment 4 Benno Baumgartner CLA 2008-01-31 12:51:19 EST
Here are my findings:
3311:
RangeDifferencer#findDifferences              1890ms 100%
-> RangeDifferencer.findDifferencesUkkonen    1000ms 53%
-> Levenshtein.findDifferences                 890ms 47%

HEAD:
RangeDifferencer#findDifferences              7265ms 100%
-> RangeDifferencer.findDifferencesUkkonen    1001ms 14%
-> Levenshtein.findDifferences                6234ms 86%

Looks like findDifferencesUkkonen throws a LowMemoryException way more often in HEAD then in 3311:
try {
	return findDifferencesUkkonen(pm, left, right);
} catch (LowMemoryException e) {
	return Levenshtein.findDifferences(pm, left, right);
}

crazy code btw. The RangeDifferencer seams to make this test unpredictable. I did run the test a couple of times and the amount of calls to LinkedRangeFactory#newRange is between 0 and 22000. Maybe we should turn off quick diff for this test?

Comment 5 Dani Megert CLA 2008-02-01 07:52:10 EST
Did you set the -Xms250M -Xmx250M? If not you tested something completely different.
Comment 6 Benno Baumgartner CLA 2008-02-01 15:42:00 EST
(In reply to comment #5)
> Did you set the -Xms250M -Xmx250M? If not you tested something completely
> different.
> 

Yes, although I did set it to 512.
Comment 7 Dani Megert CLA 2008-02-02 06:42:20 EST
>Yes, although I did set it to 512.
Maybe this is too high ;-) Also, did you use exact same VM?
Comment 8 Benno Baumgartner CLA 2008-02-04 05:22:34 EST
Ok, more findings:
Set up is java sun 1.5.0_12 with -Xmx250m -Xms250m

Used heap before we start measure is: 
3311: 147mb
HEAD: 198mb

Which is a pretty clear regression and may lead faster to low memory in the quick diff. Yourkit shows that following big objects are in HEAD heap but not in 3311 heap:

org.eclipse.core.internal.registry.ExtensionRegistry
  6.5mb referenced by org.eclipse.pde.internal.core.PDEExtensionRegistry#fRegistry
org.eclipse.core.internal.registry.RegistryObjectManager
  6.5mb referenced by org.eclipse.pde.internal.core.PDEExtensionRegistry#fRegistry
org.eclipse.core.internal.registry.KeyedHashSet
  5.8mb referenced by you guess
org.eclipse.core.internal.registry.KeyedElement[28673]
  5.8mb referenced by ...

This objects referenced by PDE do not exist in 3.3.1.1. 
This got introduced with bug 166610. Do this objects have to be that big? The platforms registry is much smaller (~2mb). Maybe a leak in PDE? 
Comment 9 Benno Baumgartner CLA 2008-02-04 05:42:44 EST
(In reply to comment #8)
> This got introduced with bug 166610. Do this objects have to be that big? The
> platforms registry is much smaller (~2mb). Maybe a leak in PDE? 
> 

Forcing garbage collection makes this object _not_ go away. They are not garbage. After garbage collection the used heap is ~60mb, and ~25mb is used by this registry, which is pretty bad.

Comment 10 Benno Baumgartner CLA 2008-02-04 06:35:46 EST
Mmm, the amount of calls to LinkedRangeFactory#newRange is 0 most of the times on my machine, in Head and 3311:-( But I also saw 22000 calls on my machine, I think it highly depends if the quick diff job runs before the test finishes. I guess this is also the reason for the noticeable variations we see in this test.

More regressions:
AnnotationPainter$1.run()     3311:  15ms   HEAD: 531ms
ProblemMarkerManager$1.run()  3311: 171ms   HEAD: 375ms
Comment 11 Dani Megert CLA 2008-02-04 06:40:06 EST
>AnnotationPainter$1.run()     3311:  15ms   HEAD: 531ms
Mmh: are there more problems (errors and warnings) on the file in HEAD?
Comment 12 Benno Baumgartner CLA 2008-02-04 09:07:50 EST
(In reply to comment #11)
> >AnnotationPainter$1.run()     3311:  15ms   HEAD: 531ms
> Mmh: are there more problems (errors and warnings) on the file in HEAD?
> 

No, 24 in 3311 vs. 24 in HEAD. Maybe this are quick diff annotations?
Comment 13 Benno Baumgartner CLA 2008-02-06 09:12:54 EST
Nothing I can do here, I would move it to PDE
Comment 14 Benno Baumgartner CLA 2008-03-26 09:40:22 EDT
(In reply to comment #13)
> Nothing I can do here, I would move it to PDE
 

Comment 15 Dani Megert CLA 2008-04-21 12:49:19 EDT
Benno, I tried to verify your findings but couldn't. I could neither make it use the slow diff alog nor see the PDE memory consumption.

Did you just run the JavaFormatterTest or the whole suite?

However, I do see the regression.
Comment 16 Dani Megert CLA 2008-04-23 08:31:25 EDT
Looked at this in detail now. There are several issues here:

1. Benno was right: in 3.4 more memory is used (+18MB alone for primitive data
   types like char[], int[] etc.). This isn't an issue when running the formatter
   test by itself but when running the whole suite the memory cap of the quick
   differ is reached and then it falls into slower mode which uses less memory.
   This can affect several JDT Text tests.
   Possible fixes:
   a) mark the test gray and explain the degradation
   b) disable quick diff on performance tests
      -> I don't like that as we want to get numbers which correspond to what
         what the users experience
   c) try to reduce memory
      -> Brian, you committed bug Bug 166610. When I looked at the additional 
         consumption I wasn't able to reproduce Benno's numbers but it would be
         great if you could have a second look and reduce the memory footprint
         if it turns out to be as Benno said.
   ==> I will go for a) but hopefully fixing bug 227098 brings us
       back into green land.

2. there is a huge (much bigger than 1.) regression that got introduced after
   M6. Due to a bug, a semantic highlighting got enabled which caused much more
   work for the editor. This affects many JDT Text tests.
   ==> fixed for N20080423-2000.

Comment 17 Dani Megert CLA 2008-04-28 05:42:41 EDT
Starting verification...
Comment 18 Dani Megert CLA 2008-04-28 12:09:34 EDT
Verified that the introduced huge regression got fixed. In addition, the test now runs much faster since I20080427-2000 due to the new and faster formatter in JDT Core (see bug 227098). Hence I removed the degradation comment again.
Comment 19 Benno Baumgartner CLA 2008-05-08 11:17:33 EDT
Created attachment 99308 [details]
yourkit memory snapshot, biggest retained sizes after the test

(In reply to comment #8)
> Ok, more findings:
> Set up is java sun 1.5.0_12 with -Xmx250m -Xms250m
> 
> Used heap before we start measure is: 
> 3311: 147mb
> HEAD: 198mb
> 
> Which is a pretty clear regression and may lead faster to low memory in the
> quick diff. Yourkit shows that following big objects are in HEAD heap but not
> in 3311 heap:
> 
> org.eclipse.core.internal.registry.ExtensionRegistry
>   6.5mb referenced by
> org.eclipse.pde.internal.core.PDEExtensionRegistry#fRegistry
> org.eclipse.core.internal.registry.RegistryObjectManager
>   6.5mb referenced by
> org.eclipse.pde.internal.core.PDEExtensionRegistry#fRegistry
> org.eclipse.core.internal.registry.KeyedHashSet
>   5.8mb referenced by you guess
> org.eclipse.core.internal.registry.KeyedElement[28673]
>   5.8mb referenced by ...
> 
> This objects referenced by PDE do not exist in 3.3.1.1. 
> This got introduced with bug 166610. Do this objects have to be that big? The
> platforms registry is much smaller (~2mb). Maybe a leak in PDE? 
> 

I can still reproduce this in I20080507-2000 with yourkit 7 although the objects are smaller now, but still pretty big, check the screen shot.
Comment 20 Dani Megert CLA 2008-05-08 12:23:09 EDT
Filed bug 231154 against PDE.