Bug 137932 - Platform reads too many "plugin.xml" entries during startup
Summary: Platform reads too many "plugin.xml" entries during startup
Status: RESOLVED INVALID
Alias: None
Product: Equinox
Classification: Eclipse Project
Component: Compendium (show other bugs)
Version: 3.2   Edit
Hardware: PC Windows XP
: P3 normal (vote)
Target Milestone: ---   Edit
Assignee: equinox.framework-inbox CLA
QA Contact:
URL:
Whiteboard:
Keywords: performance
Depends on:
Blocks:
 
Reported: 2006-04-21 09:28 EDT by Chris Laffra CLA
Modified: 2006-04-21 12:08 EDT (History)
4 users (show)

See Also:


Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Chris Laffra CLA 2006-04-21 09:28:17 EDT
A major focus of the Eclipse 3.2 release is scalability, and major strides have been made in various areas (UI, workspace, JDT, platform, equinox). I am working on a product that ships around 1,800 plugins, so I think we are a nice test case for scalability of equinox :-)

What I think I discovered is that while building the extension registry, each contribution is validated by taking its timestamp. For this, from the contribution either "plugin.xml" or "fragment.xml" is retrieved. When the bundle has been jarred up (which a growing number of bundles are), this means we have to open the jar (create instance of java.util.ZipFile), to get the entry out, and then the only thing we do with it is test its timestamp.

This is fine for Eclipse. For larger products, this becomes noticeable. When something as large as RAD starts up, Eclipse may take 2-10 seconds *before* the fabulous progress bar shows progress in the splash screen. Once the progress bar starts animating, startup of RAD seems to progress almost as fast as Eclipse (all jars are in the OS disk cache by now, of course).
When self-hosting, a product like RAD can take up to 20 seconds before progress starts showing.

Is the exhaustive timestamp checking by design? Are there alternatives? Is there something I am doing wrong? This is all on 3.2M6

What I recommend the equinox team does is to build a fake product with 10,000 empty plugins (org.eclipse.equinox.scalability.test1, 2, etc), and one with 100,000 plugins, to see if you can replicate this problem, and then see if we can find better ways to determine whether the binary registry is out of date?

I saw the behavior both when self-hosting _and_ when running from the command line (to rule out PDE artifact behavior).

Below, you find a stack dump where plugin.xml is loaded during initialization.

