Community
Participate
Working Groups
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. 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). Inside the method JavaCore.initializeAfterLoad, I see VERY different behavior at this point depending on a number of conditions. Occasionally, though this isn't the main problem, JavaModel.getJavaProjects() will return an empty array, which will skip over most of this method. I find that strange since we're only in this method because of receiving JDT deltas after the import of Java projects (55 in total). 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 org.eclipse.jdt.internal.core.JavaModelManager$PerProjectInfo.rememberExternalLibTimestamps which might ultimately be called by the DelayedSnapshotJob or by the main UI thread refreshing markers. If one of those occur before the call to get the JAR timestamp, then we properly detect that no change has occurred in the JAR. If not, we incorrectly detect that the JAR was recently added to the classpath and subsequently send out a delta. As a fix for this issue, in JavaCore.initializeAfterLoad we need to explicitly call something that will populate the DeltaProcessingState.externalTimeStamps if not yet done for new projects. One such call that I found was javaProject.getPackageFragmentRoots. When inserting this call right below the line classpath = javaProject.getResolvedClasspath(); (somewhere around line 3347) then the callstack org.eclipse.jdt.internal.core.JavaModelManager$PerProjectInfo.rememberExternalLibTimestamps org.eclipse.jdt.internal.core.JavaProject.buildStructure org.eclipse.jdt.internal.core.Openable.generateInfos org.eclipse.jdt.internal.core.JavaElement.openWhenClosed org.eclipse.jdt.internal.core.JavaElement.getElementInfo org.eclipse.jdt.internal.core.JavaElement.getElementInfo org.eclipse.jdt.internal.core.JavaElement.getChildren org.eclipse.jdt.internal.core.JavaProject.getPackageFragmentRoots org.eclipse.jdt.core.JavaCore.initializeAfterLoad was executed in-thread, eliminating the race condition and never generating spurious deltas on the external JARs. If a fix for this is possible on the 3.4 maintenance stream, that would be best. As additional background, this is important to us because we are using the deltas to create a Java search scope. We do not need all the runtime JARs in this scope, and doing a search with them in the scope adds about 25 MB to our live heap, forever kept in the JavaModelCache(yes, there are lots of runtime JARs that get added). We can work around the issue (for example by iterating through the projects and calling getPackageFragmentRoots before we ever call JavaCore.initializeAfterLoad), but I wanted to make sure that the root cause would be fixed going forward, hence this bug.
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.
