Bug 296686 - Folder type container has poor performance
Summary: Folder type container has poor performance
Status: VERIFIED FIXED
Alias: None
Product: PDE
Classification: Eclipse Project
Component: API Tools (show other bugs)
Version: 3.6   Edit
Hardware: All All
: P3 normal (vote)
Target Milestone: 3.6 M4   Edit
Assignee: Michael Rennie CLA
QA Contact:
URL:
Whiteboard:
Keywords: performance
Depends on:
Blocks: 233643
  Show dependency tree
 
Reported: 2009-12-02 06:40 EST by Markus Keller CLA
Modified: 2009-12-04 13:02 EST (History)
2 users (show)

See Also:
Michael_Rennie: review+


Attachments
complete thread dump (43.52 KB, text/plain)
2009-12-02 06:40 EST, Markus Keller CLA
no flags Details
performance trace (58.58 KB, text/plain)
2009-12-02 06:40 EST, Markus Keller CLA
no flags Details
proposed fix (18.88 KB, patch)
2009-12-03 10:20 EST, Michael Rennie CLA
no flags Details | Diff
updated fix (20.45 KB, patch)
2009-12-03 10:35 EST, Michael Rennie CLA
no flags Details | Diff
updated patch with tests (30.99 KB, patch)
2009-12-03 17:12 EST, Darin Wright CLA
no flags Details | Diff

Note You need to log in before you can comment on or make changes to this bug.
Description Markus Keller CLA 2009-12-02 06:40:02 EST
Created attachment 153580 [details]
complete thread dump

I20091201-1600

My dev workspace was completely compiled. I accepted several incoming changes,
one of which caused a compile error
(org.eclipse.jdt.internal.ui.preferences.ComplianceConfigurationBlock can't
resolve import BundleDefaultsScope).

The incremental build took very long. After a while, I took a thread dump and
started tracing, which confirmed that most of the time was burned in
FolderApiTypeContainer.collectPackageNames(..). I didn't see disk activity,
just one CPU core at 100%.

I could not reproduce by reverting and restoring ComplianceConfigurationBlock,
so the compile error may not be the actual problem.


"Worker-10" prio=6 tid=0x28d05800 nid=0x1c58 runnable [0x2cf7d000]
   java.lang.Thread.State: RUNNABLE
        at
org.eclipse.core.internal.dtree.AbstractDataTreeNode.indexOfChild(AbstractDataTreeNode.java:421)
        at
org.eclipse.core.internal.dtree.AbstractDataTreeNode.childAtOrNull(AbstractDataTreeNode.java:207)
        at
org.eclipse.core.internal.dtree.DeltaDataTree.lookup(DeltaDataTree.java:666)
        at
org.eclipse.core.internal.watson.ElementTree.includes(ElementTree.java:528)
        - locked <0x1ea278f8> (a org.eclipse.core.internal.watson.ElementTree)
        at
org.eclipse.core.internal.resources.Workspace.getResourceInfo(Workspace.java:1289)
        at
org.eclipse.core.internal.resources.Container.getChildren(Container.java:101)
        at
org.eclipse.core.internal.resources.Container.members(Container.java:185)
        at
org.eclipse.core.internal.resources.Container.members(Container.java:164)
        at
org.eclipse.pde.api.tools.internal.model.FolderApiTypeContainer.collectPackageNames(FolderApiTypeContainer.java:170)
        at
org.eclipse.pde.api.tools.internal.model.FolderApiTypeContainer.collectPackageNames(FolderApiTypeContainer.java:199)
        at
org.eclipse.pde.api.tools.internal.model.FolderApiTypeContainer.collectPackageNames(FolderApiTypeContainer.java:199)
        at
org.eclipse.pde.api.tools.internal.model.FolderApiTypeContainer.collectPackageNames(FolderApiTypeContainer.java:199)
        at
