Bug 540712 - Running JUnit test takes long due to Creating Type Hierarchy
Summary: Running JUnit test takes long due to Creating Type Hierarchy
Status: RESOLVED FIXED
Alias: None
Product: JDT
Classification: Eclipse Project
Component: Core (show other bugs)
Version: 4.9   Edit
Hardware: PC Windows 10
: P3 normal with 3 votes (vote)
Target Milestone: 4.16 M3   Edit
Assignee: Eric Milles CLA
QA Contact: Stephan Herrmann CLA
URL:
Whiteboard:
Keywords: performance
Depends on: 560451
Blocks: 560449
  Show dependency tree
 
Reported: 2018-11-02 05:43 EDT by David Karnok CLA
Modified: 2020-07-31 09:13 EDT (History)
9 users (show)

See Also:


Attachments
Heap dump when create type hierarchy is running for a large project (27.38 KB, image/png)
2019-03-07 12:58 EST, Eric Milles CLA
no flags Details
Proposed changes to reduce TypeBound[] instances (4.24 KB, patch)
2019-03-07 13:02 EST, Eric Milles CLA
no flags Details | Diff
Proposed changes to HierarchyResolver to reduce creation of progress monitors (2.60 KB, patch)
2019-03-13 18:00 EDT, Eric Milles CLA
no flags Details | Diff

Note You need to log in before you can comment on or make changes to this bug.
Description David Karnok CLA 2018-11-02 05:43:47 EDT
I've switched from Eclipse 4.7.3a to 4.9 and since then, running JUnit (4.12) tests of a project with 10.000+ test methods (right click on the project, select Run > As JUnit test) takes 30-60 seconds to start the status bar shows "Creating Type Hierarchy" for a long time, every time (no changes to the project inbetween).

Project: https://github.com/ReactiveX/RxJava

Additional info:
- I have the Gradle STS plugin with 4.7.3a and the (out of box) Buildship plugin in 4.9
- If I import the project as Buildship into 4.7.3a, it is slow too - not sure why as running the test should have no interaction with the plugin.

A Flight Recorder capture indicates these:

Package	Sample Count	Percentage(%)
org.eclipse.jdt.internal.core	756	28,177
org.eclipse.jdt.internal.core.search	707	26,351
org.eclipse.jdt.internal.compiler.lookup	443	16,511
java.lang	220	8,2
org.eclipse.jdt.internal.compiler.parser	195	7,268
org.eclipse.jdt.internal.compiler.util	71	2,646
org.eclipse.jdt.internal.compiler.ast	69	2,572
java.util	53	1,975


Class	Sample Count	Percentage(%)
org.eclipse.jdt.internal.core.search.JavaSearchScope	707	26,351
org.eclipse.jdt.internal.core.JavaElement	581	21,655

Stack Trace	Sample Count	Percentage(%)
org.eclipse.jdt.internal.core.search.JavaSearchScope.encloses(IJavaElement)	704	26,239
org.eclipse.jdt.internal.core.JavaElement.equals(Object)	533	19,866
java.lang.String.equals(Object)	201	7,492
org.eclipse.jdt.internal.core.SourceMethod.equals(Object)	71	2,646
org.eclipse.jdt.internal.core.JavaElement.getAncestor(int)	42	1,565
org.eclipse.jdt.internal.compiler.lookup.Scope.getTypeOrPackage(char[], int, boolean)	35	1,305
org.eclipse.jdt.internal.compiler.lookup.LookupEnvironment.createParameterizedGenericMethod(MethodBinding, TypeBinding[], boolean, boolean)	35	1,305
org.eclipse.jdt.internal.core.SourceRefElement.equals(Object)	34	1,267
org.eclipse.jdt.internal.compiler.lookup.TypeSystem.getWildcard(ReferenceBinding, int, TypeBinding, TypeBinding[], int)	33	1,23
org.eclipse.jdt.internal.compiler.parser.Parser.parse()	31	1,155
Comment 1 Stephan Herrmann CLA 2018-11-06 06:59:30 EST
As you mention STS, what is the exact version number of plugin org.eclipse.jdt.core?
Comment 2 David Karnok CLA 2018-11-06 07:18:54 EST
In Eclipse 4.7.3a:

