Bug 337012 - Performance: large regression in starting RAD as a non-root user
Summary: Performance: large regression in starting RAD as a non-root user
Status: CLOSED WORKSFORME
Alias: None
Product: Equinox
Classification: Eclipse Project
Component: p2 (show other bugs)
Version: 3.7   Edit
Hardware: PC Linux
: P3 critical (vote)
Target Milestone: ---   Edit
Assignee: DJ Houghton CLA
QA Contact:
URL:
Whiteboard:
Keywords: performance
Depends on:
Blocks:
 
Reported: 2011-02-11 17:28 EST by Gary Karasiuk CLA
Modified: 2011-03-02 11:17 EST (History)
7 users (show)

See Also:


Attachments
Sampling profile taken during the first 10 minutes of startup (5.33 MB, application/octet-stream)
2011-02-11 17:37 EST, Gary Karasiuk CLA
no flags Details
Tracing profile, about a minute long, taken at 15 minute mark (1.45 MB, application/octet-stream)
2011-02-11 17:40 EST, Gary Karasiuk CLA
no flags Details
Sampling profile taken during the first 10 minutes of startup (1.30 MB, application/octet-stream)
2011-02-11 17:42 EST, Gary Karasiuk CLA
no flags Details
p2 bunldes from the "previous" version of our product (7.62 KB, text/plain)
2011-02-15 09:13 EST, Gary Karasiuk CLA
no flags Details
screenshot of profiled data (180.26 KB, image/gif)
2011-03-02 10:42 EST, Gary Karasiuk CLA
no flags Details
Screenshot from the 1 minute profile (84.54 KB, image/gif)
2011-03-02 10:57 EST, Gary Karasiuk CLA
no flags Details
profile snapshot (1.64 MB, application/zip)
2011-03-02 11:11 EST, DJ Houghton CLA
no flags Details

Note You need to log in before you can comment on or make changes to this bug.
Description Gary Karasiuk CLA 2011-02-11 17:28:39 EST
We are a large adopting product. This is the scenario that has regressed for us:

1) As root, modify our product by adding or removing a feature.
2) As a non-root user, start the product.

For our product that is built on 3.6.1, step 2 takes 5.5 minutes (which is already very bad), but for our product that is built on 3.6.2, step 2 takes 23.5 minutes. 

I have some Yourkit profiles for step 2, which I can send to you.

We see that this method is very expensive:

org.eclipse.equinox.internal.p2.metadata.repository.io.MetadataWriter.writeInstallableUnit(IInstallableUnit)
Comment 1 Gary Karasiuk CLA 2011-02-11 17:32:25 EST
These are the "p2" plug-ins, in our current drivers:

