Bug 27764 - IResource.findMarkers is called too often
Summary: IResource.findMarkers is called too often
Status: RESOLVED FIXED
Alias: None
Product: Platform
Classification: Eclipse Project
Component: Resources (show other bugs)
Version: 2.1   Edit
Hardware: PC Windows 2000
: P3 major (vote)
Target Milestone: ---   Edit
Assignee: DJ Houghton CLA
QA Contact:
URL:
Whiteboard:
Keywords: performance
Depends on: 27948
Blocks:
  Show dependency tree
 
Reported: 2002-12-05 10:48 EST by John Arthorne CLA
Modified: 2005-01-06 11:54 EST (History)
3 users (show)

See Also:


Attachments
opening preference page (74.92 KB, text/plain)
2002-12-05 11:45 EST, Adam Kiezun CLA
no flags Details
opening package explorer (21.59 KB, text/plain)
2002-12-09 05:09 EST, Adam Kiezun CLA
no flags Details
expanding/collapsing nodes in packeage explorer 1 (8.29 KB, text/plain)
2002-12-09 05:25 EST, Adam Kiezun CLA
no flags Details

Note You need to log in before you can comment on or make changes to this bug.
Description John Arthorne CLA 2002-12-05 10:48:21 EST
Build I20021204.

I am investigating bug 11164, which states that when starting Eclipse in the
java perspective, roughly 40% of the time is in IResource.findMarkers.  I have
improved the performance of this method by 4x, but the slowness is largely due
to the number of times findMarkers is called.  Here are some JDT-specific
scenarios along with the number of times findMarkers is called in each case. 
All of these scenarios use the "big workspace" that Jeff made available on the
eclipse performance page.  This workspace has 134 projects, 812 warning markers,
and a total of 74133 resources, 7789 of which are team private (invisible to
most clients).

Startup in the resources perspective with one java file open (I used
CoreException.java).  Hit space bar in the editor, then save.  findMarkers is
called 1369 times, 44 of those on folders, 2 on files, and 1323 times on
projects (ten times for each project).

Simply switching to the java perspective after startup calls findMarkers 414
times, always on projects (roughly three times on each project).

You can get rough breakdown of where the number come from by carefully starting
components one at a time:

1) Open a new workbench in the resource perspective, no editors open.
2) Open a java preference page.  This of course starts JavaCore and JavaUI
plugins.  This causes findMarkers to be called 234 times on projects, a bit less
than twice for each project. I don't understand why it should be searching for
markers *at all* in this case.  

3) Then open a collapsed java package exlorer view.  This calls findMarkers a
further 178 times on projects.  This is mostly reasonable because it does have
to decorate each visible project in the tree.

4) After this, for each resource revealed in the package explorer, findMarkers
is called once for each resource.  Note that this is n^2 behaviour at best: it
calls findMarkers with depth infinity on each visible resource.  If findMarkers
on a parent has not revealed any markers, then calling findMarkers on all
children is a waste. In general, calling findMarkers in files is very cheap, but
calling it on folders near the root gets more expensive.

5) Then do a no-op edit on CoreException.java and save.  This calls findMarkers
a further 1142 times, mostly on projects.
Comment 1 Adam Kiezun CLA 2002-12-05 11:22:15 EST
major, I think
Comment 2 Adam Kiezun CLA 2002-12-05 11:45:49 EST
Created attachment 2677 [details]
opening preference page

one reason for calling findMarkers is included in the profile
but that's only 2% here
Comment 3 Adam Kiezun CLA 2002-12-09 04:13:48 EST
i'll have a look at this
Comment 4 Erich Gamma CLA 2002-12-09 04:17:20 EST
adding Martin - this is related to our error tick infrastructure
Comment 5 Adam Kiezun CLA 2002-12-09 05:09:48 EST
Created attachment 2718 [details]
opening package explorer

