Bug 190094 - Java Outline Causes Eclipse Lock-up.
Summary: Java Outline Causes Eclipse Lock-up.
Status: VERIFIED FIXED
Alias: None
Product: JDT
Classification: Eclipse Project
Component: Core (show other bugs)
Version: 3.2.2   Edit
Hardware: PC Windows XP
: P3 normal (vote)
Target Milestone: 3.4 M3   Edit
Assignee: Jerome Lanneluc CLA
QA Contact:
URL:
Whiteboard:
Keywords:
Depends on:
Blocks:
 
Reported: 2007-05-30 20:36 EDT by Matthew Wilson CLA
Modified: 2007-10-30 11:43 EDT (History)
7 users (show)

See Also:


Attachments
[screen shot]: debug stack trace during the second Crtl+O (81.68 KB, image/jpeg)
2007-06-01 02:56 EDT, Eric Jodet CLA
no flags Details
Debug trace for eric (62.14 KB, text/plain)
2007-06-03 20:10 EDT, Matthew Wilson CLA
no flags Details
Proposed fix and performance test (60.84 KB, patch)
2007-09-18 12:26 EDT, Jerome Lanneluc CLA
no flags Details | Diff
Improved fix and same performance test (63.46 KB, patch)
2007-09-20 12:43 EDT, Jerome Lanneluc CLA
no flags Details | Diff

Note You need to log in before you can comment on or make changes to this bug.
Description Matthew Wilson CLA 2007-05-30 20:36:51 EDT
Build ID: 3.2.2

Steps To Reproduce:
1.  Get a really big jar library in your project's class path
2.  Select, in a java editor, the name of a class that somehow inherits from a few things in this jar and press Ctrl-O (java outline pop-up).
3.  Press Ctrl-O again to see inherited attributes, then go make some coffee.


More information:
I first posted this problem in the newcomers group - see "Eclipse Frequently Pausing" on the 15/05/2007.

We have a very big library that contains a baseline build, which developers test their local changes against using a classpath that loads their local stuff first.  The baseline jar is very big - ~8600 classes, ~10000 resources in total and an attached source jar file as well.

I hacked some methods called by JavaOutlineInformationControl.toggleShowInheritedMembers() to print out some information on what was going on, and found that the two main jars in the classpath (our build.jar and rt.jar from the jdk) were being processed/interrogated an astonising number of times, which was using 100% of the CPU for several minutes (pentium P4, mainly single core but a couple of hyperthreaded ones, ~3GHz, plenty of memory) and locking up the main eclipse thread.  It was basically just the same two libraries being examined, over and over.

By unpacking these two main jars into classes directories, we made the response time for this operation essentially instantaneous.  But I think the problem is actually more widespread than just this one pop-up.  The developers here were experiencing a lot of long lockup-pauses at random moments, and this unpack-trick seems to solve the problem entirely.  I guess this function must be used in a few different ways, and is causing some problems for eclipse as a whole.

I have briefly tested this with 3.3RC1 and found that exactly the same lockup/pause happens if I view the outline popup with inherited attributes.  As I mentioned in the original newcomer posting, I'm a bit stuck for time at the moment, but if I get a chance in a couple of weeks I'm happy to take a look at this in more depth.  It looks like an easy win for overall performance and it'd make the developers here quite happy to have it solved.  In the meantime if someone more knowledgable solves it first that makes me happy too :-)

Thanks.
Matt.
Comment 1 Olivier Thomann CLA 2007-05-30 22:07:56 EDT
Moving to JDT/UI.
Would not be surprised if this would be related to the issue also seen in bug 186144.
Comment 2 Dani Megert CLA 2007-05-31 04:31:19 EDT
>Would not be surprised if this would be related to the issue also seen in bug
>186144.
Why? Bug 186144 is about class files without source. Ctrl+O doesn't even work in that case. So this is a different issue, at least looking from 100 miles.

This bug clearly states that the JAR case is very slow but if the JAR is extracted it is instant. This looks like a JDT Core issue to me.