org.eclipse.pde.api.tools.internal.model.FolderApiTypeContainer.collectPackageNames(FolderApiTypeContainer.java:199)
        at
org.eclipse.pde.api.tools.internal.model.FolderApiTypeContainer.collectPackageNames(FolderApiTypeContainer.java:199)
        at
org.eclipse.pde.api.tools.internal.model.FolderApiTypeContainer.collectPackageNames(FolderApiTypeContainer.java:199)
        at
org.eclipse.pde.api.tools.internal.model.FolderApiTypeContainer.getPackageNames(FolderApiTypeContainer.java:155)
        at
org.eclipse.pde.api.tools.internal.model.AbstractApiTypeContainer.getPackageNames(AbstractApiTypeContainer.java:143)
        at
org.eclipse.pde.api.tools.internal.model.ApiBaseline.resolvePackage0(ApiBaseline.java:560)
        at
org.eclipse.pde.api.tools.internal.model.ApiBaseline.resolvePackage(ApiBaseline.java:506)
        - locked <0x1688e618> (a
org.eclipse.pde.api.tools.internal.model.WorkspaceBaseline)
        at
org.eclipse.pde.api.tools.internal.builder.SystemApiDetector.considerReference(SystemApiDetector.java:397)
        at
org.eclipse.pde.api.tools.internal.builder.ReferenceAnalyzer$Visitor.visit(ReferenceAnalyzer.java:109)
        at
org.eclipse.pde.api.tools.internal.model.FolderApiTypeContainer.doVisit(FolderApiTypeContainer.java:106)
        at
org.eclipse.pde.api.tools.internal.model.FolderApiTypeContainer.doVisit(FolderApiTypeContainer.java:125)
        at
org.eclipse.pde.api.tools.internal.model.FolderApiTypeContainer.doVisit(FolderApiTypeContainer.java:125)
        at
org.eclipse.pde.api.tools.internal.model.FolderApiTypeContainer.doVisit(FolderApiTypeContainer.java:125)
        at
org.eclipse.pde.api.tools.internal.model.FolderApiTypeContainer.doVisit(FolderApiTypeContainer.java:125)
        at
org.eclipse.pde.api.tools.internal.model.FolderApiTypeContainer.doVisit(FolderApiTypeContainer.java:125)
        at
org.eclipse.pde.api.tools.internal.model.FolderApiTypeContainer.doVisit(FolderApiTypeContainer.java:125)
        at
org.eclipse.pde.api.tools.internal.model.FolderApiTypeContainer.doVisit(FolderApiTypeContainer.java:125)
        at
org.eclipse.pde.api.tools.internal.model.FolderApiTypeContainer.accept(FolderApiTypeContainer.java:59)
        at
org.eclipse.pde.api.tools.internal.model.AbstractApiTypeContainer.accept(AbstractApiTypeContainer.java:56)
        at
org.eclipse.pde.api.tools.internal.model.Component.accept(Component.java:58)
        at
org.eclipse.pde.api.tools.internal.builder.ReferenceAnalyzer.extractReferences(ReferenceAnalyzer.java:265)
        at
org.eclipse.pde.api.tools.internal.builder.ReferenceAnalyzer.analyze(ReferenceAnalyzer.java:170)
        at
org.eclipse.pde.api.tools.internal.builder.ReferenceAnalyzer.analyze(ReferenceAnalyzer.java:292)
        at
org.eclipse.pde.api.tools.internal.builder.BaseApiAnalyzer.checkApiUsage(BaseApiAnalyzer.java:830)
        at
org.eclipse.pde.api.tools.internal.builder.BaseApiAnalyzer.analyzeComponent(BaseApiAnalyzer.java:260)
        at
org.eclipse.pde.api.tools.internal.builder.ApiAnalysisBuilder.buildAll(ApiAnalysisBuilder.java:388)
        at
org.eclipse.pde.api.tools.internal.builder.ApiAnalysisBuilder.build(ApiAnalysisBuilder.java:283)
        at