first opening of the package explorer - 72% of time is spent in findMarkers
Comment 6 Adam Kiezun CLA 2002-12-09 05:22:16 EST
most of the time spent on expanding/collapsing nodes is in figuring out which 
icon to choose for a IPackageFragment
see bug 27924
Comment 7 Adam Kiezun CLA 2002-12-09 05:25:02 EST
Created attachment 2720 [details]
expanding/collapsing nodes in packeage explorer 1

btw, 100% of which is spent in Openable.hasChildren
Comment 8 Adam Kiezun CLA 2002-12-09 05:30:24 EST
opened bug Bug 27925 for the slow Openable.hasChildren
Comment 9 Martin Aeschlimann CLA 2002-12-09 05:43:12 EST
My comments:
- I wonder why 'findMarkers' is called so many times on projects. Could you see 
how this happens.
- What would help a lot would be that core not only offers the findMarker ( 
returning the complete result in an array) but also an marker-Iterator. In our 
use case we can quit the iteration as soon as we found an error marker; the 
rest of the result are then not interesting.
- Point 4.) mentioned by John: The labelprovider is invoked on a single 
element, and doesn't know about childrens and parents. The thing to do would be 
to create a cache. We could keep e.g the last 20 results.

What we definitly should do is the now move to the 'decorator in a thread' 
infrastructure offered by the desktop.
However, we should really track down the problems first.


Comment 10 Martin Aeschlimann CLA 2002-12-09 05:46:48 EST
I meant that I wonder why findMarkers is called more on projects than on 
resources.
Comment 11 Adam Kiezun CLA 2002-12-09 08:11:21 EST
this calling findMarkers on projects seems to have sth to do with jface - or 
maybe we something bogus:

what follows are 2 stacktraces of calls to 
ProblemsLabelDecorator.getErrorTicksFromMarkers which calls findMarkers

the question is - why is it called twice for each element in the package 
expolorer and can we avoid it?
	at org.eclipse.jdt.ui.ProblemsLabelDecorator.getErrorTicksFromMarkers
(ProblemsLabelDecorator.java:199)
	at org.eclipse.jdt.ui.ProblemsLabelDecorator.computeAdornmentFlags
(ProblemsLabelDecorator.java:156)
	at org.eclipse.jdt.ui.ProblemsLabelDecorator.decorateImage
(ProblemsLabelDecorator.java:139)
	at org.eclipse.jdt.internal.ui.viewsupport.JavaUILabelProvider.getImage
(JavaUILabelProvider.java:108)
	at org.eclipse.jface.viewers.DecoratingLabelProvider.getImage
(DecoratingLabelProvider.java:67)
	at org.eclipse.jface.viewers.TreeViewer.doUpdateItem(TreeViewer.java:83)
	at org.eclipse.jface.viewers.AbstractTreeViewer.doUpdateItem
(AbstractTreeViewer.java:363)
	at org.eclipse.jface.viewers.StructuredViewer.updateItem
(StructuredViewer.java:1132)
	at org.eclipse.jface.viewers.AbstractTreeViewer.createTreeItem
(AbstractTreeViewer.java:267)
	at org.eclipse.jface.viewers.AbstractTreeViewer.createChildren
(AbstractTreeViewer.java:252)
	at org.eclipse.jface.viewers.AbstractTreeViewer$2.run
(AbstractTreeViewer.java:655)
	at org.eclipse.jface.viewers.StructuredViewer.preservingSelection
(StructuredViewer.java:684)
	at org.eclipse.jface.viewers.AbstractTreeViewer.inputChanged
(AbstractTreeViewer.java:647)
	at org.eclipse.jface.viewers.ContentViewer.setInput
(ContentViewer.java:232)
	at org.eclipse.jface.viewers.StructuredViewer.setInput
(StructuredViewer.java:871)
	at 
org.eclipse.jdt.internal.ui.packageview.PackageExplorerPart.createPartControl
(PackageExplorerPart.java:281)
	at org.eclipse.ui.internal.PartPane$4.run(PartPane.java:135)
	at org.eclipse.core.internal.runtime.InternalPlatform.run
(InternalPlatform.java:843)
	at org.eclipse.core.runtime.Platform.run(Platform.java:413)
	at org.eclipse.ui.internal.PartPane.createChildControl
