Bug 307040 - Search Job with HierarchyScope on Object does not cancel
Summary: Search Job with HierarchyScope on Object does not cancel
Status: VERIFIED FIXED
Alias: None
Product: JDT
Classification: Eclipse Project
Component: Core (show other bugs)
Version: 3.6   Edit
Hardware: PC Windows XP
: P3 normal (vote)
Target Milestone: 3.6 RC1   Edit
Assignee: Satyam Kandula CLA
QA Contact:
URL:
Whiteboard:
Keywords:
Depends on:
Blocks:
 
Reported: 2010-03-25 07:32 EDT by Markus Keller CLA
Modified: 2010-05-17 11:48 EDT (History)
2 users (show)

See Also:
Olivier_Thomann: review+
markus.kell.r: review+


Attachments
Patch (1.01 KB, patch)
2010-04-05 05:56 EDT, Satyam Kandula CLA
no flags Details | Diff
Patch (13.40 KB, patch)
2010-04-29 02:57 EDT, Satyam Kandula CLA
Olivier_Thomann: iplog+
Olivier_Thomann: review+
Details | Diff

Note You need to log in before you can comment on or make changes to this bug.
Description Markus Keller CLA 2010-03-25 07:32:17 EDT
HEAD

- open org.eclipse.core.internal.resources.Resource#hashCode()
- hold Ctrl, hover over hashCode in "getFullPath().hashCode()"
- click "Open Implementation"
- after a while, realize that this will take a long time, and click the Cancel button in the workbench window status line
=> takes about a minute to cancel

Below are a few stacktraces I took while waiting. The monitor should be checked more often for cancellation.

"ModalContext" prio=6 tid=0x2a7d4800 nid=0x19f4 runnable [0x3369f000]
   java.lang.Thread.State: RUNNABLE
        at org.eclipse.jdt.internal.core.search.HierarchyScope.buildResourceVector(HierarchyScope.java:146)
        at org.eclipse.jdt.internal.core.search.HierarchyScope.initialize(HierarchyScope.java:433)
        at org.eclipse.jdt.internal.core.search.HierarchyScope.encloses(HierarchyScope.java:268)
        at org.eclipse.jdt.core.search.SearchPattern.acceptMatch(SearchPattern.java:298)
        at org.eclipse.jdt.core.search.SearchPattern.findIndexMatches(SearchPattern.java:2307)
        at org.eclipse.jdt.internal.core.search.matching.MatchLocator.findIndexMatches(MatchLocator.java:264)
        at org.eclipse.jdt.internal.core.search.PatternSearchJob.search(PatternSearchJob.java:97)
        at org.eclipse.jdt.internal.core.search.PatternSearchJob.execute(PatternSearchJob.java:63)
        at org.eclipse.jdt.internal.core.search.processing.JobManager.performConcurrentJob(JobManager.java:276)
        at org.eclipse.jdt.internal.core.search.BasicSearchEngine.findMatches(BasicSearchEngine.java:214)
        at org.eclipse.jdt.internal.core.search.BasicSearchEngine.search(BasicSearchEngine.java:515)
        at org.eclipse.jdt.core.search.SearchEngine.search(SearchEngine.java:582)
        at org.eclipse.jdt.internal.ui.javaeditor.JavaElementImplementationHyperlink$1.run(JavaElementImplementationHyperlink.java:242)
        at org.eclipse.jface.operation.ModalContext$ModalContextThread.run(ModalContext.java:121)


