Bug 138377 - [patch] [console] [source lookup] Clicking on Java stack trace hyperlink in console is unusably slow again
Summary: [patch] [console] [source lookup] Clicking on Java stack trace hyperlink in c...
Status: RESOLVED FIXED
Alias: None
Product: JDT
Classification: Eclipse Project
Component: Debug (show other bugs)
Version: 3.2   Edit
Hardware: All All
: P2 major with 12 votes (vote)
Target Milestone: 3.8 M7   Edit
Assignee: Michael Rennie CLA
QA Contact:
URL:
Whiteboard:
Keywords: performance
: 322202 (view as bug list)
Depends on:
Blocks:
 
Reported: 2006-04-25 10:30 EDT by Markus Keller CLA
Modified: 2012-05-02 11:17 EDT (History)
11 users (show)

See Also:


Attachments
trial run of indexed search (3.58 KB, patch)
2006-04-25 17:14 EDT, Michael Rennie CLA
no flags Details | Diff
patch (4.56 KB, patch)
2011-05-03 13:37 EDT, Michael Rennie CLA
no flags Details | Diff
patch 2 (4.97 KB, patch)
2011-05-03 14:40 EDT, Markus Keller CLA
no flags Details | Diff
patch 3 (9.57 KB, patch)
2011-08-08 06:01 EDT, Markus Keller CLA
no flags Details | Diff

Note You need to log in before you can comment on or make changes to this bug.
Description Markus Keller CLA 2006-04-25 10:30:20 EDT
N20060425-0010

With the fix for bug 112774, perfomance of target resolution became acceptable (at least for the second and later clicks). But in lastest builds, perfomance has become unusable again. I am blocked for about 30 seconds for each click now.
Comment 1 Dani Megert CLA 2006-04-25 11:11:03 EDT
Saw the same thing too.
Comment 2 Darin Wright CLA 2006-04-25 11:23:50 EDT
Please investigate, Mike.
Comment 3 Michael Rennie CLA 2006-04-25 17:14:36 EDT
Created attachment 39474 [details]
trial run of indexed search

This patch is a test case for using jdt's searching capabilities, to see if we can out-perform the old way of searching for types by using the available indexed searching.

Please apply and try this patch, I noticed an improvement on my machine, but that does not mean it will work the same on everyone elses...
Comment 4 Darin Wright CLA 2006-04-26 00:06:49 EDT
For me, this fix feels about the same as the original implementation. However, I noticed that #linkActivated() was being called twice each time I cliked on a link.
Comment 5 Markus Keller CLA 2006-04-26 13:39:04 EDT
I also tried the patch, and it also feels about the same here. But the global search does not find the right version of JRE classes any more, which makes the patch worse than HEAD for me.

If the perfomance improvement from earlier builds is not achievable any more, I guess a (cancellable) progress indication would already relieve the problem a bit.
Comment 6 Darin Wright CLA 2006-05-01 15:33:50 EDT
I think this may just be a progress reporting issue. When we invoke a search on the Java model the first time, it may invoke indexing, and we block while that completes rather than offering a progress dialog showing what is happening.
Comment 7 Dani Megert CLA 2006-05-01 15:44:50 EDT
Mmh. It should simply not take that long - 30s is really too long.
Comment 8 Darin Wright CLA 2006-05-02 17:37:29 EDT
Deferred
Comment 9 Denis Roy CLA 2009-08-30 02:22:46 EDT
As of now 'LATER' and 'REMIND' resolutions are no longer supported.
Please reopen this bug if it is still valid for you.
Comment 10 Michael Rennie CLA 2010-08-10 10:41:21 EDT
reopening this is still a problem
Comment 11 Michael Rennie CLA 2010-08-10 10:41:44 EDT
*** Bug 322202 has been marked as a duplicate of this bug. ***
Comment 12 Dani Megert CLA 2011-02-02 05:32:24 EST
Something needs to be done here. I and other people still often run into this (especially the first time I click on a link).

Joh, can you attach some stack dumps?
Comment 13 Johannes Rieken CLA 2011-02-02 06:22:57 EST
> Joh, can you attach some stack dumps?

Name: Worker-166
State: RUNNABLE
Total blocked: 255  Total waited: 390