(PartPane.java:133)
	at org.eclipse.ui.internal.ViewPane.createChildControl
(ViewPane.java:202)
	at org.eclipse.ui.internal.PartPane.createControl(PartPane.java:177)
	at org.eclipse.ui.internal.ViewPane.createControl(ViewPane.java:181)
	at org.eclipse.ui.internal.PartTabFolder.createPartTab
(PartTabFolder.java:251)
	at org.eclipse.ui.internal.PartTabFolder.createControl
(PartTabFolder.java:223)
	at org.eclipse.ui.internal.PartSashContainer.createControl
(PartSashContainer.java:181)
	at org.eclipse.ui.internal.PerspectivePresentation.activate
(PerspectivePresentation.java:94)
	at org.eclipse.ui.internal.Perspective.onActivate(Perspective.java:666)
	at org.eclipse.ui.internal.WorkbenchPage.onActivate
(WorkbenchPage.java:1607)
	at org.eclipse.ui.internal.WorkbenchWindow$7.run
(WorkbenchWindow.java:1255)
	at org.eclipse.swt.custom.BusyIndicator.showWhile(BusyIndicator.java:65)
	at org.eclipse.ui.internal.WorkbenchWindow.setActivePage
(WorkbenchWindow.java:1242)
	at org.eclipse.ui.internal.WorkbenchWindow.restoreState
(WorkbenchWindow.java:1125)
	at org.eclipse.ui.internal.Workbench.restoreState(Workbench.java:1259)
	at org.eclipse.ui.internal.Workbench.access$7(Workbench.java:1228)
	at org.eclipse.ui.internal.Workbench$8.run(Workbench.java:852)
	at org.eclipse.core.internal.runtime.InternalPlatform.run
(InternalPlatform.java:843)
	at org.eclipse.core.runtime.Platform.run(Platform.java:413)
	at org.eclipse.ui.internal.Workbench.openPreviousWorkbenchState
(Workbench.java:804)
	at org.eclipse.ui.internal.Workbench.init(Workbench.java:604)
	at org.eclipse.ui.internal.Workbench.run(Workbench.java:1381)
	at org.eclipse.core.internal.boot.InternalBootLoader.run
(InternalBootLoader.java:840)
	at org.eclipse.core.boot.BootLoader.run(BootLoader.java:462)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke
(NativeMethodAccessorImpl.java:39)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke
(DelegatingMethodAccessorImpl.java:25)
	at java.lang.reflect.Method.invoke(Method.java:324)
	at org.eclipse.core.launcher.Main.basicRun(Main.java:247)
	at org.eclipse.core.launcher.Main.run(Main.java:703)
	at org.eclipse.core.launcher.Main.main(Main.java:539)


---------
	at org.eclipse.jdt.ui.ProblemsLabelDecorator.getErrorTicksFromMarkers
(ProblemsLabelDecorator.java:199)
	at org.eclipse.jdt.ui.ProblemsLabelDecorator.computeAdornmentFlags
(ProblemsLabelDecorator.java:156)
	at org.eclipse.jdt.ui.ProblemsLabelDecorator.decorateImage
(ProblemsLabelDecorator.java:139)
	at org.eclipse.jdt.internal.ui.viewsupport.JavaUILabelProvider.getImage
(JavaUILabelProvider.java:108)
	at org.eclipse.jface.viewers.DecoratingLabelProvider.getImage
(DecoratingLabelProvider.java:67)
	at org.eclipse.jface.viewers.TreeViewer.doUpdateItem(TreeViewer.java:83)
	at org.eclipse.jface.viewers.AbstractTreeViewer.doUpdateItem
(AbstractTreeViewer.java:363)
	at org.eclipse.jface.viewers.StructuredViewer.updateItem
(StructuredViewer.java:1132)
	at org.eclipse.jface.viewers.AbstractTreeViewer.internalRefresh
(AbstractTreeViewer.java:843)
	at org.eclipse.jface.viewers.AbstractTreeViewer.internalRefresh