java.lang.Exception: Loading plugin.xml
	at com.ibm.cds.jxes.JxeZipFile.getEntry(JxeZipFile.java:85)
	at org.eclipse.osgi.baseadaptor.bundlefile.ZipBundleFile.getZipEntry(ZipBundleFile.java:102)
	at org.eclipse.osgi.baseadaptor.bundlefile.ZipBundleFile.getEntry(ZipBundleFile.java:229)
	at org.eclipse.osgi.baseadaptor.BaseData.getEntry(BaseData.java:97)
	at org.eclipse.osgi.framework.internal.core.AbstractBundle.getEntry(AbstractBundle.java:1281)
	at org.eclipse.core.internal.registry.osgi.RegistryStrategyOSGI.getContributionsTimestamp(Unknown Source)
	at org.eclipse.core.internal.registry.ExtensionRegistry.computeTimeStamp(Unknown Source)
	at org.eclipse.core.internal.registry.ExtensionRegistry.<init>(Unknown Source)
	at org.eclipse.core.runtime.RegistryFactory.createRegistry(Unknown Source)
	at org.eclipse.core.internal.registry.osgi.Activator.startRegistry(Unknown Source)
	at org.eclipse.core.internal.registry.osgi.Activator.start(Unknown Source)
	at org.eclipse.osgi.framework.internal.core.BundleContextImpl$2.run(BundleContextImpl.java:994)
	at java.security.AccessController.doPrivileged(AccessController.java:204)
	at org.eclipse.osgi.framework.internal.core.BundleContextImpl.startActivator(BundleContextImpl.java:988)
	at org.eclipse.osgi.framework.internal.core.BundleContextImpl.start(BundleContextImpl.java:969)
	at org.eclipse.osgi.framework.internal.core.BundleHost.startWorker(BundleHost.java:317)
	at org.eclipse.osgi.framework.internal.core.AbstractBundle.start(AbstractBundle.java:256)
	at org.eclipse.core.runtime.internal.adaptor.EclipseLazyStarter.preFindLocalClass(EclipseLazyStarter.java:86)
	at org.eclipse.osgi.baseadaptor.loader.ClasspathManager.findLocalClass(ClasspathManager.java:402)
	at org.eclipse.osgi.internal.baseadaptor.DefaultClassLoader.findLocalClass(DefaultClassLoader.java:188)
	at org.eclipse.osgi.framework.internal.core.BundleLoader.findLocalClass(BundleLoader.java:338)
	at org.eclipse.osgi.framework.internal.core.SingleSourcePackage.loadClass(SingleSourcePackage.java:37)
	at org.eclipse.osgi.framework.internal.core.MultiSourcePackage.loadClass(MultiSourcePackage.java:32)
	at org.eclipse.osgi.framework.internal.core.BundleLoader.findClass(BundleLoader.java:387)
	at org.eclipse.osgi.framework.internal.core.BundleLoader.findClass(BundleLoader.java:351)
	at org.eclipse.osgi.internal.baseadaptor.DefaultClassLoader.loadClass(DefaultClassLoader.java:83)
	at java.lang.ClassLoader.loadClass(ClassLoader.java:560)
	at java.lang.ClassLoader.defineClassImpl(Native Method)
	at java.lang.ClassLoader.defineClass(ClassLoader.java:211)
	at org.eclipse.osgi.internal.baseadaptor.DefaultClassLoader.defineClass(DefaultClassLoader.java:160)
	at org.eclipse.osgi.baseadaptor.loader.ClasspathManager.defineClass(ClasspathManager.java:491)
	at org.eclipse.osgi.baseadaptor.loader.ClasspathManager.findClassImpl(ClasspathManager.java:461)
	at org.eclipse.osgi.baseadaptor.loader.ClasspathManager.findLocalClassImpl(ClasspathManager.java:420)
	at org.eclipse.osgi.baseadaptor.loader.ClasspathManager.findLocalClass(ClasspathManager.java:403)
	at org.eclipse.osgi.internal.baseadaptor.DefaultClassLoader.findLocalClass(DefaultClassLoader.java:188)
	at org.eclipse.osgi.framework.internal.core.BundleLoader.findLocalClass(BundleLoader.java:338)
	at org.eclipse.osgi.framework.internal.core.BundleLoader.findClass(BundleLoader.java:390)
	at org.eclipse.osgi.framework.internal.core.BundleLoader.findClass(BundleLoader.java:351)
	at org.eclipse.osgi.internal.baseadaptor.DefaultClassLoader.loadClass(DefaultClassLoader.java:83)
	at java.lang.ClassLoader.loadClass(ClassLoader.java:560)
	at org.eclipse.osgi.framework.internal.core.BundleLoader.loadClass(BundleLoader.java:276)
	at org.eclipse.osgi.framework.internal.core.BundleHost.loadClass(BundleHost.java:227)
	at org.eclipse.osgi.framework.internal.core.AbstractBundle.loadBundleActivator(AbstractBundle.java:134)
	at org.eclipse.osgi.framework.internal.core.BundleContextImpl.start(BundleContextImpl.java:965)
	at org.eclipse.osgi.framework.internal.core.BundleHost.startWorker(BundleHost.java:317)
	at org.eclipse.osgi.framework.internal.core.AbstractBundle.resume(AbstractBundle.java:329)
	at org.eclipse.osgi.framework.internal.core.Framework.resumeBundle(Framework.java:1037)
	at org.eclipse.osgi.framework.internal.core.StartLevelManager.resumeBundles(StartLevelManager.java:573)
	at org.eclipse.osgi.framework.internal.core.StartLevelManager.incFWSL(StartLevelManager.java:495)
	at org.eclipse.osgi.framework.internal.core.StartLevelManager.doSetStartLevel(StartLevelManager.java:275)
	at org.eclipse.osgi.framework.internal.core.StartLevelManager.dispatchEvent(StartLevelManager.java:455)
	at org.eclipse.osgi.framework.eventmgr.EventManager.dispatchEvent(EventManager.java:189)
	at org.eclipse.osgi.framework.eventmgr.EventManager$EventThread.run(EventManager.java:291)
Comment 1 Jeff McAffer CLA 2006-04-21 10:27:26 EDT
Interesting. Oleg, can you dig into this?  

Chris, can you confirm that this is NOT first start?

The time stamp checking really ought to be of the JAR itself in the case of JAR'd plugins.
Comment 2 Thomas Watson CLA 2006-04-21 10:31:10 EDT
When you do normal command line startup do you set the following :

osgi.checkConfiguration=true

By default this property is not set and the code from the stacktrace should not be run at all.  This property will also get set if you use the -dev option from command line.
Comment 3 Chris Laffra CLA 2006-04-21 10:45:58 EDT
I triple-quadruple checked. It seems like all of a sudden the entries are no longer read from the command line. Duh. So it wasn't those entries after all.

What follows now is a desperate struggle to demonstrate I am still onto something...

What I see is that it takes about 2.5 seconds (at 100% CPU) before the progress bar is starting to show in the splash screen. This seems long to me. Overall, with a warm hard disk, command-line startup is around 8-9 seconds to go into empty Java perspective.
Comment 4 Oleg Besedin CLA 2006-04-21 12:08:09 EDT
Hi Chris,
I just checked again and it works just like Thomas described in the comment #2. 

For the startup time: let's assume that the time before you see the progress bar is the headless startup time. (This is not quite correct, but is a reasonable simplification.)

The headless startup time consist from two variables: "base" startup time (about 0.8 sec on the WinXP 2Gb 2GHz) and the "variable" time.

The "base" startup time goes into classloading, activation of the runtime and OSGi, and some housekeeping. 

The "variable" startup time depends on the number of plugns in the target and seems to be about 1ms per bundle.

So, the headless startup time for 1800 plugins would be about:
"base" + "variable" = 0.8sec + 0.001sec/plugin * 1800plugins = 2.6 sec 

Which is close to what you see.

I am closing the bug as "invalid" as the timestamp are only checked in "dev" mode, if the "osgi.checkConfiguration" property is set, or during the fist startup. 

That said, I would be very interested in suggestions on reducing the startup time.