Stack trace: 
java.lang.Class.isAssignableFrom(Native Method)
com.ibm.team.filesystem.client.internal.PathLocation.getAdapter(PathLocation.java:71)
com.ibm.team.filesystem.client.internal.ManagedFileSystem.expandUri(ManagedFileSystem.java:145)
com.ibm.team.filesystem.client.internal.ManagedFileSystem.getStore(ManagedFileSystem.java:62)
org.eclipse.core.internal.filesystem.InternalFileSystemCore.getStore(InternalFileSystemCore.java:107)
org.eclipse.core.filesystem.EFS.getStore(EFS.java:470)
org.eclipse.core.internal.localstore.FileSystemResourceManager.getFileURI(FileSystemResourceManager.java:157)
org.eclipse.core.internal.localstore.FileSystemResourceManager.allPathsForLocationNonCanonical(FileSystemResourceManager.java:84)
org.eclipse.core.internal.localstore.FileSystemResourceManager.allPathsForLocation(FileSystemResourceManager.java:57)
org.eclipse.core.internal.localstore.FileSystemResourceManager.allResourcesFor(FileSystemResourceManager.java:198)
org.eclipse.core.internal.resources.WorkspaceRoot.findFilesForLocationURI(WorkspaceRoot.java:112)
org.eclipse.core.internal.resources.WorkspaceRoot.findFilesForLocationURI(WorkspaceRoot.java:103)
org.eclipse.core.internal.resources.WorkspaceRoot.findFilesForLocation(WorkspaceRoot.java:96)
org.eclipse.jdt.internal.launching.RuntimeClasspathEntry.getResource(RuntimeClasspathEntry.java:328)
org.eclipse.jdt.internal.launching.RuntimeClasspathEntry.resolveToOSPath(RuntimeClasspathEntry.java:460)
org.eclipse.jdt.internal.launching.RuntimeClasspathEntry.getLocation(RuntimeClasspathEntry.java:449)
org.eclipse.jdt.internal.launching.JavaSourceLookupUtil.getPackageFragmentRoot(JavaSourceLookupUtil.java:175)
org.eclipse.jdt.internal.launching.JavaSourceLookupUtil.translate(JavaSourceLookupUtil.java:58)
org.eclipse.jdt.launching.JavaRuntime.getSourceContainers(JavaRuntime.java:2380)
org.eclipse.jdt.launching.sourcelookup.containers.JavaSourcePathComputer.computeSourceContainers(JavaSourcePathComputer.java:58)
org.eclipse.debug.internal.core.sourcelookup.SourcePathComputer.computeSourceContainers(SourcePathComputer.java:69)
org.eclipse.debug.core.sourcelookup.containers.DefaultSourceContainer.createSourceContainers(DefaultSourceContainer.java:112)
org.eclipse.debug.core.sourcelookup.containers.CompositeSourceContainer.getSourceContainers(CompositeSourceContainer.java:129)
   - locked org.eclipse.debug.core.sourcelookup.containers.DefaultSourceContainer@4d1079
org.eclipse.debug.core.sourcelookup.containers.CompositeSourceContainer.findSourceElements(CompositeSourceContainer.java:46)
org.eclipse.debug.core.sourcelookup.AbstractSourceLookupParticipant.findSourceElements(AbstractSourceLookupParticipant.java:67)
org.eclipse.debug.core.sourcelookup.AbstractSourceLookupDirector$SourceLookupQuery.run(AbstractSourceLookupDirector.java:141)
org.eclipse.core.runtime.SafeRunner.run(SafeRunner.java:42)
org.eclipse.debug.core.sourcelookup.AbstractSourceLookupDirector.findSourceElements(AbstractSourceLookupDirector.java:742)
org.eclipse.pde.internal.launching.sourcelookup.PDESourceLookupDirector.findSourceElements(PDESourceLookupDirector.java:86)
org.eclipse.jdt.internal.debug.core.JavaDebugUtils.resolveSourceElement(JavaDebugUtils.java:319)
org.eclipse.jdt.internal.debug.ui.console.JavaStackTraceHyperlink$1.run(JavaStackTraceHyperlink.java:102)
org.eclipse.core.internal.jobs.Worker.run(Worker.java:54)
Comment 14 Johannes Rieken CLA 2011-02-02 06:23:55 EST
Took around one minute the first time I clicked. Subsequent calls where faster, but not fast (depending on the file)
Comment 15 Dani Megert CLA 2011-02-02 06:31:29 EST
Can you check whether the time is burnt inside com.ibm.team.filesystem.client.internal.* or by too many calls to it?
Comment 16 Dani Megert CLA 2011-02-04 07:12:25 EST
Below is a slightly different dump. What I observe is that it is very slow when I click the first time on a link in the console. Further links open with acceptable performance. However, this happens for each lunch/console.