(AbstractTreeViewer.java:857)
	at org.eclipse.jface.viewers.AbstractTreeViewer.internalRefresh
(AbstractTreeViewer.java:826)
	at org.eclipse.jface.viewers.StructuredViewer$4.run
(StructuredViewer.java:744)
	at org.eclipse.jface.viewers.StructuredViewer.preservingSelection
(StructuredViewer.java:684)
	at org.eclipse.jface.viewers.StructuredViewer.refresh
(StructuredViewer.java:742)
	at org.eclipse.jface.viewers.StructuredViewer.refresh
(StructuredViewer.java:704)
	at 
org.eclipse.jdt.internal.ui.packageview.PackageExplorerActionGroup.restoreState
(PackageExplorerActionGroup.java:193)
	at 
org.eclipse.jdt.internal.ui.packageview.PackageExplorerPart.restoreState
(PackageExplorerPart.java:762)
	at 
org.eclipse.jdt.internal.ui.packageview.PackageExplorerPart.createPartControl
(PackageExplorerPart.java:309)
	at org.eclipse.ui.internal.PartPane$4.run(PartPane.java:135)
	at org.eclipse.core.internal.runtime.InternalPlatform.run
(InternalPlatform.java:843)
	at org.eclipse.core.runtime.Platform.run(Platform.java:413)
	at org.eclipse.ui.internal.PartPane.createChildControl
(PartPane.java:133)
	at org.eclipse.ui.internal.ViewPane.createChildControl
(ViewPane.java:202)
	at org.eclipse.ui.internal.PartPane.createControl(PartPane.java:177)
	at org.eclipse.ui.internal.ViewPane.createControl(ViewPane.java:181)
	at org.eclipse.ui.internal.PartTabFolder.createPartTab
(PartTabFolder.java:251)
	at org.eclipse.ui.internal.PartTabFolder.createControl
(PartTabFolder.java:223)
	at org.eclipse.ui.internal.PartSashContainer.createControl
(PartSashContainer.java:181)
	at org.eclipse.ui.internal.PerspectivePresentation.activate
(PerspectivePresentation.java:94)
	at org.eclipse.ui.internal.Perspective.onActivate(Perspective.java:666)
	at org.eclipse.ui.internal.WorkbenchPage.onActivate
(WorkbenchPage.java:1607)
	at org.eclipse.ui.internal.WorkbenchWindow$7.run
(WorkbenchWindow.java:1255)
	at org.eclipse.swt.custom.BusyIndicator.showWhile(BusyIndicator.java:65)
	at org.eclipse.ui.internal.WorkbenchWindow.setActivePage
(WorkbenchWindow.java:1242)
	at org.eclipse.ui.internal.WorkbenchWindow.restoreState
(WorkbenchWindow.java:1125)
	at org.eclipse.ui.internal.Workbench.restoreState(Workbench.java:1259)
	at org.eclipse.ui.internal.Workbench.access$7(Workbench.java:1228)
	at org.eclipse.ui.internal.Workbench$8.run(Workbench.java:852)
	at org.eclipse.core.internal.runtime.InternalPlatform.run
(InternalPlatform.java:843)
	at org.eclipse.core.runtime.Platform.run(Platform.java:413)
	at org.eclipse.ui.internal.Workbench.openPreviousWorkbenchState
(Workbench.java:804)
	at org.eclipse.ui.internal.Workbench.init(Workbench.java:604)
	at org.eclipse.ui.internal.Workbench.run(Workbench.java:1381)
	at org.eclipse.core.internal.boot.InternalBootLoader.run
(InternalBootLoader.java:840)
	at org.eclipse.core.boot.BootLoader.run(BootLoader.java:462)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke
(NativeMethodAccessorImpl.java:39)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke
(DelegatingMethodAccessorImpl.java:25)
	at java.lang.reflect.Method.invoke(Method.java:324)
	at org.eclipse.core.launcher.Main.basicRun(Main.java:247)
	at org.eclipse.core.launcher.Main.run(Main.java:703)
	at org.eclipse.core.launcher.Main.main(Main.java:539)