org.eclipse.core.internal.events.BuildManager$2.run(BuildManager.java:627)
        at org.eclipse.core.runtime.SafeRunner.run(SafeRunner.java:42)
        at
org.eclipse.core.internal.events.BuildManager.basicBuild(BuildManager.java:170)
        at
org.eclipse.core.internal.events.BuildManager.basicBuild(BuildManager.java:201)
        at
org.eclipse.core.internal.events.BuildManager$1.run(BuildManager.java:253)
        at org.eclipse.core.runtime.SafeRunner.run(SafeRunner.java:42)
        at
org.eclipse.core.internal.events.BuildManager.basicBuild(BuildManager.java:256)
        at
org.eclipse.core.internal.events.BuildManager.basicBuildLoop(BuildManager.java:309)
        at
org.eclipse.core.internal.events.BuildManager.build(BuildManager.java:341)
        at
org.eclipse.core.internal.events.AutoBuildJob.doBuild(AutoBuildJob.java:140)
        at
org.eclipse.core.internal.events.AutoBuildJob.run(AutoBuildJob.java:238)
        at org.eclipse.core.internal.jobs.Worker.run(Worker.java:55)
Comment 1 Markus Keller CLA 2009-12-02 06:40:35 EST
Created attachment 153581 [details]
performance trace
Comment 2 Michael Rennie CLA 2009-12-02 10:47:36 EST
Looking at the traces, I can not figure out why our visitor is taking up so much time. This code has not changed since it was created, there is obviously more to this.

I have reproduced the slow down on Linux using the following steps:

1. bring in jdt.core and jdt.ui from HEAD
2. make a breaking API change to one of them - wait for build
3. replace the changed one from HEAD

I also notice that the Java builder seems to take longer than normal as well using these steps - such that I can actually read the progress messages from it.

Running our performance updates all last week neither Darin nor myself saw this behavior. Investigating.
Comment 3 Markus Keller CLA 2009-12-02 13:47:41 EST
> I have reproduced the slow down on Linux using the following steps:
> [..]
> I also notice that the Java builder seems to take longer than normal as well
> using these steps - such that I can actually read the progress messages from
> it.

I'm on WinXP. On Linux, there's bug 296647, which is probably what you are seeing here. I did not get the excessive slowness again today -- with similar interactions that produced them this mornings. Reducing severity.

Maybe it was just a bad state after I started with the latest build. I'll add more info if I see this again.
Comment 4 Michael Rennie CLA 2009-12-02 14:16:55 EST
(In reply to comment #3)

> Maybe it was just a bad state after I started with the latest build. I'll add
> more info if I see this again.

That could be, but it should not be nearly as bad as you reported. Inspecting our code I did find that for every class file we are going to  build we end up re-looking up all the package names for the containing output directory. This is incredibly poor performance-wise as this method recurses through the resource tree N times when it should only be done once.
Comment 5 Michael Rennie CLA 2009-12-03 10:20:40 EST
Created attachment 153732 [details]
proposed fix

The patch now properly caches package names so that they are only computed once (and recomputed if the backing project changes). The patch also removes the recursive visitation of the output folders and instead uses an IResourceProxyVisitor.
Comment 6 Michael Rennie CLA 2009-12-03 10:35:58 EST
Created attachment 153734 [details]
updated fix

Apparently the other patch is not complete, an NLS'd string did not make it into the patch.
Comment 7 Darin Wright CLA 2009-12-03 17:12:40 EST
Created attachment 153781 [details]
updated patch with tests
Comment 8 Darin Wright CLA 2009-12-04 11:18:52 EST
Committed patch & tests. Please verify, Mike.
Comment 9 Darin Wright CLA 2009-12-04 11:19:14 EST
Fixed.
Comment 10 Michael Rennie CLA 2009-12-04 13:02:03 EST
new tests all pass.