Summary: | JavaCore.initializeAfterLoad race condition leading to incorrect deltas for external JARs | ||||||
---|---|---|---|---|---|---|---|
Product: | [Eclipse Project] JDT | Reporter: | Randall Theobald <rstheo> | ||||
Component: | Core | Assignee: | Jay Arthanareeswaran <jarthana> | ||||
Status: | VERIFIED FIXED | QA Contact: | |||||
Severity: | normal | ||||||
Priority: | P3 | CC: | benson.ning, john.arthorne, min123, Olivier_Thomann, srikanth_sankaran | ||||
Version: | 3.4.2 | ||||||
Target Milestone: | 3.5 M2 | ||||||
Hardware: | PC | ||||||
OS: | Windows XP | ||||||
Whiteboard: | |||||||
Attachments: |
|
Description
Randall Theobald
2009-08-06 13:35:26 EDT
Created attachment 143696 [details]
Patch on v895 with the mentioned addition.
Jay, please investigate. (In reply to comment #0) > Build ID: JDT: 3.4.5.v_895_R34x > > I am a performance analyst for an adopting product. This is a complicated issue > that I've been investigating aggressively for many days now. The scenario is > simple: (1) open our product with a NEW workspace, (2) disable autobuild, (3) > import the project interchange. > I was wondering if you can send me the projects (probably a smaller version?) that had this problem. Or as an alternative, a test case could also be helpful in reproducing the problem. Your patch looks fine. But I would like to see if we can avoid the race condition and catch the problem earlier. Sending just the projects will not reproduce the problem since it is not caused by the project contents, but rather the combination of plugins in our product and when the call to JavaCore.initializeAfterLoad is called. I'm not sure how to allow you to reproduce it, which is why I included as much detail and explanation as possible. (In reply to comment #0) > Build ID: JDT: 3.4.5.v_895_R34x > > We have a plugin that calls JavaCore.initializeAfterLoad after receiving a JDT > ElementChangedEvent after the project interchange is imported (basically right > after the RefreshJob completes). Can you tell me how your IElementChangedListener was registered? Did you use the following? org.eclipse.jdt.core.JavaCore.addElementChangedListener(IElementChangedListener) If that's the case, the bug should not occur because we notify the listeners only after processing the delta. Yes, that is exactly how this listener is registered. Should not and does not are, unfortunately, two very different things. :-) Could you please provide me the plug-in that you mentioned in comment #0, if that's okay? I believe we should try to avoid the race condition altogether if that's what happening here. I have the environment set up and I am seeing what I believe to be the bug. After importing the projects and after the workspace has been refreshed, there is a prolonged CPU usage for few more minutes. I also see that the Deltaprocessor#resourceChanged is invoked quite a few times consequently (the number of times is not consistent) However, I am not seeing any timestamps being null as mentioned in comment#0. All jars remain unchanged from what I see in the createExternalArchiveDelta() method. May be what I am seeing is not this bug? Continuing to investigate the multiple invocation of the resourceChanged event. (In reply to comment #0) > Build ID: JDT: 3.4.5.v_895_R34x > The big problem, though, is that the info object for the java projects might > not have been built yet, and therefore, inside > JavaModel.refreshExternalArchives (which calls) > DeltaProcessor.checkExternalArchiveChanges (which calls) > DeltaProcessor.createExternalArchiveDelta > (So now we're in createExternalArchiveDelta) > This call: > Long oldTimestamp =(Long) > this.state.getExternalLibTimeStamps().get(entryPath); > results in a null, since the DeltaProcessingState.externalTimeStamps field > hasn't been populated yet. I find that this field is initially populated by Actually getExternalLibTimeStamps() restores the presisted state and if the jar isn't recently added, the key corresponding to the external jar path should exist in DeltaProcessingState.externalTimeStamps. What am I overlooking here ? (In reply to comment #7) > Could you please provide me the plug-in that you mentioned in comment #0, if > that's okay? I believe we should try to avoid the race condition altogether if > that's what happening here. Jay/Randall, Would hacking up JavaModelManager.rememberExternalLibTimestamps to wait until after JavaCore.initializeAfterLoad has finished running make the problem consistently reproduce ? Randall, Are you in a position to test with this with 3.5 at all ? Better yet with 3.6M3 ? (In reply to comment #9) > (In reply to comment #0) [...] > Actually getExternalLibTimeStamps() restores the presisted state and if the > jar isn't recently added, the key corresponding to the external jar path > should exist in DeltaProcessingState.externalTimeStamps. > What am I overlooking here ? I missed the bit about opening the product with the new workspace. So please ignore the above. Perhaps skewing scheduling by forcing one thread to wait until after another thread has reached the problematic point as suggsted in comment#10 would help understand this issue better. After further investigation, I could not find a race condition. However, I noticed this behavior. The import operation uses the Project.open (which invokes RefreshJob). After the RefreshJob is run, JavaCore.initializeAfterLoad is called. Eventually, DelayedSnapshopJob gets invoked, which notifies the save participants - see ISaveParticipant and JavaModelManager.saving(ISaveContext). And as of 3.4, the PerProjectInfo.rememberExternalLibTimestamps was getting called inside JavaModelManager.saving(), which would remember the timestamps. But that's not what we have in HEAD. I believe this change went in as part of fix to bug 244849. As part of this, the call to rememberExternalLibTimestamps was added to DeltaProcessor (in a couple of places) Now that I believe this could be the fix, Randall, would you like a patch to test this? I also would like to post this question to John - Is it the expected behavior that the RefreshJob gets to run before the save participants get a chance? Yes, if you attach a patch, I could test this (on 3.4.5). (In reply to comment #12) > I also would like to post this question to John - Is it the expected behavior > that the RefreshJob gets to run before the save participants get a chance? Snapshot happens in the background and could occur any time there is no resource changing operation running. If a client calling IProject#open specifies the refresh should happen in the background then it will occur sometime after the open() method completes. In this case it's quite possible for a snapshot to occur either before or after the refresh job.. it just comes down to timing which job gets to run first. With a patch passed to me by Jay, I'm observing the same positive memory effects as my workaround, so I would say that his fix solves my problem. The fix made to the bug #244849 does fix this one too. This fix has introduced a call to PerProjectInfo#rememberExternalLibTimestamps() from the DeltaProcessor#elementAdded, which is essentially what is required here. This fix should be available from v_912 onwards. Fixed as part of the fix to bug #244849. Closing this one. Verified. |