Comment 12 Adam Kiezun CLA 2002-12-09 08:26:39 EST
on PackageExplorer creation we call the label provider 2 for each element

here're the 2 traces
	at org.eclipse.jdt.ui.ProblemsLabelDecorator.getErrorTicksFromMarkers
(ProblemsLabelDecorator.java:199)
	at org.eclipse.jdt.ui.ProblemsLabelDecorator.computeAdornmentFlags
(ProblemsLabelDecorator.java:159)
	at org.eclipse.jdt.ui.ProblemsLabelDecorator.decorateImage
(ProblemsLabelDecorator.java:139)
	at org.eclipse.jdt.internal.ui.viewsupport.JavaUILabelProvider.getImage
(JavaUILabelProvider.java:108)
	at org.eclipse.jface.viewers.DecoratingLabelProvider.getImage
(DecoratingLabelProvider.java:67)
	at org.eclipse.jface.viewers.TreeViewer.doUpdateItem(TreeViewer.java:83)
	at org.eclipse.jface.viewers.AbstractTreeViewer.doUpdateItem
(AbstractTreeViewer.java:363)
	at org.eclipse.jface.viewers.StructuredViewer.updateItem
(StructuredViewer.java:1132)
	at org.eclipse.jface.viewers.AbstractTreeViewer.internalRefresh
(AbstractTreeViewer.java:843)
	at org.eclipse.jface.viewers.AbstractTreeViewer.internalRefresh
(AbstractTreeViewer.java:857)
	at org.eclipse.jface.viewers.AbstractTreeViewer.internalRefresh
(AbstractTreeViewer.java:857)
	at org.eclipse.jface.viewers.AbstractTreeViewer.internalRefresh
(AbstractTreeViewer.java:826)
	at org.eclipse.jface.viewers.StructuredViewer$4.run
(StructuredViewer.java:744)
	at org.eclipse.jface.viewers.StructuredViewer.preservingSelection
(StructuredViewer.java:684)
	at org.eclipse.jface.viewers.StructuredViewer.refresh
(StructuredViewer.java:742)
	at org.eclipse.jface.viewers.StructuredViewer.refresh
(StructuredViewer.java:704)
	at 
org.eclipse.jdt.internal.ui.packageview.PackageExplorerActionGroup.restoreState
(PackageExplorerActionGroup.java:193)

and 
	at org.eclipse.jdt.ui.ProblemsLabelDecorator.getErrorTicksFromMarkers
(ProblemsLabelDecorator.java:199)
	at org.eclipse.jdt.ui.ProblemsLabelDecorator.computeAdornmentFlags
(ProblemsLabelDecorator.java:159)
	at org.eclipse.jdt.ui.ProblemsLabelDecorator.decorateImage
(ProblemsLabelDecorator.java:139)
	at org.eclipse.jdt.internal.ui.viewsupport.JavaUILabelProvider.getImage
(JavaUILabelProvider.java:108)
	at org.eclipse.jface.viewers.DecoratingLabelProvider.getImage
(DecoratingLabelProvider.java:67)
	at org.eclipse.jface.viewers.TreeViewer.doUpdateItem(TreeViewer.java:83)
	at org.eclipse.jface.viewers.AbstractTreeViewer.doUpdateItem
(AbstractTreeViewer.java:363)
	at org.eclipse.jface.viewers.StructuredViewer.updateItem
(StructuredViewer.java:1132)
	at org.eclipse.jface.viewers.AbstractTreeViewer.createTreeItem
(AbstractTreeViewer.java:267)
	at org.eclipse.jface.viewers.AbstractTreeViewer.createChildren
(AbstractTreeViewer.java:252)
	at org.eclipse.jface.viewers.AbstractTreeViewer.internalSetExpanded
(AbstractTreeViewer.java:915)
	at org.eclipse.jface.viewers.AbstractTreeViewer.setExpandedElements
(AbstractTreeViewer.java:1106)
	at 