Sorry, moving back.
Comment 3 Dani Megert CLA 2007-05-31 04:37:08 EDT
Matthew, can you give us a concrete example of a class from rt.jar where Ctrl+O Ctrl+O is very slow? Also, can you verify that Eclipse gets enough memory by using -vmargs -Xms50M -Xmx350M (if you don't do so already)?
Comment 4 Martin Aeschlimann CLA 2007-05-31 05:02:05 EDT
Just as info: The second Ctrl+O builds a supertype hierarchy and asks each supertypes for its methods.
Comment 5 Eric Jodet CLA 2007-05-31 10:47:06 EDT
(In reply to comment #3)
Also, may you please tell us the exact steps to perform in order to reproduce the problem.

May please try the following:
1 - start Eclipse, open the Java editor for a file that is supposed to cause the issue, then press Crtl+O twice
--> the locked-up behavior occurs - wait until completion
2- press Crtl+O twice, many times, and check whether the problem is there or not
(noticed that response time were slower the first time I performed the Crtl+O after Eclipse start-up, other Crtl+O's after the first one were faster)

May you please also provide us with complete JVM dumps while Eclipse behaving as locked-up (waiting for the second Crtl+O to complete, I assume)

Thanks in advance
Comment 6 Eric Jodet CLA 2007-05-31 10:54:29 EDT
sorry - assigned to wrong component
Comment 7 Matthew Wilson CLA 2007-05-31 20:26:31 EDT
Wow - you guys have really got excited about this.  I'm impressed :-)

Eric Jodet 2007-05-31 10:47:06 asked:

"press Crtl+O twice, many times, and check whether the problem is there or
not (noticed that response time were slower the first time I performed the Crtl+O after Eclipse start-up, other Crtl+O's after the first one were faster)"

In my environment it doesn't seem to be any different.  Maybe it depends on the specifics of which class is selected and what needs to be searched.  But the experiments I did last week didn't seem to get any faster the second time around (I just tried it with -clean on the command line, just to make sure).

Daniel Megert 2007-05-31 04:37:08 asked:

"can you verify that Eclipse gets enough memory by
using -vmargs -Xms50M -Xmx350M (if you don't do so already)?"

Yep - plenty of memory (350Mmx/ms).  There's a bit of GC activity on my machine when it's happening, but it's small first-generation stuff.

"can you give us a concrete example of a class from rt.jar where Ctrl+O
Ctrl+O is very slow?"

That's a bit more difficult.  I've tried a few classes here and there and they seem reasonably quick.  But If I select "HttpSession" from one of our own build classes, it bogs down for a little while.  The project is getting its web classes from weblogic.jar though, not just the standard struts library.  I'll have another try at this later this afternoon.  If I can, I'll try to set up a contrived example, but I can't promise anything just at the moment.

As for a stack trace, though, here you go:

Full thread dump Java HotSpot(TM) Client VM (1.5.0_06-b05 mixed mode):

"Worker-8" prio=6 tid=0x1d95ae40 nid=0xbec in Object.wait() [0x1e5cf000..0x1e5cfa68]
        at java.lang.Object.wait(Native Method)
        - waiting on <0x04a59260> (a org.eclipse.core.internal.jobs.WorkerPool)
        at org.eclipse.core.internal.jobs.WorkerPool.sleep(WorkerPool.java:173)
        - locked <0x04a59260> (a org.eclipse.core.internal.jobs.WorkerPool)
        at org.eclipse.core.internal.jobs.WorkerPool.startJob(WorkerPool.java:205)
        at org.eclipse.core.internal.jobs.Worker.run(Worker.java:51)

"Worker-7" prio=6 tid=0x1d95ab88 nid=0xa28 in Object.wait() [0x1e58f000..0x1e58fae8]
        at java.lang.Object.wait(Native Method)
        - waiting on <0x04a59260> (a org.eclipse.core.internal.jobs.WorkerPool)
        at org.eclipse.core.internal.jobs.WorkerPool.sleep(WorkerPool.java:173)
        - locked <0x04a59260> (a org.eclipse.core.internal.jobs.WorkerPool)
        at org.eclipse.core.internal.jobs.WorkerPool.startJob(WorkerPool.java:205)
        at org.eclipse.core.internal.jobs.Worker.run(Worker.java:51)

"org.eclipse.jdt.internal.ui.text.JavaReconciler" daemon prio=2 tid=0x1d7b58b0 nid=0xbb0 in Object.wait() [0x1e54f000..0x1e54fb68]
        at java.lang.Object.wait(Native Method)
        - waiting on <0x05b91b48> (a org.eclipse.jface.text.reconciler.DirtyRegionQueue)
        at org.eclipse.jface.text.reconciler.AbstractReconciler$BackgroundThread.run(AbstractReconciler.java:176)
        - locked <0x05b91b48> (a org.eclipse.jface.text.reconciler.DirtyRegionQueue)

"Worker-6" prio=6 tid=0x1d8387f0 nid=0xab8 in Object.wait() [0x1e50f000..0x1e50fce8]
        at java.lang.Object.wait(Native Method)
        - waiting on <0x04a59260> (a org.eclipse.core.internal.jobs.WorkerPool)
        at org.eclipse.core.internal.jobs.WorkerPool.sleep(WorkerPool.java:173)
        - locked <0x04a59260> (a org.eclipse.core.internal.jobs.WorkerPool)
        at org.eclipse.core.internal.jobs.WorkerPool.startJob(WorkerPool.java:205)
        at org.eclipse.core.internal.jobs.Worker.run(Worker.java:51)

"Worker-5" prio=6 tid=0x1d84c4a8 nid=0xa64 in Object.wait() [0x1e40f000..0x1e40fd68]
        at java.lang.Object.wait(Native Method)
        - waiting on <0x04a59260> (a org.eclipse.core.internal.jobs.WorkerPool)
        at org.eclipse.core.internal.jobs.WorkerPool.sleep(WorkerPool.java:173)
        - locked <0x04a59260> (a org.eclipse.core.internal.jobs.WorkerPool)
        at org.eclipse.core.internal.jobs.WorkerPool.startJob(WorkerPool.java:205)
        at org.eclipse.core.internal.jobs.Worker.run(Worker.java:51)

"Worker-4" prio=6 tid=0x1d840008 nid=0xbd4 in Object.wait() [0x1e3cf000..0x1e3cf9e8]
        at java.lang.Object.wait(Native Method)
        - waiting on <0x04a59260> (a org.eclipse.core.internal.jobs.WorkerPool)
        at org.eclipse.core.internal.jobs.WorkerPool.sleep(WorkerPool.java:173)
        - locked <0x04a59260> (a org.eclipse.core.internal.jobs.WorkerPool)
        at org.eclipse.core.internal.jobs.WorkerPool.startJob(WorkerPool.java:205)
        at org.eclipse.core.internal.jobs.Worker.run(Worker.java:51)

"Worker-3" prio=6 tid=0x1d832e00 nid=0xb1c in Object.wait() [0x1e34f000..0x1e34fa68]
        at java.lang.Object.wait(Native Method)
        - waiting on <0x04a59260> (a org.eclipse.core.internal.jobs.WorkerPool)
        at org.eclipse.core.internal.jobs.WorkerPool.sleep(WorkerPool.java:173)
        - locked <0x04a59260> (a org.eclipse.core.internal.jobs.WorkerPool)
        at org.eclipse.core.internal.jobs.WorkerPool.startJob(WorkerPool.java:205)
        at org.eclipse.core.internal.jobs.Worker.run(Worker.java:51)

"Worker-2" prio=6 tid=0x1d82fca0 nid=0xbd0 in Object.wait() [0x1e16f000..0x1e16fae8]
        at java.lang.Object.wait(Native Method)
        - waiting on <0x04a59260> (a org.eclipse.core.internal.jobs.WorkerPool)
        at org.eclipse.core.internal.jobs.WorkerPool.sleep(WorkerPool.java:173)
        - locked <0x04a59260> (a org.eclipse.core.internal.jobs.WorkerPool)
        at org.eclipse.core.internal.jobs.WorkerPool.startJob(WorkerPool.java:205)
        at org.eclipse.core.internal.jobs.Worker.run(Worker.java:51)

"Worker-1" prio=6 tid=0x1d765410 nid=0xb34 in Object.wait() [0x1ddef000..0x1ddefb68]
        at java.lang.Object.wait(Native Method)
        - waiting on <0x04a59260> (a org.eclipse.core.internal.jobs.WorkerPool)
        at org.eclipse.core.internal.jobs.WorkerPool.sleep(WorkerPool.java:173)
        - locked <0x04a59260> (a org.eclipse.core.internal.jobs.WorkerPool)
        at org.eclipse.core.internal.jobs.WorkerPool.startJob(WorkerPool.java:205)
        at org.eclipse.core.internal.jobs.Worker.run(Worker.java:51)

"Java indexing" daemon prio=4 tid=0x1d781d00 nid=0xba8 in Object.wait() [0x1e0df000..0x1e0dfc68]
        at java.lang.Object.wait(Native Method)
        - waiting on <0x04deb980> (a org.eclipse.jdt.internal.core.search.indexing.IndexManager)
        at java.lang.Object.wait(Object.java:474)
        at org.eclipse.jdt.internal.core.search.processing.JobManager.run(JobManager.java:349)
        - locked <0x04deb980> (a org.eclipse.jdt.internal.core.search.indexing.IndexManager)
        at java.lang.Thread.run(Thread.java:595)

"Worker-0" prio=6 tid=0x1d7577f0 nid=0xa20 in Object.wait() [0x1ddaf000..0x1ddafd68]
        at java.lang.Object.wait(Native Method)
        - waiting on <0x04a59260> (a org.eclipse.core.internal.jobs.WorkerPool)
        at org.eclipse.core.internal.jobs.WorkerPool.sleep(WorkerPool.java:173)
        - locked <0x04a59260> (a org.eclipse.core.internal.jobs.WorkerPool)
        at org.eclipse.core.internal.jobs.WorkerPool.startJob(WorkerPool.java:205)
        at org.eclipse.core.internal.jobs.Worker.run(Worker.java:51)

"Start Level Event Dispatcher" daemon prio=6 tid=0x1cde4408 nid=0xa2c in Object.wait() [0x1d1df000..0x1d1dfae8]
        at java.lang.Object.wait(Native Method)
        - waiting on <0x04530070> (a org.eclipse.osgi.framework.eventmgr.EventManager$EventThread)
        at java.lang.Object.wait(Object.java:474)
        at org.eclipse.osgi.framework.eventmgr.EventManager$EventThread.getNextEvent(EventManager.java:349)
        - locked <0x04530070> (a org.eclipse.osgi.framework.eventmgr.EventManager$EventThread)
        at org.eclipse.osgi.framework.eventmgr.EventManager$EventThread.run(EventManager.java:287)

"Framework Event Dispatcher" daemon prio=6 tid=0x1cd41d78 nid=0xb30 in Object.wait() [0x1d15f000..0x1d15fbe8]
        at java.lang.Object.wait(Native Method)
        - waiting on <0x045303e0> (a org.eclipse.osgi.framework.eventmgr.EventManager$EventThread)
        at java.lang.Object.wait(Object.java:474)
        at org.eclipse.osgi.framework.eventmgr.EventManager$EventThread.getNextEvent(EventManager.java:349)
        - locked <0x045303e0> (a org.eclipse.osgi.framework.eventmgr.EventManager$EventThread)
        at org.eclipse.osgi.framework.eventmgr.EventManager$EventThread.run(EventManager.java:287)

"Low Memory Detector" daemon prio=6 tid=0x00a12208 nid=0x4c8 runnable [0x00000000..0x00000000]

"CompilerThread0" daemon prio=10 tid=0x00a10e68 nid=0x578 waiting on condition [0x00000000..0x1ca5fa4c]

"Signal Dispatcher" daemon prio=10 tid=0x00a10158 nid=0x208 waiting on condition [0x00000000..0x00000000]

"Finalizer" daemon prio=8 tid=0x00a071a0 nid=0xae0 in Object.wait() [0x1c9df000..0x1c9dfa68]
        at java.lang.Object.wait(Native Method)
        - waiting on <0x045305c8> (a java.lang.ref.ReferenceQueue$Lock)
        at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:116)
        - locked <0x045305c8> (a java.lang.ref.ReferenceQueue$Lock)
        at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:132)
        at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:159)

"Reference Handler" daemon prio=10 tid=0x00a05d08 nid=0xa88 in Object.wait() [0x1c99f000..0x1c99fae8]
        at java.lang.Object.wait(Native Method)
        - waiting on <0x045300d8> (a java.lang.ref.Reference$Lock)
        at java.lang.Object.wait(Object.java:474)
        at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:116)
        - locked <0x045300d8> (a java.lang.ref.Reference$Lock)

"main" prio=6 tid=0x000367f0 nid=0xb6c runnable [0x0007e000..0x0007fc44]
        at java.util.zip.ZipFile.getNextEntry(Native Method)
        at java.util.zip.ZipFile.access$700(ZipFile.java:35)
        at java.util.zip.ZipFile$3.nextElement(ZipFile.java:421)
        - locked <0x02b1b0c8> (a java.util.zip.ZipFile)
        at java.util.zip.ZipFile$3.nextElement(ZipFile.java:415)
        at org.eclipse.jdt.internal.core.JarPackageFragmentRoot.computeChildren(JarPackageFragmentRoot.java:59)
        at org.eclipse.jdt.internal.core.PackageFragmentRoot.buildStructure(PackageFragmentRoot.java:170)
        at org.eclipse.jdt.internal.core.Openable.generateInfos(Openable.java:229)
        at org.eclipse.jdt.internal.core.JarPackageFragment.generateInfos(JarPackageFragment.java:113)
        at org.eclipse.jdt.internal.core.Openable.openParent(Openable.java:420)
        at org.eclipse.jdt.internal.core.Openable.generateInfos(Openable.java:218)
        at org.eclipse.jdt.internal.core.BinaryMember.generateInfos(BinaryMember.java:47)
        at org.eclipse.jdt.internal.core.JavaElement.openWhenClosed(JavaElement.java:505)
        at org.eclipse.jdt.internal.core.JavaElement.getElementInfo(JavaElement.java:249)
        at org.eclipse.jdt.internal.core.JavaElement.getElementInfo(JavaElement.java:235)
        at org.eclipse.jdt.internal.core.JavaElement.exists(JavaElement.java:153)
        at org.eclipse.jdt.ui.JavaElementLabels.getMethodLabel(JavaElementLabels.java:527)
        at org.eclipse.jdt.ui.JavaElementLabels.getElementLabel(JavaElementLabels.java:418)
        at org.eclipse.jdt.ui.JavaElementLabels.getElementLabel(JavaElementLabels.java:395)
        at org.eclipse.jdt.ui.JavaElementLabels.getTextLabel(JavaElementLabels.java:377)
        at org.eclipse.jdt.internal.ui.viewsupport.JavaUILabelProvider.getText(JavaUILabelProvider.java:161)
        at org.eclipse.jdt.internal.ui.text.JavaOutlineInformationControl$OutlineLabelProvider.getText(JavaOutlineInformationControl.java:120)
        at org.eclipse.jface.viewers.StructuredViewer.buildLabel(StructuredViewer.java:2102)
        at org.eclipse.jface.viewers.TreeViewer.doUpdateItem(TreeViewer.java:258)
        at org.eclipse.jface.viewers.AbstractTreeViewer$UpdateItemSafeRunnable.run(AbstractTreeViewer.java:95)
        at org.eclipse.core.runtime.SafeRunner.run(SafeRunner.java:37)
        at org.eclipse.core.runtime.Platform.run(Platform.java:843)
        at org.eclipse.ui.internal.JFaceUtil$1.run(JFaceUtil.java:44)
        at org.eclipse.jface.util.SafeRunnable.run(SafeRunnable.java:149)
        at org.eclipse.jface.viewers.AbstractTreeViewer.doUpdateItem(AbstractTreeViewer.java:849)
        at org.eclipse.jface.viewers.StructuredViewer$UpdateItemSafeRunnable.run(StructuredViewer.java:465)
        at org.eclipse.core.runtime.SafeRunner.run(SafeRunner.java:37)
        at org.eclipse.core.runtime.Platform.run(Platform.java:843)
        at org.eclipse.ui.internal.JFaceUtil$1.run(JFaceUtil.java:44)
        at org.eclipse.jface.util.SafeRunnable.run(SafeRunnable.java:149)
        at org.eclipse.jface.viewers.StructuredViewer.updateItem(StructuredViewer.java:1955)
        at org.eclipse.jface.viewers.AbstractTreeViewer.createTreeItem(AbstractTreeViewer.java:753)
        at org.eclipse.jface.viewers.AbstractTreeViewer.updateChildren(AbstractTreeViewer.java:2444)
        at org.eclipse.jface.viewers.AbstractTreeViewer.internalRefreshStruct(AbstractTreeViewer.java:1651)
        at org.eclipse.jface.viewers.TreeViewer.internalRefreshStruct(TreeViewer.java:955)
        at org.eclipse.jface.viewers.AbstractTreeViewer.internalRefreshStruct(AbstractTreeViewer.java:1658)
        at org.eclipse.jface.viewers.TreeViewer.internalRefreshStruct(TreeViewer.java:955)
        at org.eclipse.jface.viewers.AbstractTreeViewer.internalRefresh(AbstractTreeViewer.java:1627)
        at org.eclipse.jface.viewers.AbstractTreeViewer.internalRefresh(AbstractTreeViewer.java:1582)
        at org.eclipse.jface.viewers.AbstractTreeViewer.internalRefresh(AbstractTreeViewer.java:1568)
        at org.eclipse.jface.viewers.StructuredViewer$7.run(StructuredViewer.java:1388)
        at org.eclipse.jface.viewers.StructuredViewer.preservingSelection(StructuredViewer.java:1323)
        at org.eclipse.jface.viewers.StructuredViewer.refresh(StructuredViewer.java:1386)
        at org.eclipse.jface.viewers.StructuredViewer.refresh(StructuredViewer.java:1345)
        at org.eclipse.jdt.internal.ui.text.JavaOutlineInformationControl$OutlineContentProvider.toggleShowInheritedMembers(JavaOutlineInformationControl.java:270)
        at org.eclipse.jdt.internal.ui.text.JavaOutlineInformationControl.toggleShowInheritedMembers(JavaOutlineInformationControl.java:663)
        at org.eclipse.jdt.internal.ui.text.JavaOutlineInformationControl$3.keyPressed(JavaOutlineInformationControl.java:642)
        at org.eclipse.swt.widgets.TypedListener.handleEvent(TypedListener.java:122)
        at org.eclipse.swt.widgets.EventTable.sendEvent(EventTable.java:66)
        at org.eclipse.swt.widgets.Widget.sendEvent(Widget.java:928)
        at org.eclipse.swt.widgets.Widget.sendEvent(Widget.java:952)
        at org.eclipse.swt.widgets.Widget.sendEvent(Widget.java:937)
        at org.eclipse.swt.widgets.Widget.sendKeyEvent(Widget.java:965)
        at org.eclipse.swt.widgets.Text.sendKeyEvent(Text.java:1213)
        at org.eclipse.swt.widgets.Widget.sendKeyEvent(Widget.java:961)
        at org.eclipse.swt.widgets.Widget.wmChar(Widget.java:1275)
        at org.eclipse.swt.widgets.Control.WM_CHAR(Control.java:3346)
        at org.eclipse.swt.widgets.Text.WM_CHAR(Text.java:1846)
        at org.eclipse.swt.widgets.Control.windowProc(Control.java:3246)
        at org.eclipse.swt.widgets.Text.windowProc(Text.java:1841)
        at org.eclipse.swt.widgets.Display.windowProc(Display.java:4025)
        at org.eclipse.swt.internal.win32.OS.DispatchMessageW(Native Method)
        at org.eclipse.swt.internal.win32.OS.DispatchMessage(OS.java:1932)
        at org.eclipse.swt.widgets.Display.readAndDispatch(Display.java:2966)
        at org.eclipse.ui.internal.Workbench.runEventLoop(Workbench.java:1930)
        at org.eclipse.ui.internal.Workbench.runUI(Workbench.java:1894)
        at org.eclipse.ui.internal.Workbench.createAndRunWorkbench(Workbench.java:422)
        at org.eclipse.ui.PlatformUI.createAndRunWorkbench(PlatformUI.java:149)
        at org.eclipse.ui.internal.ide.IDEApplication.run(IDEApplication.java:95)
        at org.eclipse.core.internal.runtime.PlatformActivator$1.run(PlatformActivator.java:78)
        at org.eclipse.core.runtime.internal.adaptor.EclipseAppLauncher.runApplication(EclipseAppLauncher.java:92)
        at org.eclipse.core.runtime.internal.adaptor.EclipseAppLauncher.start(EclipseAppLauncher.java:68)
        at org.eclipse.core.runtime.adaptor.EclipseStarter.run(EclipseStarter.java:400)
        at org.eclipse.core.runtime.adaptor.EclipseStarter.run(EclipseStarter.java:177)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
        at java.lang.reflect.Method.invoke(Method.java:585)
        at org.eclipse.core.launcher.Main.invokeFramework(Main.java:336)
        at org.eclipse.core.launcher.Main.basicRun(Main.java:280)
        at org.eclipse.core.launcher.Main.run(Main.java:977)
        at org.eclipse.core.launcher.Main.main(Main.java:952)

"VM Thread" prio=10 tid=0x00a032e0 nid=0xb50 runnable

"VM Periodic Task Thread" prio=10 tid=0x00a13520 nid=0xdf4 waiting on condition



Thanks everyone :-)

