Bug 313953 - [performance] [reconciler] [query] Super slow startup time after deleting files in dropins
Summary: [performance] [reconciler] [query] Super slow startup time after deleting fil...
Status: RESOLVED FIXED
Alias: None
Product: Equinox
Classification: Eclipse Project
Component: p2 (show other bugs)
Version: 3.5   Edit
Hardware: PC Windows XP
: P3 normal (vote)
Target Milestone: 3.6.1   Edit
Assignee: DJ Houghton CLA
QA Contact:
URL:
Whiteboard:
Keywords: performance
Depends on: 244628
Blocks: 321057
  Show dependency tree
 
Reported: 2010-05-21 14:05 EDT by DJ Houghton CLA
Modified: 2010-07-27 14:23 EDT (History)
3 users (show)

See Also:


Attachments
YourKit output (11.64 KB, text/plain)
2010-06-02 15:46 EDT, DJ Houghton CLA
no flags Details
Fix for problem 1) using executeBatch (untested) (1.76 KB, patch)
2010-06-04 13:48 EDT, John Arthorne CLA
no flags Details | Diff

Note You need to log in before you can comment on or make changes to this bug.
Description DJ Houghton CLA 2010-05-21 14:05:40 EDT
I just had a case where I was testing the following:
- start up Eclipse and shutdown
- drop test data into the dropins folder consisting of 3000 features each pointing to a single bundle. (3000 bundles total)
- start Eclipse - note everything gets installed via the reconciler
- shut down
- delete everything from dropins
- startup and shutdown
- add single feature and bundle from first group of test data to dropins folder
- startup pegged the CPU at 100% and it took over 15min
- a couple of stack dumps showed the following: 

"Start Level Event Dispatcher" daemon prio=6 tid=0x03fda800 nid=0xbf4 runnable [0x0448e000]
   java.lang.Thread.State: RUNNABLE
        at java.lang.Class.getClassLoader0(Native Method)
        at java.lang.ClassLoader.getCallerClassLoader(Unknown Source)
        at java.lang.Class.forName(Unknown Source)
        at org.eclipse.equinox.internal.p2.metadata.expression.CoercingComparator$IntegerCoercer.getCoerceClass(CoercingComparator.java:148)
        at org.eclipse.equinox.internal.p2.metadata.expression.CoercingComparator.canCoerceTo(CoercingComparator.java:382)
        at org.eclipse.equinox.internal.p2.metadata.expression.CoercingComparator.getComparator(CoercingComparator.java:334)
        at org.eclipse.equinox.internal.p2.metadata.expression.CoercingComparator.coerceAndEquals(CoercingComparator.java:313)
        at org.eclipse.equinox.internal.p2.metadata.expression.Equals.evaluate(Equals.java:27)
        at org.eclipse.equinox.internal.p2.metadata.expression.Unary.evaluate(Unary.java:42)
        at org.eclipse.equinox.internal.p2.metadata.expression.Exists.evaluate(Exists.java:29)
        at org.eclipse.equinox.internal.p2.metadata.expression.CollectionFilter.evaluate(CollectionFilter.java:58)
        at org.eclipse.equinox.internal.p2.metadata.expression.MatchExpression.evaluate(MatchExpression.java:44)
        at org.eclipse.equinox.p2.query.ExpressionMatchQuery.isMatch(ExpressionMatchQuery.java:86)
        at org.eclipse.equinox.p2.query.ExpressionMatchQuery.perform(ExpressionMatchQuery.java:73)
        at org.eclipse.equinox.p2.query.ExpressionMatchQuery.perform(ExpressionMatchQuery.java:63)
        at org.eclipse.equinox.internal.p2.metadata.index.IndexProvider.query(IndexProvider.java:12)
        at org.eclipse.equinox.internal.p2.metadata.repository.LocalMetadataRepository.query(LocalMetadataRepository.java:221)
        at org.eclipse.equinox.internal.provisional.p2.directorywatcher.RepositoryListener.synchronizeMetadataRepository(RepositoryListener.java:220)
        at org.eclipse.equinox.internal.provisional.p2.directorywatcher.RepositoryListener.stopPoll(RepositoryListener.java:198)
        at org.eclipse.equinox.internal.provisional.p2.directorywatcher.DirectoryWatcher.stopPoll(DirectoryWatcher.java:171)
        at org.eclipse.equinox.internal.provisional.p2.directorywatcher.DirectoryWatcher.poll(DirectoryWatcher.java:109)
        - locked <0x189a9b90> (a org.eclipse.equinox.internal.provisional.p2.directorywatcher.DirectoryWatcher)
        at org.eclipse.equinox.internal.p2.extensionlocation.SiteListener.synchronizeRepositories(SiteListener.java:111)
        - locked <0x274be8b8> (a java.lang.Class for org.eclipse.equinox.internal.p2.extensionlocation.SiteListener)
        at org.eclipse.equinox.internal.p2.extensionlocation.ExtensionLocationMetadataRepository.ensureInitialized(ExtensionLocationMetadataRepository
.java:66)
        - locked <0x171fb098> (a org.eclipse.equinox.internal.p2.extensionlocation.ExtensionLocationMetadataRepository)
        at org.eclipse.equinox.internal.p2.extensionlocation.ExtensionLocationMetadataRepository.getProperties(ExtensionLocationMetadataRepository.jav
a:194)
        at org.eclipse.equinox.internal.p2.repository.helpers.AbstractRepositoryManager.addRepository(AbstractRepositoryManager.java:125)
        - locked <0x1707c3b0> (a java.lang.Object)
        at org.eclipse.equinox.internal.p2.repository.helpers.AbstractRepositoryManager.loadRepository(AbstractRepositoryManager.java:658)
        at org.eclipse.equinox.internal.p2.metadata.repository.MetadataRepositoryManager.loadRepository(MetadataRepositoryManager.java:96)
        at org.eclipse.equinox.internal.p2.metadata.repository.MetadataRepositoryManager.loadRepository(MetadataRepositoryManager.java:92)
        at org.eclipse.equinox.internal.p2.reconciler.dropins.Activator.loadMetadataRepository(Activator.java:93)
        at org.eclipse.equinox.internal.p2.reconciler.dropins.DropinsRepositoryListener.getMetadataRepository(DropinsRepositoryListener.java:198)
        at org.eclipse.equinox.internal.p2.reconciler.dropins.DropinsRepositoryListener.addRepository(DropinsRepositoryListener.java:93)
        at org.eclipse.equinox.internal.p2.reconciler.dropins.DropinsRepositoryListener.added(DropinsRepositoryListener.java:68)
        at org.eclipse.equinox.internal.provisional.p2.directorywatcher.DirectoryWatcher.processFile(DirectoryWatcher.java:197)
        at org.eclipse.equinox.internal.provisional.p2.directorywatcher.DirectoryWatcher.scanDirectories(DirectoryWatcher.java:160)
        at org.eclipse.equinox.internal.provisional.p2.directorywatcher.DirectoryWatcher.poll(DirectoryWatcher.java:108)
        - locked <0x17048c50> (a org.eclipse.equinox.internal.provisional.p2.directorywatcher.DirectoryWatcher)
        at org.eclipse.equinox.internal.p2.reconciler.dropins.Activator.watchDropins(Activator.java:518)
        at org.eclipse.equinox.internal.p2.reconciler.dropins.Activator.start(Activator.java:161)
