Bugzilla – Full Text Bug Listing
|
Description
Stefan Mücke
Created attachment 173231 [details]
Screenshot showing the hotspots
Created attachment 173232 [details]
Screenshot showing the backtraces from the hottest hotspot
Created attachment 173233 [details]
Screenshot showing the stack trace from the setFocus methods
Created attachment 173242 [details]
New analysis: Overview screenshot
Here is a new analysis with all the necessary invocation counts. This should suffice to identify the underlying problem.
Created attachment 173243 [details]
New analysis: Detail screenshot
Created attachment 173252 [details]
New analysis: Another detail screenshot
This screenshot shows that the time is actually consumed by the invocations of Method.getParameterAnnotations(). Would it be possible to cache the result of this computation? The annotations cannot change at runtime.
Created attachment 173254 [details]
New analysis: Another detail screenshot (2)
The execution of PartRendingEngine$5.setId(...) has the same problem as
PartRendingEngine$5.setClassname(...) from the previous screenshot, that is, most of the time is consumed by Method.getParameterAnnotations().
Cool, thank you very much for your help! Created attachment 173307 [details]
patch
Patch committed to HEAD. Stefan, feel free to help us some more.. ;-) at this point, we're extremely busy trying to fix bugs and fill holes, and we don't have enough time to do profiling in detail. Of course, we are always able to make point fixes for already identified performance problems. *** Bug 318708 has been marked as a duplicate of this bug. *** Created attachment 173324 [details]
Profiling results after patch
The patch was a great improvement. Delay is now ~1 second or slightly below. However, the delay is still annoying. See screenshot for another analysis after the patch.
BTW, is there some other area where I could do some profiling? What about start-up performance?
(In reply to comment #12) > BTW, is there some other area where I could do some profiling? What about > start-up performance? Yes, that would be interesting. Otherwise, anything that causes a noticeable delay (>200ms) is a candidate for profiling. For example: opening an editor, opening a view, ... Any time you see high invocation counts, it would be interesting to know if those counts are due to a large number of different instances on which we call a method, or if we call a method on a single instance many times, or if it's a combination of the two. Any time we call the same method on the same instance multiple times, we have an opportunity to optimize. :-) About "number of tool items to update?" - could it be that you had the profiler running for a couple of seconds? The runnable you are seeing here is scheduled every 500ms for every tool item - it looks like we're spending 10ms on every update (which feels like it is too much still), but the invocation count of 216 depends on how long you had the profiler active, and any time spent in the runnable is not going to affect the time it takes to switch between editors. I did the profiling with tracing enabled. This considerably slows down the program execution, so that there might have been indeed several tool item updates. The times shown on the screenshot are those during profiling. Thus, the 10 ms will be much less in real time. The total time of the profile session is indicated as ~5000 ms. This is the running time during profiling. However, the only thing I did is the focus change, which in real time takes about a second. Accordingly, the slow down with full tracing enabled is about factor 5. But, during 5000 ms there should have been only 10 updates, not 216. One per tool item. If it was 10 times 21 tool items that would be believable. Yes, I just discovered that each ToolItem has its own updater. Currently, I am back on the old analysis. I have found the root of a large part of the performance problems. Everything comes down to InjectorImpl.resolveArgs(...). This method is called in several places, and it is extremely expensive. As far as I can tell, it also has a considerable impact on the start-up performance. Perhaps we can apply the same trick with caching here. However, I will have to do some more investigation. I am not familiar with the e4 internal workings. Created attachment 173353 [details]
Proposed patch
I found out that Requestor instances have a weak reference to the requesting object. I often encountered a null value. When this is the case, a requestor will immediately return when execute() is called. Regardless of that, however, the ContextObjectSupplier will always call resolveArguments() before. Since this method is quite expensive, I suggest to add an if-statement around this:
if (requestor.getRequestingObject() != null) {
requestor.resolveArguments();
}
Perhaps "requestor.execute()" should also be inside the if-block.
Created attachment 173354 [details]
patch so that we only style once
Stefan, does this patch speed up things measurably?
Yes, definitely! I don't even need to take the profiler. You can just see how the rendering speed is improved. Before to this patch you could see how the part stack and the toolbar received their active background color one after the other. Now you cannot notice the white background of the toolbar while the stack's bar background is redrawn. However, there is still some drawing "effect" where the toolbar is located. Currently I am investigating why there are so many listeners installed in the context. All these listeners are invalidated when the context is changed. Next, I want to find out if there are duplicates, or whar kind of listeners are installed. Well, most of them seem to be handlers. I could provide another screenshot showing the invalidate cost. Created attachment 173356 [details]
Profiler screenshot before the last patch
(In reply to comment #21) > Currently I am investigating why there are so many listeners installed in the > context. All these listeners are invalidated when the context is changed. Next, > I want to find out if there are duplicates, or whar kind of listeners are > installed. Well, most of them seem to be handlers. I've been looking at this, too. I need to talk to Paul, we should really be more lazy with those handler activations. Ideally, we'd be converting the RunAndTrack subclass HandlerActivation into something that uses IContextFunction. Stefan, if you can find places where we can shave off a few percent or two that's great. But maybe your time would be better spent helping elsewhere? For example, I think we still have a memory leak problem - I have been running out of (heap) memory after a while. YourKit should help with memory leaks as well... :-) Okay, I could try to find something. But where should I start? Do you have any idea in which area you are leaking memory or when this happens? As regards the context listeners, are you interested in a list of what I found to be registered in the context? My list is 718 lines long :-), sorted alphabetically. (In reply to comment #25) > As regards the context listeners, are you interested in a list of what I found > to be registered in the context? My list is 718 lines long :-), sorted > alphabetically. Sure, that can't hurt, maybe as an attachment? It would be interesting to know if the list grows over time. As for the memory leak, I don't have anything in mind specifically. The obvious candidates are: Do we leak memory every time an editor is opened? Every time a view is opened? Every time we switch between editors, or between the active editor and a view? Every time we switch perspectives? Every time we open a dialog? To find a leak in any of the scenarios listed, you would repeat the operation multiple times, then take a heap snapshot, then repeat some more times (it helps to pick a fixed number of repetitions, e.g. 10, which will make it easy to differentiate between actual leaks and false positives), and then take a second snapshot which you compare to the first. I've committed the "patch so that we only style once" to HEAD. Created attachment 173357 [details]
List of context listeners found when a part was activated
I have already found a leak. I will open a new bug as soon as I find out the details. (In reply to comment #29) > I have already found a leak. I will open a new bug as soon as I find out the > details. Awesome. Thank you for your help! Could you please add me to the cc list of new bugs you file? (In reply to comment #19) > Created an attachment (id=173353) [details] > Proposed patch > > I found out that Requestor instances have a weak reference to the requesting > object. I often encountered a null value. When this is the case, a requestor > will immediately return when execute() is called. Regardless of that, however, > the ContextObjectSupplier will always call resolveArguments() before. I investigated this but couldn't find instances that return null from Requestor.getRequestingObject() while switching between views and/or editors. I could reproduce this with the following code and a breakpoint on the println (you could also use a conditional breakpoint). This happened on part activation.
public Object getRequestingObject() {
if (objectRef == null)
return null;
Object object = objectRef.get();
if (object == null) {
System.out.println("Oops. Here's a null value.");
}
return object;
}
Created attachment 173379 [details]
Patch for caching the result of isOverridden(...)
The computation of isOverridden(...) is quite expensive, because it invokes Class.getDeclaredMethod(String, ...) on several classes.
This patch has been tested and works well. However, I inserted one TODO in the code where it wasn't 100% sure if caching is always possible. But, as I see it, the provided class-hierarchy parameter list should always contain the same elements, i.e., the class hierarchy should never change at runtime.
(In reply to comment #33) > This patch has been tested and works well. However, I inserted one TODO in the > code where it wasn't 100% sure if caching is always possible. But, as I see it, > the provided class-hierarchy parameter list should always contain the same > elements, i.e., the class hierarchy should never change at runtime. I don't think that the class hierarchy can change over time for any given Method object. The patch looks good to me but should be reviewed by another committer. Oleg, can you have a look? The change to IStylingEngine broke the compat.tool and ui.designer! (In reply to comment #35) > The change to IStylingEngine broke the compat.tool and ui.designer! Sorry about this, have you fixed it already? yep - paul fixed it To look at isOverridden patch. PW (In reply to comment #23) > We should really be > more lazy with those handler activations. Ideally, we'd be converting the > RunAndTrack subclass HandlerActivation into something that uses > IContextFunction. I have done this, and if the fix holds, it could be huge. I've entered a new one for the changes, see bug 318930. Created attachment 173465 [details]
Patch O2
Nice work!
I'll update the code a bit:
- MethodRequestor: use WeakHashMap, no need to synch the code
- All Requestor classes: the results of #getDependentObjects() really never change for a given requestor, so we can cache them after the first request
- InjectorImpl#resolveArgs(): changed code to reuse the same result array relying on IInjector.NOT_A_VALUE rather then modifying descriptor arrays. Which surprisingly cleaned up that methor quite nicely.
(Patch O2 applied to CVS Head.)
Created attachment 173468 [details]
Patch O3 - modified "Proposed patch"
Updated version of the Stefan's "Proposed patch": use requestor.isValid() and remove the listener once the requestor becomes invalid due to the injected object being GCed.
(Patch O3 applied to CVS Head.) Stefan, would you be able to profile again, using the latest from CVS HEAD? Note that the fix for bug 318930 should make a big difference. I have just fetched the lastest from CVS HEAD. However, my e4 crashed on startup because setParentID was changed to setParentId(). There seems to be some compatibility code in the org.eclipse.ui.workbench plugin. This is a binary plugin in my workbench. I then fetched this plugin from CVS, but now I get a 3.6 workbench. It seems to me that must exist a branched org.eclipse.ui.workbench somewhere. If so, can you point me to the right place? /cvsroot/eclipse/e4/org.eclipse.e4.compatibility/bundles/org.eclipse.ui.workbench Thank you. e4 starts again. But, there was a compile error in the LegacyHandlerService. In the following line:
return parent.get(HandlerServiceImpl.H_ID + commandId);
the compiler tells me "The field HandlerServiceImpl.H_ID is not visible". After changing the field to public, the e4 workbench comes up.
I just wanted to open a Console view, but something is broken:
!ENTRY org.eclipse.e4.ui.workbench 4 0 2010-07-05 21:37:05.583
!MESSAGE Internal Error
!STACK 0
org.eclipse.e4.core.di.InjectionException: java.lang.NullPointerException
at org.eclipse.e4.core.internal.di.MethodRequestor.execute(MethodRequestor.java:54)
at org.eclipse.e4.core.internal.di.InjectorImpl.invokeUsingClass(InjectorImpl.java:196)
at org.eclipse.e4.core.internal.di.InjectorImpl.invoke(InjectorImpl.java:173)
at org.eclipse.e4.core.contexts.ContextInjectionFactory.invoke(ContextInjectionFactory.java:101)
at org.eclipse.e4.core.commands.internal.HandlerServiceImpl.executeHandler(HandlerServiceImpl.java:109)
at org.eclipse.ui.internal.handlers.LegacyHandlerService.executeCommand(LegacyHandlerService.java:362)
at org.eclipse.ui.menus.CommandContributionItem.handleWidgetSelection(CommandContributionItem.java:820)
at org.eclipse.ui.menus.CommandContributionItem.access$19(CommandContributionItem.java:806)
at org.eclipse.ui.menus.CommandContributionItem$5.handleEvent(CommandContributionItem.java:796)
at org.eclipse.swt.widgets.EventTable.sendEvent(EventTable.java:84)
at org.eclipse.swt.widgets.Widget.sendEvent(Widget.java:1053)
at org.eclipse.swt.widgets.Display.runDeferredEvents(Display.java:4066)
at org.eclipse.swt.widgets.Display.readAndDispatch(Display.java:3657)
at org.eclipse.e4.ui.internal.workbench.swt.PartRenderingEngine$4.run(PartRenderingEngine.java:664)
at org.eclipse.core.databinding.observable.Realm.runWithDefault(Realm.java:332)
at org.eclipse.e4.ui.internal.workbench.swt.PartRenderingEngine.run(PartRenderingEngine.java:589)
at org.eclipse.e4.ui.internal.workbench.E4Workbench.createAndRunUI(E4Workbench.java:103)
at org.eclipse.ui.internal.Workbench$3.run(Workbench.java:535)
at org.eclipse.core.databinding.observable.Realm.runWithDefault(Realm.java:332)
at org.eclipse.ui.internal.Workbench.createAndRunWorkbench(Workbench.java:519)
at org.eclipse.ui.PlatformUI.createAndRunWorkbench(PlatformUI.java:149)
at org.eclipse.ui.internal.ide.application.IDEApplication.start(IDEApplication.java:115)
at org.eclipse.equinox.internal.app.EclipseAppHandle.run(EclipseAppHandle.java:196)
at org.eclipse.core.runtime.internal.adaptor.EclipseAppLauncher.runApplication(EclipseAppLauncher.java:110)
at org.eclipse.core.runtime.internal.adaptor.EclipseAppLauncher.start(EclipseAppLauncher.java:79)
at org.eclipse.core.runtime.adaptor.EclipseStarter.run(EclipseStarter.java:369)
at org.eclipse.core.runtime.adaptor.EclipseStarter.run(EclipseStarter.java:179)
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:597)
at org.eclipse.equinox.launcher.Main.invokeFramework(Main.java:619)
at org.eclipse.equinox.launcher.Main.basicRun(Main.java:574)
at org.eclipse.equinox.launcher.Main.run(Main.java:1407)
at org.eclipse.equinox.launcher.Main.main(Main.java:1383)
Caused by: java.lang.NullPointerException
at org.eclipse.e4.core.commands.internal.HandlerServiceImpl.executeHandler(HandlerServiceImpl.java:96)
at org.eclipse.ui.handlers.ShowViewHandler.execute(ShowViewHandler.java:55)
at org.eclipse.ui.internal.handlers.HandlerProxy.execute(HandlerProxy.java:293)
at org.eclipse.ui.internal.handlers.E4HandlerProxy.execute(E4HandlerProxy.java:56)
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:597)
at org.eclipse.e4.core.internal.di.MethodRequestor.execute(MethodRequestor.java:47)
... 34 more
I was able to open the Console via the Quick Access in the toolbar. I will now profile part switching. (In reply to comment #46) > return parent.get(HandlerServiceImpl.H_ID + commandId); > > the compiler tells me "The field HandlerServiceImpl.H_ID is not visible". This change is in CVS so perhaps you don't have that project checked out. To get rid of the NPE, you could try starting with an empty workspace for your inner Eclipse. If that doesn't help, we could wait until tomorrow, we should have a new build by then. Created attachment 173475 [details]
Profiling results
The results look good.
One big factor is still the isOverridden method (my patch is not in CVS head). This method slows the UI down. On my system I already had a better responsiveness.
Well, I don't like my patch. Caching boolean values looks odd. Any ideas to refactor isOverridden into a faster implementation? (In reply to comment #33) > Created an attachment (id=173379) [details] > Patch for caching the result of isOverridden(...) > The computation of isOverridden(...) is quite expensive, because it invokes > Class.getDeclaredMethod(String, ...) on several classes. I suspect a large part of the expence comes from: try { subClass.getDeclaredMethod(...); ... } catch (NoSuchMethodException e) { continue; // this is the desired outcome } Creation and propagation of exceptions slows things down. Too bad there is no good way to get a method using name & arg list. I did not want to write that but might as well do it now while we are on the subject. > This patch has been tested and works well. However, I inserted one TODO in the > code where it wasn't 100% sure if caching is always possible. But, as I see it, > the provided class-hierarchy parameter list should always contain the same > elements, i.e., the class hierarchy should never change at runtime. As you suspect, the class hierarchy (or, more precisely, the class of the injected object) plays its role. For instance, if you were to run core tests with this patch, they woudl fail as both Tire#injectProtectedMethodForOverride() and SpareTire#injectProtectedMethodForOverride() methods are checked in #isOverridden(). The Tire's method is checked first and is set in the cache, preventing the same method to be checked when we are starting with the SpareTire. (In reply to comment #50) > Well, I don't like my patch. Caching boolean values looks odd. Any ideas to > refactor isOverridden into a faster implementation? I'll attach a patch but I doubt that this method has significant effect with the current code (the time spend in this method = 31ms or ~1% of switching active editors). Created attachment 173476 [details]
Hotspot isOverridden
The percentage is much higher. The other ones didn't fit on my screen.
It is the hottest hotspot. And the second hotspot depends on isOverridden, too.
(In reply to comment #51) My patch should be changed to respect the class. For example: Map<Class<?>, MethodInfo[]> isOverriddenCache = new HashMap<Class<?>, MethodInfo[]>(); Created attachment 173478 [details]
Patch O4 - caching isOverridden()
This patch is based on the idea of caching results of #isOverriden() proposed by Stefan. I also changed the way we get the matching method to test - it is more code, but it does not play catch-and-throw exceptions which migh eventually be visible in the startup timing.
(Patch applied to CVS Head.)
Created attachment 173479 [details]
Profiling results after isOverridden cache
Congratulations! Editor/part switching is now fast.
See results. All serious hotspots have gone. The topmost one is now "sleep," that is, I couldn't click fast enough to produce enough CPU load :-).
Try the following again: - Minimize the Outline - Open and close the Outline from the trim as fast as you can :-) - Result: It's fast enough. Created attachment 173481 [details]
Profiling results
(In reply to comment #57) > - Result: It's fast enough. Woot! Very impressive results, thanks Stefan ond Boris! Nicely done. Verified in I20100707-2006. |