"ModalContext" prio=6 tid=0x2aacf800 nid=0x8b4 runnable [0x347fe000]
   java.lang.Thread.State: RUNNABLE
        at org.eclipse.jdt.internal.compiler.parser.Scanner.getNextToken(Scanner.java:1082)
        at org.eclipse.jdt.internal.compiler.parser.Parser.parse(Parser.java:9311)
        at org.eclipse.jdt.internal.compiler.parser.Parser.parse(Parser.java:9605)
        at org.eclipse.jdt.internal.compiler.parser.Parser.parse(Parser.java:9562)
        at org.eclipse.jdt.internal.compiler.parser.Parser.dietParse(Parser.java:8155)
        at org.eclipse.jdt.internal.core.hierarchy.HierarchyResolver.resolve(HierarchyResolver.java:682)
        at org.eclipse.jdt.internal.core.hierarchy.IndexBasedHierarchyBuilder.buildForProject(IndexBasedHierarchyBuilder.java:226)
        at org.eclipse.jdt.internal.core.hierarchy.IndexBasedHierarchyBuilder.buildFromPotentialSubtypes(IndexBasedHierarchyBuilder.java:306)
        at org.eclipse.jdt.internal.core.hierarchy.IndexBasedHierarchyBuilder.build(IndexBasedHierarchyBuilder.java:131)
        at org.eclipse.jdt.internal.core.hierarchy.TypeHierarchy.compute(TypeHierarchy.java:300)
        at org.eclipse.jdt.internal.core.hierarchy.TypeHierarchy.refresh(TypeHierarchy.java:1263)
        - locked <0x17dc5150> (a org.eclipse.jdt.internal.core.hierarchy.TypeHierarchy)
        at org.eclipse.jdt.internal.core.CreateTypeHierarchyOperation.executeOperation(CreateTypeHierarchyOperation.java:90)
        at org.eclipse.jdt.internal.core.JavaModelOperation.run(JavaModelOperation.java:728)
        at org.eclipse.jdt.internal.core.JavaModelOperation.runOperation(JavaModelOperation.java:788)
        at org.eclipse.jdt.internal.core.BinaryType.newTypeHierarchy(BinaryType.java:918)
        at org.eclipse.jdt.internal.core.search.HierarchyScope.initialize(HierarchyScope.java:428)
        at org.eclipse.jdt.internal.core.search.HierarchyScope.encloses(HierarchyScope.java:268)
        at org.eclipse.jdt.core.search.SearchPattern.acceptMatch(SearchPattern.java:298)
        at org.eclipse.jdt.core.search.SearchPattern.findIndexMatches(SearchPattern.java:2307)
        at org.eclipse.jdt.internal.core.search.matching.MatchLocator.findIndexMatches(MatchLocator.java:264)
        at org.eclipse.jdt.internal.core.search.PatternSearchJob.search(PatternSearchJob.java:97)
        at org.eclipse.jdt.internal.core.search.PatternSearchJob.execute(PatternSearchJob.java:63)
        at org.eclipse.jdt.internal.core.search.processing.JobManager.performConcurrentJob(JobManager.java:276)
        at org.eclipse.jdt.internal.core.search.BasicSearchEngine.findMatches(BasicSearchEngine.java:214)
        at org.eclipse.jdt.internal.core.search.BasicSearchEngine.search(BasicSearchEngine.java:515)
        at org.eclipse.jdt.core.search.SearchEngine.search(SearchEngine.java:582)
        at org.eclipse.jdt.internal.ui.javaeditor.JavaElementImplementationHyperlink$1.run(JavaElementImplementationHyperlink.java:242)
        at org.eclipse.jface.operation.ModalContext$ModalContextThread.run(ModalContext.java:121)