Comment 1 DJ Houghton CLA 2010-06-02 15:46:00 EDT
Created attachment 170871 [details]
YourKit output

There are 2 issues here:

1). We spend 74% of the time synchronizing the artifact repository. Given the following chain of method calls:
  CachingArtifactRepository.save();
  CachingArtifactRepository.saveRemovals();
  SimpleArtifactRepository.removeDescriptor(IArtifactDescriptor);
  SimpleArtifactRepository.save();
We are removing the artifacts one by one and doing a full save after each one. We should consider adding a method which removes multiple artifacts before saving.

2). We spend 26% of the time synchronizing the metadata repository. Most of this time is spent doing the following query:
  IQuery<IInstallableUnit> removeQuery = QueryUtil.createMatchQuery(
	"$1.exists(x | properties[$0] == x)", FILE_NAME, removedFiles);
  IQueryResult<IInstallableUnit> toRemove = metadataRepository.query(removeQuery, null);
I'm not sure how to optimize this. Perhaps Thomas has a suggestion.

It appears that when we start up and a repository has been completely removed, we do nothing and then when it re-appears we reconcile with it. We should investigate removing the cached data if the repository is not available. One consideration though is if (for instance) the repo is a linked location that currently isn't available (because we are working offline) but will be available next time we start. Do we really want to delete the metadata and regenerate next time?
Comment 2 DJ Houghton CLA 2010-06-02 16:19:30 EDT
Bug 244628 handles case 1.
Comment 3 John Arthorne CLA 2010-06-04 13:48:29 EDT
Created attachment 171138 [details]
Fix for problem 1) using executeBatch (untested)
Comment 4 John Arthorne CLA 2010-06-04 13:50:32 EDT
Consider for 3.6.1
Comment 5 Thomas Hallgren CLA 2010-06-04 16:40:10 EDT
(In reply to comment #1)
> 2). We spend 26% of the time synchronizing the metadata repository. Most of
> this time is spent doing the following query:
>   IQuery<IInstallableUnit> removeQuery = QueryUtil.createMatchQuery(
>     "$1.exists(x | properties[$0] == x)", FILE_NAME, removedFiles);
>   IQueryResult<IInstallableUnit> toRemove =
> metadataRepository.query(removeQuery, null);
> I'm not sure how to optimize this. Perhaps Thomas has a suggestion.
> 
The query itself doesn't seems fairly lightweight unless of course the removedFiles is a very large collection Can that be the case? Or is the query executed a very large number of times?
Comment 6 Thomas Hallgren CLA 2010-06-04 17:25:46 EDT
I meant to write "The query seem fairly lightweight", not the opposite :-)
Comment 7 DJ Houghton CLA 2010-07-27 14:23:53 EDT
Patch released to R36x maintenance branch.
Closing.