Some Eclipse Foundation services are deprecated, or will be soon. Please ensure you've read this important communication.
Bug 312495 - BundleProjectDescription.apply() very slow on 1st call in clean workspace
Summary: BundleProjectDescription.apply() very slow on 1st call in clean workspace
Status: RESOLVED FIXED
Alias: None
Product: PDE
Classification: Eclipse Project
Component: UI (show other bugs)
Version: 3.6   Edit
Hardware: PC Windows XP
: P3 normal (vote)
Target Milestone: 3.7 M2   Edit
Assignee: Darin Wright CLA
QA Contact:
URL:
Whiteboard:
Keywords:
Depends on:
Blocks:
 
Reported: 2010-05-11 15:45 EDT by James Kingdon CLA
Modified: 2010-08-31 12:25 EDT (History)
7 users (show)

See Also:


Attachments
screenshot from profiling (347.65 KB, image/jpeg)
2010-05-11 15:51 EDT, James Kingdon CLA
no flags Details
New profile with more detail (891.85 KB, image/jpeg)
2010-05-12 11:37 EDT, James Kingdon CLA
no flags Details
More profile data (604.97 KB, image/jpeg)
2010-05-12 17:20 EDT, James Kingdon CLA
no flags Details
patch (6.90 KB, patch)
2010-05-13 15:33 EDT, Darin Wright CLA
no flags Details | Diff
work in progress (8.56 KB, patch)
2010-05-19 16:11 EDT, Darin Wright CLA
no flags Details | Diff
Sync'd patch (8.14 KB, patch)
2010-07-27 10:28 EDT, Ankur Sharma CLA
no flags Details | Diff
updated patch (7.82 KB, patch)
2010-07-27 12:38 EDT, Darin Wright CLA
no flags Details | Diff
update (8.05 KB, patch)
2010-08-31 12:22 EDT, Darin Wright CLA
no flags Details | Diff

Note You need to log in before you can comment on or make changes to this bug.
Description James Kingdon CLA 2010-05-11 15:45:12 EDT
Build Identifier: 3.6.0.v20100405

I am working on an adopting product which calls org.eclipse.pde.internal.core.project.BundleProjectDescription.apply() when creating a new project. I am investigating a performance issue where the first new project created in a clean workspace takes approximately 2 minutes to complete, compared to roughly o.5s for subsequent projects. I gathered some profiling data which indicated that 66s was spent in BundleProjectDescription.apply() (screenshot attached).

Is there any possibility of speeding this up, or deferring the majority of the work to a background thread to release the UI?

Reproducible: Always

Steps to Reproduce:
Regrettably I don't know how to reproduce this problem in eclipse.
With our adopting product, the problem can be reproduced by:
1. start with a clean workspace
2. create a new project
Comment 1 James Kingdon CLA 2010-05-11 15:51:16 EDT
Created attachment 168016 [details]
screenshot from profiling