- org.eclipse.jdt.core: 3.13.102.v20180330-0919
- org.eclipse.buildship: 2.2.1.v20180125-1441
- Gradle IDE: 3.9.4.201805142235-RELEASE

In Eclipse 4.9:
- org.eclipse.jdt.core: 3.15.0.v20180905-0317
- org.eclipse.buildship: 2.2.1.v20180125-1441 (yes, the same as above)
Comment 3 Stephan Herrmann CLA 2018-11-06 07:34:45 EST
(In reply to David Karnok from comment #2)
> In Eclipse 4.7.3a:
> 
> - org.eclipse.jdt.core: 3.13.102.v20180330-0919
> - org.eclipse.buildship: 2.2.1.v20180125-1441
> - Gradle IDE: 3.9.4.201805142235-RELEASE
> 
> In Eclipse 4.9:
> - org.eclipse.jdt.core: 3.15.0.v20180905-0317
> - org.eclipse.buildship: 2.2.1.v20180125-1441 (yes, the same as above)

Thanks, so those are indeed original versions of jdt.core.
Comment 4 Eric Milles CLA 2019-03-07 12:58:16 EST
Created attachment 277802 [details]
Heap dump when create type hierarchy is running for a large project

We have been experiencing this issue as well.  When taking a heap dump during the "Creating type hierarchy" step of Run As > JUnit Test, users are seeing lots of TypeBound[] instances.

I think org.eclipse.jdt.internal.compiler.lookup.BoundSet is aggressively creating and copying arrays.  I will post a patch that reduces this somewhat.
Comment 5 Eric Milles CLA 2019-03-07 13:02:33 EST
Created attachment 277803 [details]
Proposed changes to reduce TypeBound[] instances

Here are some proposed changes that can reduce the amount of TypeBound[] instances when creating Type Hierarchy.
Comment 6 Andrey Loskutov CLA 2019-03-08 08:07:46 EST
(In reply to Eric Milles from comment #5)
> Created attachment 277803 [details]
> Proposed changes to reduce TypeBound[] instances
> 
> Here are some proposed changes that can reduce the amount of TypeBound[]
> instances when creating Type Hierarchy.

Eric, could you please create Gerrit patch?
Comment 7 Eric Milles CLA 2019-03-08 08:57:12 EST
Sorry, not sure how to deal with Gerrit.

I am just proposing these changes for further investigation.  I don't know the origin of the 1024 array size, so my reduction to 4 may be reducing memory footprint but hurting performance.


Quick note: These changes reduced my Run As > JUnit startup time from 1:42 to 1:25, so there is likely more to be done.  But it did help developers getting OutOfMemoryErrors successfully start their tests.
Comment 8 Andrey Loskutov CLA 2019-03-08 09:12:35 EST
(In reply to Eric Milles from comment #7)
> Sorry, not sure how to deal with Gerrit.

May be this helps: https://wiki.eclipse.org/Platform_UI/How_to_Contribute ?
A Gerrit patch allows us to work with the contribution and discuss directly on the code. If the patch is OK, it could be also directly merged.
Comment 9 Eric Milles CLA 2019-03-08 09:50:32 EST
I'm not working directly from JDT Core or JDT UI.  I have a patched org.eclipse.jdt.core that I used to try something out quickly.
Comment 10 Stephan Herrmann CLA 2019-03-10 14:52:50 EDT
(In reply to Eric Milles from comment #5)
> Created attachment 277803 [details]
> Proposed changes to reduce TypeBound[] instances
> 
> Here are some proposed changes that can reduce the amount of TypeBound[]
> instances when creating Type Hierarchy.

Thanks.

While this is a sensitive code area, avoiding creation of empty arrays is a valid pattern, already used in various places in the compiler.

(In reply to Eric Milles from comment #7)
> Sorry, not sure how to deal with Gerrit.

It's OK, I can work with an "old-school" patch :)

> I am just proposing these changes for further investigation.  I don't know
> the origin of the 1024 array size, so my reduction to 4 may be reducing
> memory footprint but hurting performance.

My guess is that 4 is a bit too low. Would you be able to measure if a compromise, say 16, would already have a similarly positive effect?
 
 
> Quick note: These changes reduced my Run As > JUnit startup time from 1:42
> to 1:25, so there is likely more to be done.  But it did help developers
> getting OutOfMemoryErrors successfully start their tests.

So we assume the speed-up is directly linked to less GC pressure?
Comment 11 Eric Milles CLA 2019-03-11 12:43:55 EDT
I ran tests locally and the array that was once 1024 by default was never grown from size 4 to 8.  So I'm happy with the size 4; the code to increase its size when necessary remains in place.

Yes, in this case we achieved performance boost by reduction of allocations plus the array copy operations in copy() method.
Comment 12 Eric Milles CLA 2019-03-12 12:49:02 EDT
With some additional testing on a larger project, I did hit the array growth code with size 4.  8 or 16 would probably make a better default value.
Comment 13 Eric Milles CLA 2019-03-13 17:50:55 EDT
It seems the longest part of Create Type Hierarchy is "parsedUnit.scope.faultInTypes(); parsedUnit.resolve();" which happens near the end of "HierarchyResolver.resolve(Openable[] openables, HashSet localTypes, IProgressMonitor monitor)".

JUnit search for tests uses RegionBasedTypeHierarchy when initiated from a source folder or package.  And RBTH passes null for the localTypes parameter, so this code always sets containsLocalType to true:

	// contains a potential subtype as a local or anonymous type?
	boolean containsLocalType = false;
	if (localTypes == null) { // case of hierarchy on region
		containsLocalType = true;
	} else {
		containsLocalType = cu.isWorkingCopy() ? true /* presume conservatively */ : localTypes.contains(cu.getPath().toString());
	}


Is there a more accurate way to check for local types from an org.eclipse.jdt.core.ICompilationUnit or org.eclipse.jdt.internal.compiler.ast.CompilationUnitDeclaration?  If so, this flag could be set to false more often than not and quite expensive type resolution could be skipped.  In my case I could go from over 70 seconds to 42 seconds.


What sorts of things fail if this resolution is skipped for region-based type hierarchies?
Comment 14 Eric Milles CLA 2019-03-13 18:00:08 EDT
Created attachment 277857 [details]
Proposed changes to HierarchyResolver to reduce creation of progress monitors

I think the use of SubMonitor.split(1) should be replaced by IProgressMonitor.worked(1) to reduce the creation of possibly thousands of unused progress monitor instances.
Comment 15 Eric Milles CLA 2019-03-14 13:31:12 EDT
(In reply to Eric Milles from comment #13)
> In my case I could go from over 70 seconds to 42 seconds.

Actually type hierarchy went from 70399 ms to 8279 ms.  The total time to launch JUnit tests went from ~104 seconds to ~52 seconds.
Comment 16 Stephan Herrmann CLA 2019-03-14 14:08:57 EDT
(In reply to Eric Milles from comment #14)
> Created attachment 277857 [details]
> Proposed changes to HierarchyResolver to reduce creation of progress monitors
> 
> I think the use of SubMonitor.split(1) should be replaced by
> IProgressMonitor.worked(1) to reduce the creation of possibly thousands of
> unused progress monitor instances.

Full replacement would not be a good idea, since only split() supports cancelling, worked() doesn't.
Comment 17 Stephan Herrmann CLA 2019-03-14 14:24:36 EDT
(In reply to Eric Milles from comment #13)
> It seems the longest part of Create Type Hierarchy is
> "parsedUnit.scope.faultInTypes(); parsedUnit.resolve();" which happens near
> the end of "HierarchyResolver.resolve(Openable[] openables, HashSet
> localTypes, IProgressMonitor monitor)".
> 
> JUnit search for tests uses RegionBasedTypeHierarchy when initiated from a
> source folder or package.  And RBTH passes null for the localTypes
> parameter, so this code always sets containsLocalType to true:
> 
> 	// contains a potential subtype as a local or anonymous type?
> 	boolean containsLocalType = false;
> 	if (localTypes == null) { // case of hierarchy on region
> 		containsLocalType = true;
> 	} else {
> 		containsLocalType = cu.isWorkingCopy() ? true /* presume conservatively */
> : localTypes.contains(cu.getPath().toString());
> 	}
> 
> 
> Is there a more accurate way to check for local types from an
> org.eclipse.jdt.core.ICompilationUnit or
> org.eclipse.jdt.internal.compiler.ast.CompilationUnitDeclaration?  If so,
> this flag could be set to false more often than not and quite expensive type
> resolution could be skipped.  In my case I could go from over 70 seconds to
> 42 seconds.

That's a very interesting find!

The parser sets #bits |= ASTNode.HasLocalType on each field, method or type directly containing a local type. I'm not sure if this could additionally be propagated further out, e.g., to the CUD. bit 2 seems to be unused for CUD, so it's worth a try.
If not, a coarse grained AST traversal should still be fast enough for this purpose.
 
 
> What sorts of things fail if this resolution is skipped for region-based
> type hierarchies?

Hierarchy would be incomplete if any local types should be seen as members of the hierarchy.
Comment 18 Eric Milles CLA 2019-03-28 12:11:03 EDT
I compared test start up time between current (4.11), 4.7.3a and 4.6.3.  All are taking a similar amount of time to start a batch of JUnit4 tests.  Type hierarchy and search for Test and RunWith annotations (in JUnit4TestFinder) take more than 1 minute 20 seconds for a project with ~16000 JUnit test cases.

> The parser sets #bits |= ASTNode.HasLocalType on each field, method or type directly containing a local type.

I had a look at this and I think the parser has not run far enough at the point in HierarchyResolver where the bits would be available.  Once a unit moves through "parsedUnit.scope.faultInTypes(); and parsedUnit.resolve();" these bits are indeed set.

I was wondering why the sources are re-parsed for type hierarchy.  For the purposes of Run As, aren't only class files to be considered?
Comment 19 Manoj N Palat CLA 2019-08-27 02:06:57 EDT
Bulk move out of 4.13
Comment 20 Stephan Herrmann CLA 2020-04-05 17:09:34 EDT
Sorry, we ran out of time for 4.16 M1, moving to M3 (since M2 is not a defined milestone, just on I-build that is contributed to Eclipse 2020-06), hoping to get to this soon.
Comment 22 Stephan Herrmann CLA 2020-05-12 18:14:46 EDT
(In reply to Eclipse Genie from comment #21)
> Gerrit change https://git.eclipse.org/r/158126 was merged to [master].
> Commit:
> http://git.eclipse.org/c/jdt/eclipse.jdt.core.git/commit/
> ?id=b4ef933a2eb6a626ac46a0b6b74b39d792552f4a

I released this optimization to master for 4.16 M3

Thanks Eric!

For book keeping I'm resolving this bug.

@Eric, if you have more improvements ready, we could possibly still add them to 4.16 via this bug.

Otherwise, for further optimization let's use a new bug.
Comment 23 Vikas Chandra CLA 2020-05-19 07:54:24 EDT
Is there a way we can verify this optimization? For example, opening type hierarchy on a class X in project Y takes z% less time !
Comment 24 Mauro Molinari CLA 2020-07-31 09:05:29 EDT
I find it still unbearably slow to run a JUnit launch for multiple tests on 4.16 compared to some old Eclipse version.

- it's incredibly slow (minutes and minutes) to show the launch configuration contents in the "Run Configurations" dialog
- it's unbearably slow (minutes and minutes) to actually start the test process once you click on "Run" in the "Run Configurations" dialog or through the "Play button". In this case, the Progress View shows "Creating Type Hierarchy..." while the launch is in progress

I'm observing this on a JUnit 4 configuration containing 1632 test methods spread over 15 test classes.

What happened here? Maybe this is due the removal of the experimental new indexer?
Comment 25 Andrey Loskutov CLA 2020-07-31 09:13:36 EDT
(In reply to Mauro Molinari from comment #24)
> I find it still unbearably slow to run a JUnit launch for multiple tests on
> 4.16 compared to some old Eclipse version.

Please create new bug and attach few jstack dumps created while you are waiting on launch config dialog.