"ModalContext" prio=6 tid=0x2acfe400 nid=0x1d00 runnable [0x3756e000]
   java.lang.Thread.State: RUNNABLE
        at java.util.Arrays.copyOf(Arrays.java:2882)
        at java.lang.StringValue.from(StringValue.java:24)
        at java.lang.String.<init>(String.java:178)
        at org.eclipse.jdt.internal.core.SearchableEnvironment.isPackage(SearchableEnvironment.java:673)
        at org.eclipse.jdt.internal.compiler.lookup.LookupEnvironment.isPackage(LookupEnvironment.java:1311)
        at org.eclipse.jdt.internal.compiler.lookup.PackageBinding.findPackage(PackageBinding.java:77)
        at org.eclipse.jdt.internal.compiler.lookup.PackageBinding.getPackage(PackageBinding.java:98)
        at org.eclipse.jdt.internal.compiler.lookup.CompilationUnitScope.buildTypeBindings(CompilationUnitScope.java:128)
        at org.eclipse.jdt.internal.compiler.lookup.LookupEnvironment.buildTypeBindings(LookupEnvironment.java:153)
        at org.eclipse.jdt.internal.core.hierarchy.HierarchyResolver.resolve(HierarchyResolver.java:690)
        at org.eclipse.jdt.internal.core.hierarchy.IndexBasedHierarchyBuilder.buildForProject(IndexBasedHierarchyBuilder.java:226)
        at org.eclipse.jdt.internal.core.hierarchy.IndexBasedHierarchyBuilder.buildFromPotentialSubtypes(IndexBasedHierarchyBuilder.java:306)
        at org.eclipse.jdt.internal.core.hierarchy.IndexBasedHierarchyBuilder.build(IndexBasedHierarchyBuilder.java:131)
        at org.eclipse.jdt.internal.core.hierarchy.TypeHierarchy.compute(TypeHierarchy.java:300)
        at org.eclipse.jdt.internal.core.hierarchy.TypeHierarchy.refresh(TypeHierarchy.java:1263)
        - locked <0x168bebf8> (a org.eclipse.jdt.internal.core.hierarchy.TypeHierarchy)
        at org.eclipse.jdt.internal.core.CreateTypeHierarchyOperation.executeOperation(CreateTypeHierarchyOperation.java:90)
        at org.eclipse.jdt.internal.core.JavaModelOperation.run(JavaModelOperation.java:728)
        at org.eclipse.jdt.internal.core.JavaModelOperation.runOperation(JavaModelOperation.java:788)
        at org.eclipse.jdt.internal.core.BinaryType.newTypeHierarchy(BinaryType.java:918)
        at org.eclipse.jdt.internal.core.search.HierarchyScope.initialize(HierarchyScope.java:428)
        at org.eclipse.jdt.internal.core.search.HierarchyScope.encloses(HierarchyScope.java:268)
        at org.eclipse.jdt.core.search.SearchPattern.acceptMatch(SearchPattern.java:298)
        at org.eclipse.jdt.core.search.SearchPattern.findIndexMatches(SearchPattern.java:2307)
        at org.eclipse.jdt.internal.core.search.matching.MatchLocator.findIndexMatches(MatchLocator.java:264)
        at org.eclipse.jdt.internal.core.search.PatternSearchJob.search(PatternSearchJob.java:97)
        at org.eclipse.jdt.internal.core.search.PatternSearchJob.execute(PatternSearchJob.java:63)
        at org.eclipse.jdt.internal.core.search.processing.JobManager.performConcurrentJob(JobManager.java:276)
        at org.eclipse.jdt.internal.core.search.BasicSearchEngine.findMatches(BasicSearchEngine.java:214)
        at org.eclipse.jdt.internal.core.search.BasicSearchEngine.search(BasicSearchEngine.java:515)
        at org.eclipse.jdt.core.search.SearchEngine.search(SearchEngine.java:582)
        at org.eclipse.jdt.internal.ui.javaeditor.JavaElementImplementationHyperlink$1.run(JavaElementImplementationHyperlink.java:242)
        at org.eclipse.jface.operation.ModalContext$ModalContextThread.run(ModalContext.java:121)
Comment 1 Olivier Thomann CLA 2010-03-31 10:15:13 EDT
Satyam, please investigate. We should check cancellation more often.
Comment 2 Satyam Kandula CLA 2010-04-05 05:56:27 EDT
Created attachment 163799 [details]
Patch