"Worker-7" prio=6 tid=0x235d7400 nid=0x1bc0 runnable [0x259ff000]
   java.lang.Thread.State: RUNNABLE
        at java.lang.String.hashCode(String.java:1488)
        at org.eclipse.core.runtime.Path.computeHashCode(Path.java:409)
        at org.eclipse.core.runtime.Path.initialize(Path.java:605)
        at org.eclipse.core.runtime.Path.<init>(Path.java:163)
        at org.eclipse.core.filesystem.URIUtil.toURI(URIUtil.java:108)
        at org.eclipse.core.internal.filesystem.local.LocalFile.toURI(LocalFile.java:431)
        at org.eclipse.core.internal.localstore.FileStoreRoot.computeURI(FileStoreRoot.java:76)
        at org.eclipse.core.internal.localstore.FileSystemResourceManager.locationURIFor(FileSystemResourceManager.java:692)
        at org.eclipse.core.internal.resources.Resource.getLocationURI(Resource.java:1132)
        at org.eclipse.core.internal.localstore.FileSystemResourceManager.allPathsForLocationNonCanonical(FileSystemResourceManager.java:79)
        at org.eclipse.core.internal.localstore.FileSystemResourceManager.allPathsForLocation(FileSystemResourceManager.java:58)
        at org.eclipse.core.internal.localstore.FileSystemResourceManager.allResourcesFor(FileSystemResourceManager.java:199)
        at org.eclipse.core.internal.resources.WorkspaceRoot.findContainersForLocationURI(WorkspaceRoot.java:88)
        at org.eclipse.core.internal.resources.WorkspaceRoot.findContainersForLocationURI(WorkspaceRoot.java:79)
        at org.eclipse.core.internal.resources.WorkspaceRoot.findContainersForLocation(WorkspaceRoot.java:72)
        at org.eclipse.jdt.internal.launching.RuntimeClasspathEntry.getResource(RuntimeClasspathEntry.java:332)
        at org.eclipse.jdt.internal.launching.RuntimeClasspathEntry.getResource(RuntimeClasspathEntry.java:312)
        at org.eclipse.pde.launching.PDESourcePathProvider.resolveClasspath(PDESourcePathProvider.java:102)
        at org.eclipse.jdt.internal.launching.RuntimeClasspathProvider.resolveClasspath(RuntimeClasspathProvider.java:60)
        at org.eclipse.jdt.launching.JavaRuntime.resolveSourceLookupPath(JavaRuntime.java:822)
        at org.eclipse.jdt.launching.sourcelookup.containers.JavaSourcePathComputer.computeSourceContainers(JavaSourcePathComputer.java:57)
        at org.eclipse.debug.internal.core.sourcelookup.SourcePathComputer.computeSourceContainers(SourcePathComputer.java:69)
        at org.eclipse.debug.core.sourcelookup.containers.DefaultSourceContainer.createSourceContainers(DefaultSourceContainer.java:112)
        at org.eclipse.debug.core.sourcelookup.containers.CompositeSourceContainer.getSourceContainers(CompositeSourceContainer.java:129)
        - locked <0x15370778> (a org.eclipse.debug.core.sourcelookup.containers.DefaultSourceContainer)
        at org.eclipse.debug.core.sourcelookup.containers.CompositeSourceContainer.findSourceElements(CompositeSourceContainer.java:46)
        at org.eclipse.debug.core.sourcelookup.AbstractSourceLookupParticipant.findSourceElements(AbstractSourceLookupParticipant.java:67)
        at org.eclipse.debug.core.sourcelookup.AbstractSourceLookupDirector$SourceLookupQuery.run(AbstractSourceLookupDirector.java:141)
        at org.eclipse.core.runtime.SafeRunner.run(SafeRunner.java:42)
        at org.eclipse.debug.core.sourcelookup.AbstractSourceLookupDirector.findSourceElements(AbstractSourceLookupDirector.java:742)
        at org.eclipse.pde.internal.launching.sourcelookup.PDESourceLookupDirector.findSourceElements(PDESourceLookupDirector.java:86)
        at org.eclipse.jdt.internal.debug.core.JavaDebugUtils.resolveSourceElement(JavaDebugUtils.java:319)
        at org.eclipse.jdt.internal.debug.ui.console.JavaStackTraceHyperlink$1.run(JavaStackTraceHyperlink.java:102)
        at org.eclipse.core.internal.jobs.Worker.run(Worker.java:54)