org.eclipse.equinox.p2.artifact.repository,1.1.1.R36x_v20100901,../SDPShared/plugins/org.eclipse.equinox.p2.artifact.repository_1.1.1.R36x_v20100901.jar,4,false
org.eclipse.equinox.p2.artifact.repository.nl1,1.1.1.v201102031400,../SDPShared/plugins/org.eclipse.equinox.p2.artifact.repository.nl1_1.1.1.v201102031400.jar,4,false
org.eclipse.equinox.p2.console,1.0.200.v20100601,../SDPShared/plugins/org.eclipse.equinox.p2.console_1.0.200.v20100601.jar,4,false
org.eclipse.equinox.p2.console.nl1,1.0.200.v201102031400,../SDPShared/plugins/org.eclipse.equinox.p2.console.nl1_1.0.200.v201102031400.jar,4,false
org.eclipse.equinox.p2.core,2.0.3.R36x_v20110111,../SDPShared/plugins/org.eclipse.equinox.p2.core_2.0.3.R36x_v20110111.jar,4,false
org.eclipse.equinox.p2.core.nl1,2.0.3.v201102031400,../SDPShared/plugins/org.eclipse.equinox.p2.core.nl1_2.0.3.v201102031400.jar,4,false
org.eclipse.equinox.p2.director,2.0.3.R36x_v20101117-1018,../SDPShared/plugins/org.eclipse.equinox.p2.director_2.0.3.R36x_v20101117-1018.jar,4,false
org.eclipse.equinox.p2.director.app,1.0.201.R36x_v20100823,../SDPShared/plugins/org.eclipse.equinox.p2.director.app_1.0.201.R36x_v20100823.jar,4,false
org.eclipse.equinox.p2.director.app.nl1,1.0.201.v201102031400,../SDPShared/plugins/org.eclipse.equinox.p2.director.app.nl1_1.0.201.v201102031400.jar,4,false
org.eclipse.equinox.p2.director.nl1,2.0.3.v201102031400,../SDPShared/plugins/org.eclipse.equinox.p2.director.nl1_2.0.3.v201102031400.jar,4,false
org.eclipse.equinox.p2.directorywatcher,1.0.203.R36x_v20101220,../SDPShared/plugins/org.eclipse.equinox.p2.directorywatcher_1.0.203.R36x_v20101220.jar,4,false
org.eclipse.equinox.p2.directorywatcher.nl1,1.0.203.v201102031400,../SDPShared/plugins/org.eclipse.equinox.p2.directorywatcher.nl1_1.0.203.v201102031400.jar,4,false
org.eclipse.equinox.p2.engine,2.0.0.v20100606,../SDPShared/plugins/org.eclipse.equinox.p2.engine_2.0.0.v20100606.jar,4,false
org.eclipse.equinox.p2.engine.nl1,2.0.0.v201102031400,../SDPShared/plugins/org.eclipse.equinox.p2.engine.nl1_2.0.0.v201102031400.jar,4,false
org.eclipse.equinox.p2.extensionlocation,1.2.0.v20100518,../SDPShared/plugins/org.eclipse.equinox.p2.extensionlocation_1.2.0.v20100518.jar,4,false
org.eclipse.equinox.p2.extensionlocation.nl1,1.2.0.v201102031400,../SDPShared/plugins/org.eclipse.equinox.p2.extensionlocation.nl1_1.2.0.v201102031400.jar,4,false
org.eclipse.equinox.p2.garbagecollector,1.0.100.v20100503,../SDPShared/plugins/org.eclipse.equinox.p2.garbagecollector_1.0.100.v20100503.jar,4,false
org.eclipse.equinox.p2.garbagecollector.nl1,1.0.100.v201102031400,../SDPShared/plugins/org.eclipse.equinox.p2.garbagecollector.nl1_1.0.100.v201102031400.jar,4,false
org.eclipse.equinox.p2.jarprocessor,1.0.200.v20100503a,../SDPShared/plugins/org.eclipse.equinox.p2.jarprocessor_1.0.200.v20100503a.jar,4,false
org.eclipse.equinox.p2.jarprocessor.nl1,1.0.200.v201102031400,../SDPShared/plugins/org.eclipse.equinox.p2.jarprocessor.nl1_1.0.200.v201102031400.jar,4,false
org.eclipse.equinox.p2.metadata,2.0.1.R36x_v20101202,../SDPShared/plugins/org.eclipse.equinox.p2.metadata_2.0.1.R36x_v20101202.jar,4,false
org.eclipse.equinox.p2.metadata.generator,1.0.202.R36x_v20101208-1400,../SDPShared/plugins/org.eclipse.equinox.p2.metadata.generator_1.0.202.R36x_v20101208-1400.jar,4,false
org.eclipse.equinox.p2.metadata.generator.nl1,1.0.202.v201102031400,../SDPShared/plugins/org.eclipse.equinox.p2.metadata.generator.nl1_1.0.202.v201102031400.jar,4,false
org.eclipse.equinox.p2.metadata.nl1,2.0.1.v201102031400,../SDPShared/plugins/org.eclipse.equinox.p2.metadata.nl1_2.0.1.v201102031400.jar,4,false
org.eclipse.equinox.p2.metadata.repository,1.1.0.v20100513,../SDPShared/plugins/org.eclipse.equinox.p2.metadata.repository_1.1.0.v20100513.jar,4,false
org.eclipse.equinox.p2.metadata.repository.nl1,1.1.0.v201102031400,../SDPShared/plugins/org.eclipse.equinox.p2.metadata.repository.nl1_1.1.0.v201102031400.jar,4,false
org.eclipse.equinox.p2.operations,2.0.0.v20100510,../SDPShared/plugins/org.eclipse.equinox.p2.operations_2.0.0.v20100510.jar,4,false
org.eclipse.equinox.p2.operations.nl1,2.0.0.v201102031400,../SDPShared/plugins/org.eclipse.equinox.p2.operations.nl1_2.0.0.v201102031400.jar,4,false
org.eclipse.equinox.p2.publisher,1.1.2.v20100824-2220,../SDPShared/plugins/org.eclipse.equinox.p2.publisher_1.1.2.v20100824-2220.jar,4,false
org.eclipse.equinox.p2.publisher.nl1,1.1.2.v201102031400,../SDPShared/plugins/org.eclipse.equinox.p2.publisher.nl1_1.1.2.v201102031400.jar,4,false
org.eclipse.equinox.p2.ql,2.0.0.v20100503a,../SDPShared/plugins/org.eclipse.equinox.p2.ql_2.0.0.v20100503a.jar,4,false
org.eclipse.equinox.p2.ql.nl1,2.0.0.v201102031400,../SDPShared/plugins/org.eclipse.equinox.p2.ql.nl1_2.0.0.v201102031400.jar,4,false
org.eclipse.equinox.p2.reconciler.dropins,1.1.2.R36x_v20110114,../SDPShared/plugins/org.eclipse.equinox.p2.reconciler.dropins_1.1.2.R36x_v20110114.jar,4,true
org.eclipse.equinox.p2.reconciler.dropins.nl1,1.1.2.v201102031400,../SDPShared/plugins/org.eclipse.equinox.p2.reconciler.dropins.nl1_1.1.2.v201102031400.jar,4,false
org.eclipse.equinox.p2.repository,2.0.2.R36x_v20110111-1500,../SDPShared/plugins/org.eclipse.equinox.p2.repository_2.0.2.R36x_v20110111-1500.jar,4,false
org.eclipse.equinox.p2.repository.nl1,2.0.2.v201102031400,../SDPShared/plugins/org.eclipse.equinox.p2.repository.nl1_2.0.2.v201102031400.jar,4,false
org.eclipse.equinox.p2.repository.tools,2.0.1.R36x_v20100823,../SDPShared/plugins/org.eclipse.equinox.p2.repository.tools_2.0.1.R36x_v20100823.jar,4,false
org.eclipse.equinox.p2.repository.tools.nl1,2.0.1.v201102031400,../SDPShared/plugins/org.eclipse.equinox.p2.repository.tools.nl1_2.0.1.v201102031400.jar,4,false
org.eclipse.equinox.p2.touchpoint.eclipse,2.0.3.R36x_v20101202,../SDPShared/plugins/org.eclipse.equinox.p2.touchpoint.eclipse_2.0.3.R36x_v20101202.jar,4,false
org.eclipse.equinox.p2.touchpoint.eclipse.nl1,2.0.3.v201102031400,../SDPShared/plugins/org.eclipse.equinox.p2.touchpoint.eclipse.nl1_2.0.3.v201102031400.jar,4,false
org.eclipse.equinox.p2.touchpoint.natives,1.0.201.R36x_v20110111,../SDPShared/plugins/org.eclipse.equinox.p2.touchpoint.natives_1.0.201.R36x_v20110111.jar,4,false
org.eclipse.equinox.p2.touchpoint.natives.nl1,1.0.201.v201102031400,../SDPShared/plugins/org.eclipse.equinox.p2.touchpoint.natives.nl1_1.0.201.v201102031400.jar,4,false
org.eclipse.equinox.p2.ui,2.0.0.v20100518,../SDPShared/plugins/org.eclipse.equinox.p2.ui_2.0.0.v20100518.jar,4,false
org.eclipse.equinox.p2.ui.nl1,2.0.0.v201102031400,../SDPShared/plugins/org.eclipse.equinox.p2.ui.nl1_2.0.0.v201102031400.jar,4,false
org.eclipse.equinox.p2.ui.sdk,1.0.100.v20100513,../SDPShared/plugins/org.eclipse.equinox.p2.ui.sdk_1.0.100.v20100513.jar,4,false
org.eclipse.equinox.p2.ui.sdk.nl1,1.0.100.v201102031400,../SDPShared/plugins/org.eclipse.equinox.p2.ui.sdk.nl1_1.0.100.v201102031400.jar,4,false
org.eclipse.equinox.p2.ui.sdk.scheduler,1.0.0.v20100507-1815,../SDPShared/plugins/org.eclipse.equinox.p2.ui.sdk.scheduler_1.0.0.v20100507-1815.jar,4,false
org.eclipse.equinox.p2.ui.sdk.scheduler.nl1,1.0.0.v201102031400,../SDPShared/plugins/org.eclipse.equinox.p2.ui.sdk.scheduler.nl1_1.0.0.v201102031400.jar,4,false
org.eclipse.equinox.p2.updatechecker,1.1.101.R36x_v20100823,../SDPShared/plugins/org.eclipse.equinox.p2.updatechecker_1.1.101.R36x_v20100823.jar,4,false
org.eclipse.equinox.p2.updatechecker.nl1,1.1.101.v201102031400,../SDPShared/plugins/org.eclipse.equinox.p2.updatechecker.nl1_1.1.101.v201102031400.jar,4,false
org.eclipse.equinox.p2.updatesite,1.0.201.R36x_v20100823,../SDPShared/plugins/org.eclipse.equinox.p2.updatesite_1.0.201.R36x_v20100823.jar,4,false
org.eclipse.equinox.p2.updatesite.nl1,1.0.201.v201102031400,../SDPShared/plugins/org.eclipse.equinox.p2.updatesite.nl1_1.0.201.v201102031400.jar,4,false
Comment 2 Gary Karasiuk CLA 2011-02-11 17:37:34 EST
Created attachment 188821 [details]
Sampling profile taken during the first 10 minutes of startup
Comment 3 Gary Karasiuk CLA 2011-02-11 17:40:57 EST
Created attachment 188822 [details]
Tracing profile, about a minute long, taken at 15 minute mark
Comment 4 Gary Karasiuk CLA 2011-02-11 17:42:46 EST
Created attachment 188823 [details]
Sampling profile taken during the first 10 minutes of startup
Comment 5 Pascal Rapicault CLA 2011-02-11 20:14:59 EST
Are you sure that in both case the number of plugins installed as root is the same.
Moving to DJ since I don't have access to the data set.
Comment 6 Gary Karasiuk CLA 2011-02-12 05:06:13 EST
(In reply to comment #5)
> Are you sure that in both case the number of plugins installed as root is the
> same.

I counted the number of lines in bundles.info:

Previous product: 3,529
Current product:  3,345
Comment 7 DJ Houghton CLA 2011-02-14 14:37:07 EST
This is very strange as the code isn't doing anything unusual and hasn't changed since before Eclipse 3.6.
Comment 8 Gary Karasiuk CLA 2011-02-15 09:13:07 EST
Created attachment 188993 [details]
p2 bunldes from the "previous" version of our product
Comment 9 Gary Karasiuk CLA 2011-02-15 09:15:13 EST
(In reply to comment #7)
> This is very strange as the code isn't doing anything unusual and hasn't
> changed since before Eclipse 3.6.

I atatched the list of p2 bundles from the previous version of our product, so that you could see what has changed wrt the current version.
Comment 10 DJ Houghton CLA 2011-02-15 09:26:36 EST
Although the specific "write out the IUs" code didn't change, I was reminded that there was code changed in 3.6.2 w.r.t. sharing IUs and String interning.
Comment 11 Gary Karasiuk CLA 2011-02-15 09:33:30 EST
Here is a report that shows the differences between the p2 plug-ins (I filtered out the NL ones) between the two versions of our product.

Comparison of C:\Documents and Settings\karasiuk\curr-p2-no-nl.txt and C:\Documents and Settings\karasiuk\prev-p2-no-nl.txt
2/15/2011 9:29:58 AM
Mode:  Just Differences

-----------------------------------------------------
L3	org.eclipse.equinox.p2.core,2.0.3.R36x_v20110111,../SDPShared/plugins/org.eclipse.equinox.p2.core_2.0.3.R36x_v20110111.jar,4,false
	org.eclipse.equinox.p2.director,2.0.3.R36x_v20101117-1018,../SDPShared/plugins/org.eclipse.equinox.p2.director_2.0.3.R36x_v20101117-1018.jar,4,false

R3	org.eclipse.equinox.p2.core,2.0.2.R36x_v20100804,../SDPShared/plugins/org.eclipse.equinox.p2.core_2.0.2.R36x_v20100804.jar,4,false
	org.eclipse.equinox.p2.director,2.0.2.R36x_v20100823,../SDPShared/plugins/org.eclipse.equinox.p2.director_2.0.2.R36x_v20100823.jar,4,false
-----------------------------------------------------
L6	org.eclipse.equinox.p2.directorywatcher,1.0.203.R36x_v20101220,../SDPShared/plugins/org.eclipse.equinox.p2.directorywatcher_1.0.203.R36x_v20101220.jar,4,false

R6	org.eclipse.equinox.p2.directorywatcher,1.0.202.R36x_v20100727,../SDPShared/plugins/org.eclipse.equinox.p2.directorywatcher_1.0.202.R36x_v20100727.jar,4,false
-----------------------------------------------------
L11	org.eclipse.equinox.p2.metadata,2.0.1.R36x_v20101202,../SDPShared/plugins/org.eclipse.equinox.p2.metadata_2.0.1.R36x_v20101202.jar,4,false
	org.eclipse.equinox.p2.metadata.generator,1.0.202.R36x_v20101208-1400,../SDPShared/plugins/org.eclipse.equinox.p2.metadata.generator_1.0.202.R36x_v20101208-1400.jar,4,false

R11	org.eclipse.equinox.p2.metadata,2.0.0.v20100601,../SDPShared/plugins/org.eclipse.equinox.p2.metadata_2.0.0.v20100601.jar,4,false
	org.eclipse.equinox.p2.metadata.generator,1.0.200.v20100503a,../SDPShared/plugins/org.eclipse.equinox.p2.metadata.generator_1.0.200.v20100503a.jar,4,false
-----------------------------------------------------
L17	org.eclipse.equinox.p2.reconciler.dropins,1.1.2.R36x_v20110114,../SDPShared/plugins/org.eclipse.equinox.p2.reconciler.dropins_1.1.2.R36x_v20110114.jar,4,true
	org.eclipse.equinox.p2.repository,2.0.2.R36x_v20110111-1500,../SDPShared/plugins/org.eclipse.equinox.p2.repository_2.0.2.R36x_v20110111-1500.jar,4,false

R17	org.eclipse.equinox.p2.reconciler.dropins,1.1.1.R36x_v20100929,../SDPShared/plugins/org.eclipse.equinox.p2.reconciler.dropins_1.1.1.R36x_v20100929.jar,4,true
	org.eclipse.equinox.p2.repository,2.0.1.R36x_v20100823,../SDPShared/plugins/org.eclipse.equinox.p2.repository_2.0.1.R36x_v20100823.jar,4,false
-----------------------------------------------------
L20	org.eclipse.equinox.p2.touchpoint.eclipse,2.0.3.R36x_v20101202,../SDPShared/plugins/org.eclipse.equinox.p2.touchpoint.eclipse_2.0.3.R36x_v20101202.jar,4,false
	org.eclipse.equinox.p2.touchpoint.natives,1.0.201.R36x_v20110111,../SDPShared/plugins/org.eclipse.equinox.p2.touchpoint.natives_1.0.201.R36x_v20110111.jar,4,false

R20	org.eclipse.equinox.p2.touchpoint.eclipse,2.0.2.R36x_v20100823,../SDPShared/plugins/org.eclipse.equinox.p2.touchpoint.eclipse_2.0.2.R36x_v20100823.jar,4,false
	org.eclipse.equinox.p2.touchpoint.natives,1.0.200.v20100503a,../SDPShared/plugins/org.eclipse.equinox.p2.touchpoint.natives_1.0.200.v20100503a.jar,4,false
Comment 12 DJ Houghton CLA 2011-02-22 16:39:12 EST
To provide an update here, the problem was only reproducible on Gary's machine and using his old .eclipse folder (which had several other older product installs). Unfortunately he is now in a state where he can't reproduce the problem any longer. 

I think a yourkit profile from the full operation might be useful if we can get back into that state. If anyone else has suggestions on what else to investigate, please add a comment.
Comment 13 Pascal Rapicault CLA 2011-02-22 22:05:01 EST
Closing as wontfix until further notice.
Comment 14 DJ Houghton CLA 2011-03-02 10:16:53 EST
For closure here, we were able to find another machine which would reproduce the same problem (with a slightly larger data set).

After some investigation we believe that it is caused by bug 338599. In my case I had a 27M content.xml file (several thousand features and bundles that had been installed via the drop-ins) and we were parsing that file, modifying it, and then re-writing it several thousand times without need.

Test teams are currently testing the fix to see if it was indeed the cause.
Comment 15 Gary Karasiuk CLA 2011-03-02 10:42:45 EST
Created attachment 190168 [details]
screenshot of profiled data

This screenshot is from the "10 minute" profile that I attached. It shows where most of the time is being spent. I don't know the code, but from the method names, it sounds like this code is involved with processing features and writing stuff out.
Comment 16 DJ Houghton CLA 2011-03-02 10:49:08 EST
This is similar to the stack that I saw when I am able to profile the whole operation in the "bad" case. Just to confirm, this is when you're running with the hacked JAR? The code in that stack (LocalMetadataRepository#addReferences) is exactly the code that we modified so I would hope not to see it here.

(my local profile snapshots after the new JAR look a lot different than before)
Comment 17 Gary Karasiuk CLA 2011-03-02 10:57:35 EST
Created attachment 190171 [details]
Screenshot from the 1 minute profile

The earlier screenshot, shows things at a "macro" level, and identifies the time being spent in this method:

org.eclipse.equinox.internal.p2.metadata.repository.io.MetadataWriter.writeInstallableUnit(IInstallableUnit)

This new screenshot is from the tracing profile, and still shows the time being spent in the writeInstallableUnit(IInstallableUnit) method but now has the extra detail of showing invocation counts, and the fan out that happens with this method.

Is this consistent with the problem that you fixed?
Comment 18 DJ Houghton CLA 2011-03-02 11:11:38 EST
Created attachment 190176 [details]
profile snapshot

Here is the snapshot that I get when running with a patched JAR.
Comment 19 Gary Karasiuk CLA 2011-03-02 11:17:39 EST
(In reply to comment #16)
> Just to confirm, this is when you're running with
> the hacked JAR? 

To clarify, the screenshots that I attached today, are based on the profiles that I attached to this defect on 2011/02/11, so they are before "the hacked jar".