org.eclipse.jdt.internal.ui.packageview.PackageExplorerPart.restoreExpansionStat
e(PackageExplorerPart.java:815)
Comment 13 Adam Kiezun CLA 2002-12-09 11:09:16 EST
The second label decoration (Viewer.refresh()) can be avoided if we change the 
initialization of the Package Explorer Part in the following way:

- first install all filters and sorters, by restoring the corresponding state
- set the input
- then restore selection and expansion state.

Currently some of the filters are restored after the input has been set, hence 
the refresh is needed.
Comment 14 Adam Kiezun CLA 2002-12-09 12:39:30 EST
We have to check the Java Browsing Perspective as well. 
Comment 15 Dirk Baeumer CLA 2002-12-10 05:47:29 EST
I fixed the package explorer part so that findMarkers is only called once per 
visible element. Checked Java Browsing Perspective and the code already set the 
input after installing all filters and sorters.

Regarding comment 4: IMO the caching should be done by core not by us. As 
Martin pointed out JFace ask for the label for a single element and we don't 
know if it will ask for a children as well. Putting the cache into the UI 
forces every implementor of a label provide dealing with error ticks to 
populate its own cache.

John, is core planning anything in this direction. What's about Martin's 
suoggestion of having an iterator?
Comment 16 John Arthorne CLA 2002-12-10 10:54:01 EST
Instead of an iterator, you seem to need a method:

boolean IResource#containsMarkers(String type, boolean includeSubTypes, int depth);

In other words, a short-circuit search that halts when it finds the first match.
 However, this doesn't improve the (common) worst case where there are no
markers at all in the sub-tree.  This would still require an exhaustive search.
 We are investigating the creation of a "fast visitor" that could walk the
resource tree very quickly, and would be able to short-circuit.

I don't think a cache would be very helpful either.  You might expand the
children much later than when the parent was expanded.  What you need is a quick
answer to the question, "Does my parent in the tree have an error tick?"  If
true, I need to call findMarkers on the children, if false, I don't.  This seems
to be a general problem with label providers, we had this same problem when
doing the CVS "is dirty" decoration.  Putting decoration in a thread to hide the
slow algorithm is really a work-around for this.

Let's see what the behaviour is like with a faster tree traversal, and it could
potentially be revisited after 2.1.
Comment 17 Martin Aeschlimann CLA 2002-12-10 11:48:31 EST
It's more than
IResource#containsMarkers(String type, boolean includeSubTypes, int depth)
The markers must be of type 'Problem' and I want to know what the maximum 
severity was (non, warning or problem).

Core could only help here by offering a method exactly for out needs.
For the cache discussion, I think a cache should be on our side, containing the 
result (non/warning/error) for a resource. If the cache would be on the core 
side, they would have to cache the arrays of markers for requests, but I guess 
this is quite expensive.

I've experimented with bringing the Java problem markers to the threaded 
implementation offered by the desktop. It works, but there are still some 
issues to discuss. 
Comment 18 Adam Kiezun CLA 2002-12-10 13:25:23 EST
let's put it back to inbox - many people are involved here
Comment 19 Adam Kiezun CLA 2002-12-11 08:27:14 EST
see bug 28082, bug 28083, bug 28085
Comment 20 Adam Kiezun CLA 2002-12-11 08:43:38 EST
see bug 28086 for a rather extreme case
Comment 21 Adam Kiezun CLA 2002-12-11 09:06:35 EST
for the explanation of the number of times findMarkers is called on save (build)
see bug 28087
Comment 22 Erich Gamma CLA 2003-01-10 12:14:12 EST
Cannot do anything in JDT UI without further support from platform-core.

Please dispose if no action planned by platform-core.
Comment 23 DJ Houghton CLA 2003-01-23 15:05:17 EST
Faster tree traversal as well as faster marker finding has been implemented and
released.
No action planned for this right now.
Deferring. Re-visit post 2.1.
Comment 24 John Arthorne CLA 2005-01-06 11:53:59 EST
Reopening to change resolution.
Comment 25 John Arthorne CLA 2005-01-06 11:54:20 EST
No further changes planned.