Comment 17 Peter Woods CLA 2011-02-24 04:05:39 EST
Is it worth pointing out that if I select the class's name from the log and use ctrl-shift-t to find it, then ctrl-l for the line number, then I can get to the destination almost instantly?

So I (possibly naively) think that the way the hyperlinks are being looked up is simply being done in the wrong way, as I can do it manually much more quickly.
Comment 18 Markus Keller CLA 2011-02-24 08:14:14 EST
> So I (possibly naively) think that the way the hyperlinks are being looked up
> is simply being done in the wrong way, as I can do it manually much more
> quickly.

AFAIK, the current implementation is supposed to find the right version of a type even if there are multiple versions in the workspace (which e.g. happens if multiple versions of the same plug-in are installed, or if the type is from a JRE and you have multiple JREs installed).

Debug team: If you don't have the resources to do an in-depth analysis, then an easier intermediate fix could be to just reverse the order of lookups in JavaStackTraceHyperlink#startSourceSearch(String, int):

Currently, you do the expensive lookup based on the actual classpath, and only if that fails, you fall back to finding the first match in the whole workspace using SearchEngine#searchAllTypeNames(..). Since the SearchEngine index is always fast, you could first do the full search (but collect all matches). If that finds exactly 1 match, then go for it. Otherwise, fall back to the expensive lookup.
Comment 19 Randy Hudson CLA 2011-03-18 11:10:26 EDT
I see this problem all the time.  Does anyone know a workaround to make things faster?  It seems like even when the Type could only resolve to one place, it still takes a long time.  Should I remove VM definitions?  Look for duplicate bundles?
Comment 20 Michael Rennie CLA 2011-05-03 13:37:20 EDT
Created attachment 194615 [details]
patch

Here is a patch that switches the search operations as Markus suggested.

It would make sense that the original ordering would take longer on the first launch as it uses the source lookup code which has to initialize itself and perform some other start-up operations and *then* start looking for the type.

Testing the patch so far on a small / medium (5 - 20 bundles) sized workspace I did not notice an appreciable difference in performance. I suspect you could really kill performance by having a large-ish workspace with a lot of entries on the source lookup path.
Comment 21 Markus Keller CLA 2011-05-03 14:40:39 EDT
Created attachment 194625 [details]
patch 2

