Community
Participate
Working Groups
Plan bug for improved performance similar to Bug 569285for the 4.20 release.
Eclipse SDK Version: 2021-03 (4.19) Build id: I20210226-0220 OS: Linux, v.5.4.0-66-generic, x86_64 / gtk 3.24.20 Java version: 15.0.2 Time 4x started with latest EGit (nightly) and Marketplace and hotspot JVM Application started in : 5118ms Application started in : 4887ms Application started in : 5170ms Application started in : 5113ms Time 4x started with latest EGit (nightly) and Marketplace and J9 JVM and modified eclipse.init (with -vmargs -Xshareclasses:name=eclipse) Application started in : 3763ms Application started in : 3803ms Application started in : 3636ms Application started in : 3353ms
Activator times as measured via OSGI logging with j9 JVM: Activator times 341 org.eclipse.jdt.ui_3.22.100.v20210224-0730 263 org.eclipse.egit.core_5.11.0.202102240823 224 org.eclipse.jdt.core_3.25.0.v20210223-0522 80 org.eclipse.core.resources_3.14.0.v20210215-0934 50 org.eclipse.egit.ui_5.11.0.202102240823 48 org.eclipse.osgi_3.16.200.v20210212-1137 40 org.eclipse.emf.common_2.22.0.v20210114-1734 39 org.eclipse.ui.workbench_3.122.100.v20210215-1525 38 org.eclipse.team.core_3.8.1100.v20200806-0621 33 org.eclipse.ui.trace_1.2.0.v20210110-1242 32 org.eclipse.e4.ui.workbench_1.12.100.v20210122-1731 31 org.eclipse.core.runtime_3.20.100.v20210111-0815 28 org.eclipse.equinox.console_1.4.300.v20210211-2058 27 org.eclipse.equinox.registry_3.10.100.v20210212-1143 27 org.eclipse.equinox.app_1.5.100.v20210212-1143 26 org.eclipse.equinox.simpleconfigurator_1.3.600.v20200721-1308 26 org.eclipse.core.net_1.3.1000.v20200715-0827 22 org.eclipse.equinox.common_3.14.100.v20210212-1143 21 org.apache.felix.scr_2.1.24.v20200924-1939 12 org.eclipse.equinox.preferences_3.8.200.v20210212-1143 12 org.eclipse.emf.ecore_2.23.0.v20200630-0516 11 org.eclipse.update.configurator_3.4.700.v20200907-1237 11 org.eclipse.equinox.p2.reconciler.dropins_1.3.500.v20210116-1855 9 org.eclipse.core.jobs_3.10.1100.v20210111-0815 9 org.apache.felix.gogo.runtime_1.1.4.v20210111-1007 4 org.eclipse.team.ui_3.8.1200.v20210204-1156 4 org.eclipse.equinox.p2.core_2.6.300.v20200211-1504 4 org.apache.felix.gogo.shell_1.1.4.v20210111-1007 4 org.apache.felix.gogo.command_1.1.2.v20210111-1007 3 org.eclipse.ui.navigator_3.10.0.v20210111-1352 3 org.eclipse.jsch.core_1.3.900.v20200422-1935 2 org.eclipse.ui.workbench.texteditor_3.16.0.v20210120-0733 2 org.eclipse.equinox.p2.ui.sdk.scheduler_1.5.0.v20201012-1421 1 org.eclipse.ui.ide_3.18.100.v20210122-1536 1 org.eclipse.ui.editors_3.14.0.v20210215-0846 1 org.eclipse.ui_3.119.0.v20210111-1350 1 org.eclipse.equinox.security_1.3.600.v20210126-1005 1 org.eclipse.emf.ecore.xmi_2.16.0.v20190528-0725 1 org.eclipse.e4.ui.workbench.swt_0.16.0.v20201230-1610 0 org.eclipse.ui.navigator.resources_3.8.0.v20210209-1136 0 org.eclipse.jdt.core.manipulation_1.14.300.v20210224-0730 0 org.eclipse.help_3.8.800.v20200525-0755 0 org.eclipse.e4.ui.css.swt_0.14.100.v20201217-1340
New activator times with the EGit core activator remorked to do less work in its activator: 306 org.eclipse.jdt.ui_3.22.200.v20210313-1129 190 org.eclipse.jdt.core_3.25.100.v20210308-2145 115 org.eclipse.core.resources_3.15.0.v20210311-1403 108 org.eclipse.core.net_1.3.1000.v20200715-0827 68 org.eclipse.ui.trace_1.2.0.v20210110-1242 68 org.eclipse.egit.ui_5.12.0.202103122349 66 org.eclipse.core.runtime_3.20.100.v20210111-0815 64 org.eclipse.ui.workbench_3.122.100.v20210215-1525 62 org.eclipse.emf.common_2.22.0.v20210114-1734 59 org.eclipse.equinox.app_1.5.100.v20210212-1143 56 org.eclipse.equinox.simpleconfigurator_1.3.600.v20200721-1308 54 org.eclipse.osgi_3.16.300.v20210308-1445 40 org.eclipse.equinox.console_1.4.300.v20210211-2058 38 org.eclipse.e4.ui.workbench_1.12.100.v20210122-1731 28 org.eclipse.egit.core_5.12.0.202103122349 27 org.eclipse.team.core_3.8.1200.v20210309-0858 23 org.eclipse.equinox.registry_3.10.100.v20210212-1143 20 org.eclipse.emf.ecore_2.23.0.v20200630-0516 20 org.apache.felix.scr_2.1.24.v20200924-1939 17 org.eclipse.update.configurator_3.4.700.v20200907-1237 16 org.eclipse.equinox.preferences_3.8.200.v20210212-1143 16 org.eclipse.equinox.common_3.14.100.v20210212-1143 16 org.apache.felix.gogo.runtime_1.1.4.v20210111-1007 13 org.eclipse.equinox.p2.reconciler.dropins_1.3.500.v20210116-1855 8 org.eclipse.core.jobs_3.10.1100.v20210111-0815 7 org.apache.felix.gogo.shell_1.1.4.v20210111-1007 6 org.eclipse.equinox.p2.core_2.6.300.v20200211-1504 5 org.eclipse.ui.navigator_3.10.0.v20210111-1352 5 org.eclipse.team.ui_3.8.1300.v20210310-1932 5 org.apache.felix.gogo.command_1.1.2.v20210111-1007 4 org.eclipse.equinox.security_1.3.600.v20210126-1005 3 org.eclipse.jsch.core_1.3.900.v20200422-1935 3 org.eclipse.equinox.p2.ui.sdk.scheduler_1.5.0.v20201012-1421 2 org.eclipse.ui.workbench.texteditor_3.16.0.v20210120-0733 2 org.eclipse.ui.editors_3.14.0.v20210215-0846 2 org.eclipse.ui_3.119.0.v20210111-1350 2 org.eclipse.e4.ui.workbench.swt_0.16.0.v20201230-1610 1 org.eclipse.ui.navigator.resources_3.8.0.v20210209-1136 1 org.eclipse.ui.ide_3.18.100.v20210122-1536 1 org.eclipse.help_3.8.800.v20200525-0755 1 org.eclipse.emf.ecore.xmi_2.16.0.v20190528-0725 0 org.eclipse.jdt.core.manipulation_1.14.400.v20210313-1129 0 org.eclipse.e4.ui.css.swt_0.14.100.v20201217-1340
As one can see this is just shuffling around the class-loading work. The sum is about the same (actually, a little bit higher even), but notably org.eclipse.core.net went up from 28 to >100. Presumably it now has to load things that previously got loaded and counted under egit.core? Or is this a statistical fluke? Are these numbers averaged over several runs?
(In reply to Thomas Wolf from comment #4) > Or is this a statistical fluke? Are these numbers averaged over several runs? I always recommend to take your own measurement as it is super easy to do. Create a .options file in your eclipse directory with the following content and start Eclipse with -debug and -data yourworkspace and you also get the numbers. See https://www.vogella.com/tutorials/EclipsePerformance/article.html#example-tracing-the-startup-time-of-plug-ins --- # 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 --- Commands to get the numbers extracted: # start Eclipse with at test workspace while piping the output into a file ./eclipse -debug -data ~/test > trace.txt # get total start time echo "Total startup time" > tracefinal.txt grep "for total start time" trace.txt | awk '{print $1 " " $13}' |sort -nr >> tracefinal.txt echo "" >> tracefinal.txt echo "Activator times" >> tracefinal.txt # extract the activation time grep "to load and start the activator" trace.txt |awk '{print $1 " " $10}'| sort -nr >> tracefinal.txt P.S. this is typically now the time in which someone writes how useless this measurements are......
(In reply to Lars Vogel from comment #5) > P.S. this is typically now the time in which someone writes how useless this > measurements are...... That someone didn't wanted to comment, but I couldn't resist if invited. To be taken seriously the numbers must be generated in automated way, using exact same environment (means also same Java/OS version/disc used), representing a median of 50-100 measures, etc. The numbers that are presented here are neither representative nor can be used to compare the state before/after release. They just show *something*. If the point is to show *something*, than it is absolutely OK. To make the numbers saying *at least* *something* useful, run same script 100 times, compute median and translate absolute times to relative (egit startup takes 5% overall startup time etc). Attach the script and ask others to compare. So one could see that an SSD or Windows or JVM used can made a huge difference (or not), 4.15 has higher egit load as 4.19 (or not) etc.
Thanks Andrey, lets not break the tradition to say the same things again and again. I usually now say: Feel free to do your own measurement. You usually reply to that you have no time nor care for that. :-)
Created attachment 285865 [details] User reaction to the startup time of 2021-03 User reaction to the startup time of 2021-03
Startup time into an empty workspace with latest OpenJ9 Java 16 release and shared classes setup as described in https://blog.openj9.org/2018/10/30/openj9-shared-classes-with-eclipse-equinox-4-9/ Eclipse SDK Version: 2021-06 (4.20) Build id: I20210316-1800 OS: Linux, v.5.4.0-67-generic, x86_64 / gtk 3.24.20 Java version: 16 Application started in : 2288ms Application started in : 2389ms Application started in : 2389ms Application started in : 2413ms Application started in : 2299ms
When the osgi classloading is taking serious time have you thought about prefetching all .jars that will be used during startup in parallel thread(s)? I mean you could just dummy-access any class in the jars to prefetch opening the .jar files and they will remain open due to the osgi cache.
(In reply to Jörg Kubitz from comment #10) > When the osgi classloading is taking serious time have you thought about > prefetching all .jars that will be used during startup in parallel thread(s)? > I mean you could just dummy-access any class in the jars to prefetch opening > the .jar files and they will remain open due to the osgi cache. Equinox has a flag to enable parallel bundle loading called equinox.start.level.thread.count. It is used in EquinoxContainerAdaptor#createLazyExecutorCreator but IIRC I never managed to enable it. If I add it as startup option it is ignored and if I add it to an RCP app as config parameter it is also ignored. @Tom (Watson), can you remind me how to enable parallel bundle loading?
VmArguments: -Dequinox.start.level.thread.count=-1
(In reply to Jörg Kubitz from comment #12) > VmArguments: > -Dequinox.start.level.thread.count=-1 That is correct. Any value <=0 indicates that you want to use Runtime.getRuntime().availableProcessors() as the number of threads to start bundles in parallel. If you want more or less threads then you have to specify the number of threads as a positive number. The default is 1.
I'm adding bug 572605 to the list. I expect small improvements to startup when it is fixed.
(In reply to Thomas Watson from comment #13) > (In reply to Jörg Kubitz from comment #12) > > VmArguments: > > -Dequinox.start.level.thread.count=-1 > > That is correct. Any value <=0 indicates that you want to use > Runtime.getRuntime().availableProcessors() as the number of threads to start > bundles in parallel. If you want more or less threads then you have to > specify the number of threads as a positive number. The default is 1. Thanks, Jörg and Thomas.
(In reply to Jörg Kubitz from comment #10) > When the osgi classloading is taking serious time have you thought about > prefetching all .jars that will be used during startup in parallel thread(s)? > I mean you could just dummy-access any class in the jars to prefetch opening > the .jar files and they will remain open due to the osgi cache. I have my doubts that opening the JAR files is the heavy hitter as far as class loading goes. In my experience it has been the IO to read the class bytes and the actual defineClass call and the amount of verification the JVM has to do to get a class object created.
I added a debug log to measure the processing time related to OSGi when Eclipse starts. Is it possible that ClasspathManager#findLocalClassImpl is the bottleneck? Eclipse IDE for Enterprise Java and Web Developers Version: 2021-06 M3 (4.20.0 M3) Build id: 20210527-1503 AdoptOpenJDK (build 15.0.2+7) macOS 11.3.1（20E241） Eclipse Startup Time 17.478 sec 11674 calls 9.638 sec org.eclipse.osgi.internal.loader.classpath.ClasspathManager#findLocalClassImpl 10878 calls 8.071 sec org.eclipse.osgi.internal.loader.ModuleClassLoader#defineClass 6235 calls 4.819 sec org.eclipse.osgi.internal.loader.classpath.ClasspathManager#findClassImpl 8149 calls 4.661 sec org.eclipse.osgi.internal.loader.ModuleClassLoader#findLocalClass 8149 calls 4.655 sec org.eclipse.osgi.internal.loader.classpath.ClasspathManager#findLocalClass 10998 calls 4.547 sec org.eclipse.osgi.internal.loader.BundleLoader#findClass 9175 calls 4.538 sec org.eclipse.osgi.internal.loader.BundleLoader#findLocalClass 5439 calls 4.204 sec org.eclipse.osgi.internal.loader.classpath.ClasspathManager#defineClass 91 calls 4.197 sec org.eclipse.osgi.internal.framework.BundleContextImpl#start 61 calls 3.642 sec org.eclipse.osgi.internal.framework.BundleContextImpl#startActivator 61 calls 3.639 sec org.eclipse.osgi.internal.framework.BundleContextImpl$2#run 90 calls 3.145 sec org.eclipse.osgi.internal.framework.EquinoxBundle#startWorker0 343 calls 1.462 sec org.eclipse.osgi.internal.loader.ModuleClassLoader#loadClass 1 calls 1.184 sec org.eclipse.osgi.internal.framework.EquinoxBundle$SystemBundle#init 1510 calls 1.106 sec org.eclipse.osgi.internal.framework.EquinoxEventPublisher#publishBundleEvent 1 calls 1.054 sec org.eclipse.osgi.internal.framework.EquinoxBundle$SystemBundle#startWorker0 3976 calls 1.008 sec org.eclipse.osgi.internal.loader.sources.PackageSource#loadClass 353 calls 0.976 sec org.eclipse.osgi.internal.serviceregistry.ServiceRegistry#registerService 353 calls 0.923 sec org.eclipse.osgi.internal.serviceregistry.ServiceRegistrationImpl#register 403 calls 0.906 sec org.eclipse.osgi.internal.serviceregistry.ServiceRegistry#publishServiceEvent 403 calls 0.906 sec org.eclipse.osgi.internal.serviceregistry.ServiceRegistry#publishServiceEventPrivileged 91 calls 0.682 sec org.eclipse.osgi.internal.framework.BundleContextImpl#loadBundleActivator 43 calls 0.661 sec org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse#factoryGetService 353 calls 0.637 sec org.eclipse.osgi.internal.framework.BundleContextImpl#registerService 300 calls 0.625 sec org.eclipse.osgi.internal.serviceregistry.ServiceRegistry#getService 300 calls 0.618 sec org.eclipse.osgi.internal.serviceregistry.ServiceRegistrationImpl#getService 19 calls 0.593 sec org.eclipse.osgi.internal.debug.FrameworkDebugOptions#addingService 300 calls 0.576 sec org.eclipse.osgi.internal.serviceregistry.ServiceConsumer#getService 300 calls 0.575 sec org.eclipse.osgi.internal.serviceregistry.ServiceUse#getService 755 calls 0.552 sec org.eclipse.osgi.internal.framework.EquinoxEventPublisher#publishBundleEventPrivileged
Eclipse Startup Time 17.478 sec 11674 calls 9.638 sec org.eclipse.osgi.internal.loader.classpath.ClasspathManager#findLocalClassImpl 10878 calls 8.071 sec org.eclipse.osgi.internal.loader.ModuleClassLoader#defineClass I'm not sure how to interpret the times here. The findLocalClassImpl method includes a call to defineClass. The 9.638 sec for findLocalClassImpl, does that include the 8.071 sec for defineClass. In other words is the "real overhead" for findLocalClassImpl 9.638-8.071 = 1.567 when we take the time of defineClass out?
(In reply to Thomas Watson from comment #18) Yes, I think so. I don't have any good ideas, but I was wondering if there is any possibility to reduce the number of calls or do some optimization. Thank you.
(In reply to Shinji Kashihara from comment #19) > (In reply to Thomas Watson from comment #18) > > Yes, I think so. > I don't have any good ideas, but I was wondering if there is any possibility > to reduce the number of calls or do some optimization. Thank you. It depends on which ClasspathManager#findLocalClassImpl method we are discussing. There are two of them: ClasspathManager.findLocalClassImpl(String, List<ClassLoaderHook>) ClasspathManager.findLocalClassImpl(String, ClasspathEntry[], List<ClassLoaderHook>) The first one calls the second one a number of times, depending on if there are fragments attached the second one will get called more.
As we are near to 4.20 release, please close or re-target.
Thanks to everyone who contributed, work continues for the next release in Bug 574015.
