Community
Participate
Working Groups
For our test case (create a project which has about 4,000 files, when 50 NavigatorContentDescriptor exist), org.eclipse.jdt.ui.ProblemsLabelDecorator.fireProblemsChanged() method takes only 62 msec for previors version, but now (3.2.1) it takes over 10,000 msec. Most of time is consumed in org.eclipse.ui.internal.navigator.NavigatorContentDescriptorManager.findDescriptorsForPossibleChild() method. I think at least org.eclipse.ui.internal.navigator.extensions.NavigatorContentDescriptor.isPossibleChild() method should be optimized(This method takes about 6,000 msec). This method is called for the same kind of instance (e.g "a.gif" file and "b.gif" file), and it always evaluates its expressions. (I also noticed one of the descriptors has over 40 expressions to check. It checks all the expressions to just return false each time target it does not want to handle is passed.
Naomi, what are the consequences of this performance problem for the end user? Does it lead to slow label decoration only, or does it block the UI? Could you please provide more details, such as (for example) a screenshot of the profiler output showing call frequencies, and the call path from ProblemsLabelDecorator.fireProblemsChanged() to NavigatorContentDescriptor.isPossibleChild()?
Created attachment 48945 [details] fireProblemChanged() sampling capture (YourKit3)
Created attachment 48946 [details] fireProblemChanged tracing capture (YourKit3), aborted after 4 hours
(In reply to comment #1) > Naomi, what are the consequences of this performance problem for the end user? It blocks UI. The wizard does not disappear until this labeling is finished. > Does it lead to slow label decoration only, or does it block the UI? > Could you please provide more details, such as (for example) a screenshot of > the profiler output showing call frequencies, and the call path from > ProblemsLabelDecorator.fireProblemsChanged() to > NavigatorContentDescriptor.isPossibleChild()? I attatched two capture images, sampling and tracing. But the "tracing" is not complete one, because the process does not finished in 4 hours and eclipse seems hung up. So I captured and aborted. Expected invocation count for CommonViewer.update() is 4097, but the data includes only 2514 invocations. I will try again tomorrow, but I am not sure I can succeed.
I believe we need to investigate if there is a safe fix or a workaround (on our side or theirs) for this for 3.2.1.
The core issue here is the performance of the Eclipse Core Expressions framework. An evaluation context has to be created for every evaluation, and each object must be evaluated since (even though two objects may have the same time), they may evaluate differently against a core expression based on property testers. We do cache the evaluation once it's made though, at which point we refer to the cache afterwards.
Michael, I disagree that this is a core expression problem. If you look at the trace than creating the evalution context takes 1% of the overall time. Even Java expressions take time when you call them thousands of times (as you can see with VisibilityAssistant#isVisible which accounts for 15% of the time since it is call 120550 times). Caching wise the expression framework could only cache the result of an instanceof expression since its value is fixed over time. Caching this value might help in this particular problem since the instanceof expression accounts for 8% of the time. All other values can't be cache (like you can't cache the value of a global expression in Java). What wonders me a little bit is the huge number of times certain calls take place. If we test all files against all descriptors we end up with 200000 tests. If this is necessary the extension point should be structured in a way that a most qualifying test can be evaluated at the beginning (for example refactoring participants first test for a project nature before doing expensive property tests of instanceof test). Of even better that we have group of tests. For example for files we could define more static tests which depend on the file extension. For a Navigator I guess the content descriptor/provider is most of the time the same for all *.gif or all *.java files. If we have such tests than we only have to evaluate them once instead of for every instance. In addition we can turn the collections into arrays, however I guess that will only be a cosmetic change.
Naomi, the trace attached in #3 contains an EnablementExpression#evaluate node which takes 14% of the time. Can you provide a screenshot showing its children.
Dirk -- that's a good point. Caching in VisibilityAssistant.isVisible() should be viable, since the declarative bindings won't change over the life of the Eclipse session.
Created attachment 49054 [details] Adds caching to the declarative visibility bindings
(In reply to comment #10) This will shave off 15%, correct? I'm a probably a little naive here, but why is it not possible to cache the result of findDescriptorsForPossibleChild()?
For a TreeItem that has been realized, is there a chance that the set of descriptorsWithPossibleChild for the associated element changes over time?
findDescriptorsForPossibleChild() does cache its result (as does findDescriptorsForTriggerPoint). The set can change sometimes (like as extensions are turned on and off) or if the characteristics of the objects change (like adding or removing facets). For now, clients are required to clear the cache if something like that does take place though.
So in the YourKit trace, what we are seeing is that there is nothing in the cache? Could the cache be eagerly populated at the time the tree items are created (assuming that at item creation time, you know the set)?
Created attachment 49117 [details] EnablementExpression.evaluate() tracing (YourKit3)
org.eclipse.core.internal.resource.Workspace.run() method. There are 2 run() methods. The one which has 2 parameters is called 3 times from WTPWorkingCopyManager. The other is called over 60 times. (DataModelPausibleOperation calls it recursively.) org.eclipe.jdt.internal.ui.viewsupport.ProblemMarkerManager use resouce change event as trigger. When our project is created, 4097 IRosource change is sent. So all the resources are set as the target of LabelProviderChangeEvent.)
Naomi, the trace you attached in #15 is interesting as well. The enablement expression is called 5023 times which results in 111527 instance of expression calls. This means that we have ~20 instanceof checks per enablement expression and since they are inside of an or expression all of them expect for 5023 in the best case evaluate to false (which are quite a lot). Can you please attach your 40 XML content descriptors so that I can have a look at them. May be this helps to optimize some code.
(In reply to comment #17) > Can you please attach your 40 XML content descriptors so that I can have a look > at them. May be this helps to optimize some code. Sent plugin.xml to dirk_baeumer@ch.ibm.com via mail.
Naomi, I have looked at the pluin.xml files an you are doing indeed lots of instanceof checks. One idea to speed things up is to put those instanceof checks which are most likely to return true at the beginning. Since all the checks are in or expressions this could speed up things quite noticably. Additionally could you do instanceof checks on some commong types instead of checking concrete types? This could reduce the number of checks as well.
(In reply to comment #19) > Additionally could you do instanceof checks on some commong types instead of > checking concrete types? This could reduce the number of checks as well. I will ask the owner of that plugin.xml.
Moving to 3.3 and lowering the severity since we could not confirm that the common navigator is the culprit. Still, it does not seem right to make >100,000 calls as a result of an update where most of the elements are not realized in the tree.
Hi, I found this bug when searching for bugs with terms NavigatorContentDescriptorManager, I had to open one about the cache using TreeSets and after importing a large workspace/projects, this cache grew to 12mb, anyways please read about it in bug 156395
I have emailed Naomi and Dirk and it appears that the problem was resolved by re-structuring the enablement expressions in the client extension. Without further feedback to the contrary, I am going to close this bug as INVALID.