Markus,
I am able to see a long time gap before the operation gets cancelled, but the call stacks I see are slightly different from the ones you see. For me, the cancel doesn't happen quickly after the search is returned and while the hierarchy is getting connected. I kept a cancellation check at the place that works for me. Can you verify if this patch also works for you?
Comment 3 Markus Keller CLA 2010-04-20 13:47:09 EDT
(In reply to comment #2)
This patch doesn't really help. I still see the implementation looping in HierarchyResolver#resolve(Openable[], HashSet, IProgressMonitor).

The problem seems to be that
    HierarchyScope.initialize() line: 428
creates the hierarchy with a null progress monitor, so your check for
    progressMonitor.isCanceled()
always returns false, see JavaModelOperation#isCanceled().

Apart from that, your check is only hit every few seconds. I think you should add more checks in the top-level "for" loops in HierarchyResolver#resolve(..) (a check in each of the loops over openables and parsedUnits).
Comment 4 Olivier Thomann CLA 2010-04-22 13:39:57 EDT
This should be fixed for 3.6RC1.
Comment 5 Satyam Kandula CLA 2010-04-28 04:51:17 EDT
(In reply to comment #3)
Markus, Thanks for your comments. I wasn't seeing much time taken in the same call stack as you were seeing. Now, I could see that with a big workspace and understand what you are talking about. As the progress monitor is not being passed, it is not getting canceled. I am working on it and will try to give you a new patch.
Comment 6 Satyam Kandula CLA 2010-04-29 02:57:09 EDT
Created attachment 166433 [details]
Patch

In this patch, the progress monitor is passed to the HierarchyScope#encloses. Some cancel checks before some time consuming methods are also been added.

I think the clean fix could have been adding a new api IJavaSearchScope#encloses(String, IProgressMonitor). As we have passed the API freeze, we could probably do that in 3.7. 
I could manage to get the IProgressMonitor passed to only the HierarchyScope without adding the new API. I still need to pass the extra parameter and for that, I had to add some public/protected functions in SearchPattern  and some internal classes. To be on the safer side, I have retained the original functions in all the classes. The comment for the original function in SearchPattern tells that the clients should not be using or overriding it. Hence, I think adding another function with an additional parameter is fine here. 
Olivier, What are your comments?
Comment 7 Olivier Thomann CLA 2010-05-04 10:32:22 EDT
We cannot easily add IJavaSearchScope#encloses(String, IProgressMonitor) as this interface is not tagged as ­@noimplement.
So we have to leave with this patch and the additional casting.
I'll finish the review today.
Comment 8 Olivier Thomann CLA 2010-05-04 12:58:36 EDT
I tried the patch and even if it looks good.
What is supposed to happen when clicking on "Open implementation"?

I get two background jobs that can be properly canceled, but once they are done, the UI is frozen for a few seconds and then nothing is open.

So the patch does seem to improve the cancellation of jobs, but the UI is frozen with or without it.
Comment 9 Olivier Thomann CLA 2010-05-04 12:58:49 EDT
+1 for RC1.
Comment 10 Olivier Thomann CLA 2010-05-04 14:05:02 EDT
Markus, if you confirm that this improves the cancellation in your case, I'll release it.
I tried myself and it seems to improve it.
Comment 11 Olivier Thomann CLA 2010-05-05 12:09:09 EDT
Released for 3.6RC1.
Updated regression test in:
org.eclipse.jdt.core.tests.model.TypeHierarchyTests#testEfficiencyMultipleProjects
Comment 12 Markus Keller CLA 2010-05-05 12:34:22 EDT
Looks good, but I still see longer delays occasionally. To find out where too
much time passes between cancel checks, I changed
org.eclipse.jface.action.StatusLine#isCanceled() to this:

private long lastCancelCheck= 0;
private Exception lastCancelTrace;

/**
 * Returns true if the user does some UI action to cancel this operation.
 * (like hitting the Cancel button on the progress dialog). The long running
 * operation typically polls isCanceled().
 */
public boolean isCanceled() {
    long now = System.currentTimeMillis();
    long delay = now -lastCancelCheck;
    if (delay > 5000 && lastCancelTrace != null) {
        lastCancelTrace.printStackTrace();
        System.out.println(delay / 1000); //breakpoint
    }
    lastCancelTrace= new Exception("too long gap between isCanceled()");
    lastCancelCheck= System.currentTimeMillis();
    return fIsCanceled;
}

=> When you set the breakpoint and then start the search, you'll have to resume
once, and then the debugger will stop at places where it would have taken
longer than 5 seconds to cancel. In the console, you see the stacktrace that
shows where the last check happened, and in the Debug view, you see where the
next check happens. In between, there should be more checks.

When I added another check right after
    for (int i = 0; i < openablesLength; i++)
, then it looked perfect.

But you also have my +1 if you decide not to add that.
Comment 13 Frederic Fusier CLA 2010-05-06 07:55:07 EDT
(In reply to comment #11)
> Released for 3.6RC1.

I'm a little bit afraid this patch can have performance impact. Adding instanceof HierarchyScope at several key places in SearchEngine code will surely have a non negligible cost... :-(

Anyway, we'll see the performance JDT/Core search results in the next I-build... Waiting for that, Satyam, did you have run the Search performance tests using your patch? Also, I'll run them on my linux machine using v_A50 to see whether my fear is legitimate or not...
Comment 14 Satyam Kandula CLA 2010-05-06 08:13:42 EDT
I did not run the tests -- did not expect considerable slow down. I will run the tests and let you know.
Comment 15 Frederic Fusier CLA 2010-05-11 09:44:41 EDT
I've run JDT/Core search performance tests for v_A49 and v_A50 versions and didn't see any noticeable time degradation. I-build performance results also show the same, hence there's no reason not to keep the fix in :-)
Comment 16 Frederic Fusier CLA 2010-05-17 11:48:51 EDT
Verified for 3.6RC1 using I20100513-1500.