Matt.
Comment 8 Eric Jodet CLA 2007-06-01 02:55:49 EDT
(In reply to comment #7)
Managed to reproduce the exact same stack trace (see to be attached screen shot)
- stored a JAR (11 Mo) on a network drive
- created a sample project with this JAR on the build path
- created a class that inherits from one in this JAR
- with this class opened in the Java Editor, pressed Crtl+O twice
- on the second Crtl+O (show inherited members), the editor sounds like hanging

From the stack trace, it seems that the remote JAR is being read.

Matt: from the bug description
(...)
"We have a very big library that contains a baseline build, which developers
test their local changes against using a classpath that loads their local stuff
first."
(...)
May you please tell us whether this big lib is local for every developer, or is it stored on a network drive?
Thanks.
Comment 9 Eric Jodet CLA 2007-06-01 02:56:36 EDT
Created attachment 69660 [details]
[screen shot]: debug stack trace during the second Crtl+O
Comment 10 Matthew Wilson CLA 2007-06-01 03:00:29 EDT
(In reply to comment #8)
"May you please tell us whether this big lib is local for every developer, or is it stored on a network drive?"

It's local.  They copy it to their desktop after each build (with a script).  It's just the way they were doing things when I got here  :-)



Comment 11 Dani Megert CLA 2007-06-01 03:06:36 EDT
Is that local disk eventually slow or even working in PIO mode instead of DMA? This would make it as slow as a network drive or even slower.
Comment 12 Matthew Wilson CLA 2007-06-01 03:10:37 EDT
(In reply to comment #11)
> Is that local disk eventually slow or even working in PIO mode instead of DMA?
> This would make it as slow as a network drive or even slower.

I don't think so.  The bottleneck seemed to actually be CPU - on most machines it's pinned at 100%.  On the other hand, the eclipse java process was reading (literally) gigabytes for some operations.  And there are only a few 10's of megs of libraries to read!

I'm pretty sure that it's not slow I/O that's causing the operation to take a long time.  It's possible that by slowing I/O down you were able to see the same snapshot, though.

Comment 13 Philipe Mulet CLA 2007-06-01 03:45:08 EDT
Matthew - can you make your workspace available to us so we can reproduce it for real ?
Comment 14 Eric Jodet CLA 2007-06-01 03:47:08 EDT
(In reply to comment #12)
Matt,
still no chance you could provide us with a sample project / test case to reproduce the problem?
What's the size of build.jar file?
Also, may you please attach a sample .classpath file from a project where the problem occurs.
Thanks.
Comment 15 Eric Jodet CLA 2007-06-01 04:36:23 EDT
(In reply to comment #12)
Also, we would like you to capture some trace data, when reproducing this issue.

1. Create a .options file with the following content:
# Turn on debug tracing for org.eclipse.jdt.core plugin
org.eclipse.jdt.core/debug=true
# Reports Java model elements opening/closing
org.eclipse.jdt.core/debug/javamodel/cache=true

2. Start eclipse with the following command:
eclipse.exe -debug <path to your .options file> -vm <path to java.exe>
e.g. eclipse.exe -debug c:\temp\.options -vm c:\jdk1.5.0\bin\java.exe
=> this should open a DOS console

3. Ensure that the DOS console buffer size is as big as possible 
(Properties > Layout > Screen Buffer Size > set width and height to 9999)

4. Try and reproduce the problem, then copy/paste the content of the DOS console into a file, and attach the file to this bug

thanks
Comment 16 Matthew Wilson CLA 2007-06-03 20:10:26 EDT
Created attachment 69906 [details]
Debug trace for eric

Thanks eric.  Here's a trace of the problem.  I was searching for "HttpSessionBindingListener" in a file called StrutsSession.

The project name wasn't my idea - I inherited that too :-)

Thanks.
Comment 17 Eric Jodet CLA 2007-06-04 04:07:58 EDT
(In reply to comment #16)
Thanks for the trace file - while we look into it, may you please provide us with:
- the .classpath file from a project where the problem occurs
- an example of class file, inheriting from a class located in the weblogic.jar file, that causes the lock-up (tell me the exact weblogic.jar class to extend to try and reproduce the issue)
thanks
Comment 18 Eric Jodet CLA 2007-06-04 05:49:51 EDT
(In reply to comment #7)
Unfortunately, a single snapshot won't help us much to determine were the CPU time is spent.
May you please take as many snapshots as you can (10 would be ideal), during the lock-up, in order for us to have a more precise view of the situation.
Thanks.
Comment 19 Eric Jodet CLA 2007-06-04 12:04:54 EDT
(In reply to comment #18)
Matt (sorry for the number of requests):
may you please take some time to test the following workaround.
The trick consists to attach fake src.zip to big JAR's.
- on your local hard disk, create an empty file called src.zip
- for a project where the problem occurs, expand the weblogic.jar file
- double-click any class
- in the right-hand class file editor, click the Attach source button
- enter the path_to_fake src.zip
- click OK to commit your changes
- do the same for the build.jar file
- When done, stop then restart Eclipse.
- Try and reproduce the issue.
Let's us know if this workaround has a (positive) impact on current behavior.
Thanks.
Comment 20 Walter Harley CLA 2007-06-04 20:21:04 EDT
FYI, we at BEA are also seeing this in 3.2.2 in builds of an internal app that has weblogic.jar on the classpath.  The bottom of the stack is essentially identical in our case, although the top is different because it's being called from annotation processing rather than from the UI.

In our case, it was necessary to set -Xmx1200M -Xms1200M (yes, 1.2G!) to make the builds take a reasonable time.

We believe this is a repeat of an issue that we faced in 3.1; the problem in that case was the size of the JavaModelCache.  In our custom version of 3.1 we made the cache much bigger to handle the problem; in 3.2, the cache was made a multiple of max memory size, but evidently it is not big enough for this particular jar file. 

Note that simply increasing the cache size may not be the right solution: the underlying problem appears to be that when a jar on the classpath is too big for all its entries to fit in the cache, the system thrashes.
Comment 21 Eric Jodet CLA 2007-06-05 00:42:41 EDT
(In reply to comment #20)
Walter, thanks for your investigation.
We already noticed that increasing the memory would fix the issue,
but first wanted to perform additional verification.
By the way, did you had the opportunity to perform the same test using a RC3?
Comment 22 Walter Harley CLA 2007-06-05 13:20:05 EDT
(In reply to comment #21)
> By the way, did you had the opportunity to perform the same test using a RC3?

Unfortunately, no; we don't have our proprietary BEA plug-ins integrated with 3.3 yet.
Comment 23 Eric Jodet CLA 2007-06-28 00:30:59 EDT
(In reply to comment #19)
Matt,
did you manage to gather the information / material we requested in the referenced comment?
Do you still encounter this issue?
Comment 24 Jerome Lanneluc CLA 2007-09-05 10:06:33 EDT
Taking over, as I believe something can be done at the Java model level to handle this situation.
Comment 25 Jerome Lanneluc CLA 2007-09-18 12:26:54 EDT
Created attachment 78664 [details]
Proposed fix and performance test
Comment 26 Jerome Lanneluc CLA 2007-09-20 12:43:10 EDT
Created attachment 78870 [details]
Improved fix and same performance test
Comment 27 Jerome Lanneluc CLA 2007-09-21 09:17:47 EDT
Fix and performance test released for 3.4M3 in HEAD.
Performance test also released in perf_33x branch.
Comment 28 David Audel CLA 2007-10-30 10:58:53 EDT
Verified for 3.4M3 using I20071029-0010 build.
Comment 29 Jerome Lanneluc CLA 2007-10-30 11:43:37 EDT
(In reply to comment #26)
Note that this patch is not an obvious change. It involves the rewriting of critical parts of the Java model. So it would be hard and risky to backport it to a R3_x_maintenance stream.