Bugzilla – Full Text Bug Listing
| Summary: | BundleProjectDescription.apply() very slow on 1st call in clean workspace | ||||||||||||||||||||
|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|
| Product: | [Eclipse Project] PDE | Reporter: | James Kingdon <jkingdon> | ||||||||||||||||||
| Component: | UI | Assignee: | Darin Wright <darin.eclipse> | ||||||||||||||||||
| Status: | RESOLVED FIXED | QA Contact: | |||||||||||||||||||
| Severity: | normal | ||||||||||||||||||||
| Priority: | P3 | CC: | ankur_sharma, curtis.windatt.public, daniel_megert, darin.eclipse, deboer, rtaniwa, tjwatson | ||||||||||||||||||
| Version: | 3.6 | ||||||||||||||||||||
| Target Milestone: | 3.7 M2 | ||||||||||||||||||||
| Hardware: | PC | ||||||||||||||||||||
| OS: | Windows XP | ||||||||||||||||||||
| Whiteboard: | |||||||||||||||||||||
| Attachments: |
|
||||||||||||||||||||
|
Description
James Kingdon
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.
And whe you put a breakpoint in BundleProjectDescription.apply(...) how many times is it hit? (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. 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.
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) (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(). 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.
(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). 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. 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. 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. 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.
Consider for RC2 +1 looks good to me 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. This seems to be the cause of bug 313489. Re-opening. 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. Not ready for RC2. Not planning to fix in 3.6. Existing fix was incorrect, and this is sensitive/risky code to be changing at this point. Created attachment 175319 [details]
Sync'd patch
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.
Created attachment 177859 [details]
update
Updated patch to work with HEAD.
Applied/Fixed. |