Profile shows data from a single new project creation on a clean workspace. One mystery that concerns me - the profile shows an invocation count of 83 for the .apply method, but I can only account for 1 call from our code.
Comment 2 Darin Wright CLA 2010-05-11 17:01:11 EDT
And whe you put a breakpoint in BundleProjectDescription.apply(...)  how many times is it hit?
Comment 3 James Kingdon CLA 2010-05-12 10:14:25 EDT
(In reply to comment #2)
> And whe you put a breakpoint in BundleProjectDescription.apply(...)  how many
> times is it hit?

Just the once, as expected.
Comment 4 James Kingdon CLA 2010-05-12 11:37:44 EDT
Created attachment 168171 [details]
New profile with more detail

Since I usually run profiling with org.eclipse filtered out, the previous profile wasn't very helpful. I took another one with the org.eclipse packages enabled and it indicates the problem occurs while trying to resolve the classpath.
Comment 5 Tim deBoer CLA 2010-05-12 11:54:10 EDT
So it looks like the delay is setting up the platform target for the first time? On this project type we're creating a new target that's much smaller than the IDE we're running in, so my first concern is whether it is even pointing to the 'correct' target at this point.

James - Can you tell if the correct platform target is created and set as the default at this point? (e.g. either by looking at the ordering in our code, or by setting a breakpoint and looking at the path it is using)
Comment 6 James Kingdon CLA 2010-05-12 16:50:53 EDT
(In reply to comment #5)
> So it looks like the delay is setting up the platform target for the first
> time? On this project type we're creating a new target that's much smaller than
> the IDE we're running in, so my first concern is whether it is even pointing to
> the 'correct' target at this point.
> 
> James - Can you tell if the correct platform target is created and set as the
> default at this point? (e.g. either by looking at the ordering in our code, or
> by setting a breakpoint and looking at the path it is using)

At the point where we enter the PDEState constructor (the last big node in the profile screenshot) I can see that the 'target' array contains only the three entries associated with the new pde target. This looks fairly convincing evidence for the target having been set before getting into BundleProjectDescription.apply().
Comment 7 James Kingdon CLA 2010-05-12 17:20:32 EDT
Created attachment 168273 [details]
More profile data

Looks like the issue (or at least part of it) is that PDEState.readTargetState saves the existing state to a cache on disk before reading the new target.
Comment 8 Darin Wright CLA 2010-05-12 22:04:01 EDT
(In reply to comment #7)
> Created an attachment (id=168273) [details]
> More profile data
> Looks like the issue (or at least part of it) is that PDEState.readTargetState
> saves the existing state to a cache on disk before reading the new target.

This indicates that when PDE attempts to restore its OSGi state from disk on initialization, the contents of the current target are not what PDE had persisted on the last shutdown (different set of bundle URLs), so it creates the new state and then writes it to disk. Is the target being changed on startup each time? 

We did have a bug with target state not being restored properly due to bug 309795, but that was only an issue when update sites were used to define target contents (i.e. bundles downloaded from a p2 repository into a local bundle pool).
Comment 9 James Kingdon CLA 2010-05-13 09:32:08 EDT
Hi Darin,

This problem is specific to the first project in a new workspace, so nothing is persisted from a previous run. As such, it's probably working as designed, but the design is a little unfavorable for us. Writing out the previous state seems like something that could be done in the background, which would help us free up the UI much quicker.

We're in something of a worst case scenario here as our new project creation will usually change the pde target if it's the first time in the workspace, and the new project wizard is waiting for both the target state to be written and the first run of the java indexer.

James.
Comment 10 Darin Wright CLA 2010-05-13 10:26:11 EDT
PDE is not writing the previous state, it is writing the current/new state. I'm not sure why that should be slow for a small state. CC'ing Tom for any comments/insight.
Comment 11 James Kingdon CLA 2010-05-13 11:08:16 EDT
You're right, and writing the new state makes more sense.

Looking in the profiling data, the 1851 calls to StateHelperImpl.buildReferences implies that the call to saveState was with the large target (the initial default runtime target) and not the small one.

When I step through the process with the debugger in my dev env I'm getting results that are inconsistent with the profile data, suggesting that there are timing related issues that change the path taken through the code.

I'm suspicious of the way we set the PDE target, which currently happens via a callback during the BundleDescription.apply method. I'll see if we can get that changed.
Comment 12 Darin Wright CLA 2010-05-13 15:33:30 EDT
Created attachment 168457 [details]
patch

PDE agressively saves target state on creation. This patch modifies state saving to be part of the PDE's save participant.
Comment 13 Darin Wright CLA 2010-05-13 15:33:53 EDT
Consider for RC2
Comment 14 Ankur Sharma CLA 2010-05-18 14:59:42 EDT
+1 looks good to me
Comment 15 Curtis Windatt CLA 2010-05-18 16:29:49 EDT
Went through the fix and I am happy with the fix.  I'm slightly concerned about putting this in so late in the cycle, but any regressions caused by this change should only affect performance (and the fix will clearly improve the performance the user experiences).

+1 Fixed in HEAD.
Comment 16 Darin Wright CLA 2010-05-19 11:41:34 EDT
This seems to be the cause of bug 313489. Re-opening.
Comment 17 Darin Wright CLA 2010-05-19 16:11:04 EDT
Created attachment 169211 [details]
work in progress

The previous patch was incorrect. In the original state save code (that saved state agressively on creation), the state saved was only the "external target" state. By waiting untill later to save the state, we get a mix of external state and projects. I've attempted to address this in this patch, but it's still not quite right. This is very sensitive code.

Additionally, there were problems as PDE core registered 2 save participants with the workspace, which ends up with one registered. That has been addressed with the fix to bug 313590.
Comment 18 Darin Wright CLA 2010-05-19 16:11:27 EDT
Not ready for RC2.
Comment 19 Darin Wright CLA 2010-05-25 17:07:16 EDT
Not planning to fix in 3.6. Existing fix was incorrect, and this is sensitive/risky code to be changing at this point.
Comment 20 Ankur Sharma CLA 2010-07-27 10:28:05 EDT
Created attachment 175319 [details]
Sync'd patch
Comment 21 Darin Wright CLA 2010-07-27 12:38:27 EDT
Created attachment 175337 [details]
updated patch

I updated the patch with some debug/trace statements. I found an issue with state save/restore when an additional location (directory) was added to a target. There was an issue with file path names using upper vs. lower case letters for drive names which made timestamp comparison fail for the same set of files. To avoid this problem the timestamp computation was changed to use lowercase for file name hashcodes. This should be resonably safes since file timestamps are also used.
Comment 22 Darin Wright CLA 2010-08-31 12:22:13 EDT
Created attachment 177859 [details]
update

Updated patch to work with HEAD.
Comment 23 Darin Wright CLA 2010-08-31 12:25:04 EDT
Applied/Fixed.