Community
Participate
Working Groups
On startup the application model is constructed. Here Xpath expressions are processed with Apache JXPath. When looking into the startup process the method StringModelFragmentImpl#mergeXPath is prominent in the profiling results. When looking deeper it can be seen that java.beans.Introspector is used often. The default tries to find BeanInfo for all EMF application classes, either explicit (<Model>BeanInfo) or by a customizer class (<Model>Customizer). Set a breakpoint into Introspector#findCustomizerClass to see what's happening. After investigation I have found out that this can be shortcutted when a DynamicPropertyHandler is registered for all application classes before introspection starts. This will avoid the introspection since org.apache.commons.jxpath.JXPathIntrospector.getBeanInfo(Class) will directly find a bean info.
Created attachment 280294 [details] Profiler results & debugger screenshots
New Gerrit change created: https://git.eclipse.org/r/151236
Out of curiosity: What is the impact of this change?
I'm expecting faster startups, see profiling results. When I'm starting Eclipse or plugin tests and profile it the introspection is a relative prominent finding in the startup phase and consumes valuable time in the main thread. If we can help to shortcut this a bit then the startup time of Eclipse and plugin tests should benefit from it.
Created attachment 280330 [details] Profiler results Here is more evidence about the effect. The overall startup time is to a large degree consumed in E4Application#createE4Workbench. The attached profiling results show that the consumed time can be significantly influenced by the change. The results show the application startup without and with the change, both with Tracing and Sampling options on in YourKit. Execution time createE4Workbench without change | with change Tracing 86352 ms | 29889 ms Sampling#1 31362 ms | 5950 ms Sampling#2 32142 ms | 7579 ms
(In reply to Karsten Thoms from comment #5) > Here is more evidence about the effect. The overall startup time is to a > large degree consumed in E4Application#createE4Workbench. The attached > profiling results Sounds cool, but it is not default SDK startup? It starts way below 10 seconds on my machine without the patch.
This is simply my runtime workspace startup. Results are influenced by profiler overhead of course, so the real startup without profiling is faster. However, it should show that the bean introspection _is_ a factor.
(In reply to Karsten Thoms from comment #5) > Created attachment 280330 [details] > Profiler results > > Here is more evidence about the effect. The overall startup time is to a > large degree consumed in E4Application#createE4Workbench. The attached > profiling results show that the consumed time can be significantly > influenced by the change. The results show the application startup without > and with the change, both with Tracing and Sampling options on in YourKit. > > Execution time createE4Workbench > without change | with change > Tracing 86352 ms | 29889 ms > Sampling#1 31362 ms | 5950 ms > Sampling#2 32142 ms | 7579 ms Impressive!
Karsten, what does Equinox report as Total start time if you activate the tracing with this patch and without this patch? Required trace options can be found here: https://www.vogella.com/tutorials/EclipsePerformance/article.html#example-tracing-the-startup-time-of-plug-ins
"Measuring" starting the runtime workspace from my dev workspace until it shows the UI (Run As / ...) 23s -> 17s
Gerrit change https://git.eclipse.org/r/151236 was merged to [master]. Commit: http://git.eclipse.org/c/platform/eclipse.platform.ui.git/commit/?id=563449d6faecf3a8c3fcecffba461e253c7a4be5
I‘ll examine if it makes sense to defer the property handler registration to a background job.
Created attachment 280342 [details] Profiler results: getPropertyNames caching The result of getPropertyNames can be cached per EClass. The screenshot shows profiling results with tracing without and with caching.
New Gerrit change created: https://git.eclipse.org/r/151328
(In reply to Eclipse Genie from comment #11) > Gerrit change https://git.eclipse.org/r/151236 was merged to [master]. > Commit: > http://git.eclipse.org/c/platform/eclipse.platform.ui.git/commit/ > ?id=563449d6faecf3a8c3fcecffba461e253c7a4be5 This causes javadoc build errors: https://download.eclipse.org/eclipse/downloads/drops4/I20191018-1800/compilelogs/platform.doc.isv.javadoc.txt ../../../eclipse.platform.ui/bundles/org.eclipse.e4.ui.workbench/src/org/eclipse/e4/ui/internal/workbench/Activator.java:38: error: package org.apache.commons.jxpath does not exist import org.apache.commons.jxpath.JXPathIntrospector; ^ ../../../eclipse.platform.ui/bundles/org.eclipse.e4.ui.workbench/src/org/eclipse/e4/ui/internal/workbench/Activator.java:39: error: package org.eclipse.e4.emf.internal.xpath.helper does not exist import org.eclipse.e4.emf.internal.xpath.helper.EDynamicPropertyHandler; ^ 2 errors
(In reply to Eclipse Genie from comment #11) > Gerrit change https://git.eclipse.org/r/151236 was merged to [master]. > Commit: > http://git.eclipse.org/c/platform/eclipse.platform.ui.git/commit/ > ?id=563449d6faecf3a8c3fcecffba461e253c7a4be5 This also causes bug 552239, that creates silly errors in the log, like "Your application model still contains a deprecated WizardDialog instance. Please remove it to keep compatibility with future versions." BasicFactoryImpl.createDialog() line: 218 BasicFactoryImpl.create(EClass) line: 108 Activator.registerJXPathPropertyHandlers() line: 244 Activator.start(BundleContext) line: 127 The deprecated methods should be black listed or the silly errors removed.
Sounds like this change initializes all model elements independent of their usage. Can this be done only for the used elements (lazy)?
(In reply to Lars Vogel from comment #17) > Sounds like this change initializes all model elements independent of their > usage. Can this be done only for the used elements (lazy)? One option is to remove the internal model elements, opened Bug 552240 for that. Bug 531054 gave the potential users sufficient warnings.
Starting Eclipse with -debug and the following.options file org.eclipse.core.runtime/perf=true # turn on debugging for the org.eclipse.core plugin. org.eclipse.osgi/debug=true # turn on execution time of the activator for the plug-ins #org.eclipse.osgi/debug/bundleTime=true # turn on total execution time of the plug-ins #org.eclipse.osgi/debug/bundleStartTime=true I used: Eclipse SDK Version: 2019-12 (4.14) Build id: I20191019-1800 OS: Linux, v.5.0.0-31-generic, x86_64 / gtk 3.24.8 Java version: 12.0.1 Results in a startup time for the pure SDK in version: Time to load bundles: 4 Starting application: 1083 Application started in : 5065ms Awesome. We only need to squeeze out 65 ms more to fulfill my personal goal of less than 5 seconds for startup of the SDK. :-)
(In reply to Lars Vogel from comment #19) > Time to load bundles: 4 > Starting application: 1083 > Application started in : 5065ms How do these 5.065 ms compare to the startup of the SDK without this patch?
(In reply to Sebastian Zarnekow from comment #20) > (In reply to Lars Vogel from comment #19) > How do these 5.065 ms compare to the startup of the SDK without this patch? See Bug 550136 for status updates on startup performance. Once this Bug has been fixed (error message resolved) I will update Bug 550136 using the same setup). See https://www.vogella.com/tutorials/EclipsePerformance/article.html#example-tracing-the-startup-time-of-plug-ins how you can measure the startup performance yourself.
Gerrit change https://git.eclipse.org/r/151328 was merged to [master]. Commit: http://git.eclipse.org/c/platform/eclipse.platform.ui.git/commit/?id=23b975ceaacfa0739472788320458ebba4e129d1
New Gerrit change created: https://git.eclipse.org/r/151508
*** Bug 552250 has been marked as a duplicate of this bug. ***
Gerrit change https://git.eclipse.org/r/151508 was merged to [master]. Commit: http://git.eclipse.org/c/platform/eclipse.platform.common.git/commit/?id=e3adff6d3c1992010061d65fb2644281e87f02ac
(In reply to Eclipse Genie from comment #11) > Gerrit change https://git.eclipse.org/r/151236 was merged to [master]. > Commit: > http://git.eclipse.org/c/platform/eclipse.platform.ui.git/commit/ > ?id=563449d6faecf3a8c3fcecffba461e253c7a4be5 This causes severe (if not a blocker) bug 552372. We see here that we must put the code to load the classes (https://git.eclipse.org/r/#/c/151236/8/bundles/org.eclipse.e4.ui.workbench/src/org/eclipse/e4/ui/internal/workbench/Activator.java@127) out of activator sequence, AFTER IDEApplication defined workspace location in IDEApplication.checkInstanceLocation() call. However, even this approach will cause activation of 3rd party bundles (with all their dependencies) on UI thread, that is already very bad idea, so IF we should do the optimization in registerJXPathPropertyHandlers(), it *MUST* be done in a job to avoid deadlocks during bundle activation on UI thread. However, doing this in a non-UI job can lead to problem with UI bundles activated in a non-UI thread. In short, we should revert https://git.eclipse.org/r/151236 patch and consider a different solution for the performance optimization. Here is the stack from bug 552372, that says that we are trying init resources bundle (and init workspace) *BEFORE* user selected workspace location. Root exception: java.lang.IllegalStateException: The instance data location has not been specified yet. at org.eclipse.core.internal.runtime.DataArea.assertLocationInitialized(DataArea.java:59) at org.eclipse.core.internal.runtime.DataArea.getStateLocation(DataArea.java:136) at org.eclipse.core.internal.runtime.InternalPlatform.getStateLocation(InternalPlatform.java:491) at org.eclipse.core.runtime.Plugin.getStateLocation(Plugin.java:259) at org.eclipse.core.internal.resources.LocalMetaArea.<init>(LocalMetaArea.java:63) at org.eclipse.core.resources.ResourcesPlugin.start(ResourcesPlugin.java:481) at org.eclipse.osgi.internal.framework.BundleContextImpl$3.run(BundleContextImpl.java:842) at org.eclipse.osgi.internal.framework.BundleContextImpl$3.run(BundleContextImpl.java:1) at java.security.AccessController.doPrivileged(Native Method) at org.eclipse.osgi.internal.framework.BundleContextImpl.startActivator(BundleContextImpl.java:834) at org.eclipse.osgi.internal.framework.BundleContextImpl.start(BundleContextImpl.java:791) at org.eclipse.osgi.internal.framework.EquinoxBundle.startWorker0(EquinoxBundle.java:1015) at org.eclipse.osgi.internal.framework.EquinoxBundle$EquinoxModule.startWorker(EquinoxBundle.java:365) at org.eclipse.osgi.container.Module.doStart(Module.java:603) at org.eclipse.osgi.container.Module.start(Module.java:467) at org.eclipse.osgi.framework.util.SecureAction.start(SecureAction.java:493) at org.eclipse.osgi.internal.hooks.EclipseLazyStarter.postFindLocalClass(EclipseLazyStarter.java:117) at org.eclipse.osgi.internal.loader.classpath.ClasspathManager.findLocalClass(ClasspathManager.java:571) at org.eclipse.osgi.internal.loader.ModuleClassLoader.findLocalClass(ModuleClassLoader.java:346) at org.eclipse.osgi.internal.loader.BundleLoader.findLocalClass(BundleLoader.java:398) at org.eclipse.osgi.internal.loader.sources.SingleSourcePackage.loadClass(SingleSourcePackage.java:41) at org.eclipse.osgi.internal.loader.BundleLoader.findClassInternal(BundleLoader.java:472) at org.eclipse.osgi.internal.loader.BundleLoader.findClass(BundleLoader.java:425) at org.eclipse.osgi.internal.loader.BundleLoader.findClass(BundleLoader.java:417) at org.eclipse.osgi.internal.loader.ModuleClassLoader.loadClass(ModuleClassLoader.java:171) at java.lang.ClassLoader.loadClass(ClassLoader.java:351) at org.eclipse.emf.ecore.plugin.EcorePlugin.getWorkspaceRoot(EcorePlugin.java:1149) at org.eclipse.emf.ecore.resource.impl.ExtensibleURIConverterImpl.<clinit>(ExtensibleURIConverterImpl.java:393) at org.eclipse.emf.ecore.resource.URIConverter.<clinit>(URIConverter.java:739) at org.eclipse.emf.ecore.plugin.URIMappingRegistryReader.readElement(URIMappingRegistryReader.java:72) at org.eclipse.emf.ecore.plugin.RegistryReader.internalReadElement(RegistryReader.java:130) at org.eclipse.emf.ecore.plugin.RegistryReader.readRegistry(RegistryReader.java:91) at org.eclipse.emf.ecore.plugin.EcorePlugin$ExtensionProcessor.internalProcessExtensions(EcorePlugin.java:922) at org.eclipse.emf.ecore.plugin.EcorePlugin$ExtensionProcessor.access$0(EcorePlugin.java:866) at org.eclipse.emf.ecore.plugin.EcorePlugin$Implementation.start(EcorePlugin.java:676) at org.eclipse.emf.common.EMFPlugin$OSGiDelegatingBundleActivator.start(EMFPlugin.java:202) at org.eclipse.osgi.internal.framework.BundleContextImpl$3.run(BundleContextImpl.java:842) at org.eclipse.osgi.internal.framework.BundleContextImpl$3.run(BundleContextImpl.java:1) at java.security.AccessController.doPrivileged(Native Method) at org.eclipse.osgi.internal.framework.BundleContextImpl.startActivator(BundleContextImpl.java:834) at org.eclipse.osgi.internal.framework.BundleContextImpl.start(BundleContextImpl.java:791) at org.eclipse.osgi.internal.framework.EquinoxBundle.startWorker0(EquinoxBundle.java:1015) at org.eclipse.osgi.internal.framework.EquinoxBundle$EquinoxModule.startWorker(EquinoxBundle.java:365) at org.eclipse.osgi.container.Module.doStart(Module.java:603) at org.eclipse.osgi.container.Module.start(Module.java:467) at org.eclipse.osgi.framework.util.SecureAction.start(SecureAction.java:493) at org.eclipse.osgi.internal.hooks.EclipseLazyStarter.postFindLocalClass(EclipseLazyStarter.java:117) at org.eclipse.osgi.internal.loader.classpath.ClasspathManager.findLocalClass(ClasspathManager.java:571) at org.eclipse.osgi.internal.loader.ModuleClassLoader.findLocalClass(ModuleClassLoader.java:346) at org.eclipse.osgi.internal.loader.BundleLoader.findLocalClass(BundleLoader.java:398) at org.eclipse.osgi.internal.loader.sources.SingleSourcePackage.loadClass(SingleSourcePackage.java:41) at org.eclipse.osgi.internal.loader.BundleLoader.findClassInternal(BundleLoader.java:472) at org.eclipse.osgi.internal.loader.BundleLoader.findClass(BundleLoader.java:425) at org.eclipse.osgi.internal.loader.BundleLoader.findClass(BundleLoader.java:417) at org.eclipse.osgi.internal.loader.ModuleClassLoader.loadClass(ModuleClassLoader.java:171) at java.lang.ClassLoader.loadClass(ClassLoader.java:351) at org.eclipse.e4.ui.internal.workbench.Activator.registerJXPathPropertyHandlers(Activator.java:226) at org.eclipse.e4.ui.internal.workbench.Activator.start(Activator.java:127) at org.eclipse.osgi.internal.framework.BundleContextImpl$3.run(BundleContextImpl.java:842) at org.eclipse.osgi.internal.framework.BundleContextImpl$3.run(BundleContextImpl.java:1) at java.security.AccessController.doPrivileged(Native Method) at org.eclipse.osgi.internal.framework.BundleContextImpl.startActivator(BundleContextImpl.java:834) at org.eclipse.osgi.internal.framework.BundleContextImpl.start(BundleContextImpl.java:791) at org.eclipse.osgi.internal.framework.EquinoxBundle.startWorker0(EquinoxBundle.java:1015) at org.eclipse.osgi.internal.framework.EquinoxBundle$EquinoxModule.startWorker(EquinoxBundle.java:365) at org.eclipse.osgi.container.Module.doStart(Module.java:603) at org.eclipse.osgi.container.Module.start(Module.java:467) at org.eclipse.osgi.framework.util.SecureAction.start(SecureAction.java:493) at org.eclipse.osgi.internal.hooks.EclipseLazyStarter.postFindLocalClass(EclipseLazyStarter.java:117) at org.eclipse.osgi.internal.loader.classpath.ClasspathManager.findLocalClass(ClasspathManager.java:571) at org.eclipse.osgi.internal.loader.ModuleClassLoader.findLocalClass(ModuleClassLoader.java:346) at org.eclipse.osgi.internal.loader.BundleLoader.findLocalClass(BundleLoader.java:398) at org.eclipse.osgi.internal.loader.BundleLoader.findClassInternal(BundleLoader.java:476) at org.eclipse.osgi.internal.loader.BundleLoader.findClass(BundleLoader.java:425) at org.eclipse.osgi.internal.loader.BundleLoader.findClass(BundleLoader.java:417) at org.eclipse.osgi.internal.loader.ModuleClassLoader.loadClass(ModuleClassLoader.java:171) at java.lang.ClassLoader.loadClass(ClassLoader.java:351) at org.eclipse.ui.PlatformUI.createDisplay(PlatformUI.java:162) at org.eclipse.ui.internal.ide.application.IDEApplication.createDisplay(IDEApplication.java:180) at org.eclipse.ui.internal.ide.application.IDEApplication.start(IDEApplication.java:123)
Too bad. Thanks for the analysis, Andrey, and for reverting. I'll dig again into it and think about if we can do something.
Please retarget if you still plan to fix this for 4.14.
Remove target milestone.