(In reply to comment #20)
The patch misses this part of comment 18:
> you could first do the full search (but collect all matches). If
> that finds exactly 1 match, then go for it.

OpenTypeAction#findTypeInWorkspace(String) just returns the first match. That's fine for a fallback, but it's not OK as the first strategy. If the workspace contains > 1 match (e.g. if the user has more than 1 installed JRE), then you'd just get an arbitrary type.

Patch 2 fixes that problem.

However, there's another potential problem: I'm not too familiar with the source lookup feature, but if it's so extensible that clients can contribute their own resolvers that also find sources outside of the workspace, then Patch 2 can still change the result iff there's exactly 1 type with the given name in the workspace but a contributed resolver finds a different type from outside of the workspace.
Comment 22 Michael Rennie CLA 2011-05-04 09:54:29 EDT
(In reply to comment #21)

> Patch 2 fixes that problem.
> 

Thanks for a complete patch Markus, mine was just a half-baked attempt to see if there was a noticeable difference in performance by switching the look-up order

> However, there's another potential problem: I'm not too familiar with the
> source lookup feature, but if it's so extensible that clients can contribute
> their own resolvers that also find sources outside of the workspace, then Patch
> 2 can still change the result iff there's exactly 1 type with the given name in
> the workspace but a contributed resolver finds a different type from outside of
> the workspace.

You are correct, that a contributed source look-up director *could* resolve a location anywhere.
Comment 23 James Fry CLA 2011-05-04 12:01:27 EDT
(In reply to comment #20)
> Created attachment 194615 [details]
> patch
> Here is a patch that switches the search operations as Markus suggested.
> It would make sense that the original ordering would take longer on the first
> launch as it uses the source lookup code which has to initialize itself and
> perform some other start-up operations and *then* start looking for the type.
> Testing the patch so far on a small / medium (5 - 20 bundles) sized workspace I
> did not notice an appreciable difference in performance. I suspect you could
> really kill performance by having a large-ish workspace with a lot of entries
> on the source lookup path.

Hi Michael,

I haven't tried this patch yet (as it is very awkward to transfer patches and the eclipse source onto our development network), but I currently use a workspace with 555 projects (bundles) open at the same time.  I also have 571 plugins in my target platform. Initialising the indexes is somewhat slow on a workspace this size, but it is usually impractical for us to work differently. 

Many thanks for putting in the effort to resolve this performance issue - it is greatly appreciated by a number of people in this office.

James
Comment 24 Randy Hudson CLA 2011-05-04 14:16:26 EDT
Is this bug also the reason that logical formatters are painfully slow?
Comment 25 Dani Megert CLA 2011-05-05 02:34:25 EDT
(In reply to comment #24)
> Is this bug also the reason that logical formatters are painfully slow?

I don't think so. If they are for you, please file a bug with a stack trace.
Comment 26 Michael Rennie CLA 2011-05-05 10:09:11 EDT
(In reply to comment #24)
> Is this bug also the reason that logical formatters are painfully slow?

No, this bug deals with the way we look up a fully qualified name in the workspace / source lookup path, which is unrelated to formatting.
Comment 27 Dani Megert CLA 2011-06-10 05:06:59 EDT
Bumping priority to 'P2'. This is something I'd like see fixed in 3.8. The earlier the better.
Comment 28 Markus Keller CLA 2011-08-08 06:01:58 EDT
Created attachment 201062 [details]
patch 3

The patch from comment 21 was incomplete. Here's the full one.

Note that this has still room for improvement:

With multiple matches, we'd better show a selection dialog rather than showing just the "first" match (see also bug 348507)

Furthermore, it looks like only the first search is very slow. We should try to trigger the filling of the caches in the background, as soon as the first hyperlink is activated. Then, subsequent links could be quick and correct.
Comment 29 Michael Rennie CLA 2012-04-05 15:27:41 EDT
(In reply to comment #28)
> Created attachment 201062 [details]
> patch 3
> 
> The patch from comment 21 was incomplete. Here's the full one.
> 
> Note that this has still room for improvement:
> 
> With multiple matches, we'd better show a selection dialog rather than showing
> just the "first" match (see also bug 348507)
> 
> Furthermore, it looks like only the first search is very slow. We should try to
> trigger the filling of the caches in the background, as soon as the first
> hyperlink is activated. Then, subsequent links could be quick and correct.

I pushed patch 3 to master so we can play around with it - thanks Markus.

http://git.eclipse.org/c/jdt/eclipse.jdt.debug.git/commit/?id=8140c9a358b4c6fbed8f0d94d70c8cc32db37fac
Comment 30 Dani Megert CLA 2012-05-02 06:27:24 EDT
Verified in I20120430-2000 that it is much faster. OK to close for me. Markus?
Comment 31 Markus Keller CLA 2012-05-02 10:55:21 EDT
> OK to close for me. Markus?

Yes, looks good. I also verified a few scenarios where the type was not unique (e.g. multiple java.util.ArrayList classes in a workspace), and the right version was opened.

Open issues discussed in this bug:

- Potential problem mentioned in comment 21: Resolvers could theoretically override the default resolution, but they are not consulted any more if the workspace contains a unique match.
=> I'd say this is OK, since resolvers are not intended to completely override the resolution.

- When the workspace search finds multiple matches, the "first" one wins and no selection dialog is shown.
=> OK for me, since a selection dialog is also not what the user wants. If you e.g. have a stacktrace with references to the rt.jar, then then opening the "first" match is perfect iff that's the right rt.jar. If not, then a selection dialog could help a bit, but it's still tedious if you open multiple links in the stack trace.
Comment 32 Michael Rennie CLA 2012-05-02 11:17:00 EDT
(In reply to comment #31)
> => I'd say this is OK, since resolvers are not intended to completely override
> the resolution.

> => OK for me, since a selection dialog is also not what the user wants. 

Both of these comments make sense. I think we can mark this bug fixed and open new issues for those points (if they become issues).