search

eclipse-jdt / eclipse.jdt.debug

Eclipse Public License 2.0
16 stars 46 forks source link

debug tree is slow with lots of thread creation #351

Open grandinj opened 9 months ago

grandinj commented 9 months ago

I have a couple of apps that are rather thread-heavy, as in 10s of threads and threads being created/removed every second or so.

The tree in the debug view gets reallllly slow, and even when the programs terminate, I can see that Eclipse is still busy updating the tree view in the debugger for several minutes after.

Is this a known issue? Any workarounds?

Sample stack trace of where Eclipse is getting stuck:

"main" #1 [10932] prio=6 os_prio=0 cpu=1671875.00ms elapsed=3480.47s tid=0x00000289dea3efc0 nid=10932 runnable [0x000000d218efd000] java.lang.Thread.State: RUNNABLE at org.eclipse.swt.internal.win32.OS.CallWindowProc(Native Method) at org.eclipse.swt.widgets.Tree.callWindowProc(Tree.java:1576) at org.eclipse.swt.widgets.Control.windowProc(Control.java:4845) at org.eclipse.swt.widgets.Tree.windowProc(Tree.java:6142) at org.eclipse.swt.widgets.Display.windowProc(Display.java:5040) at org.eclipse.swt.internal.win32.OS.SendMessage(Native Method) at org.eclipse.swt.widgets.Tree.findItem(Tree.java:2909) at org.eclipse.swt.widgets.TreeItem.getItem(TreeItem.java:720) at org.eclipse.jface.viewers.TreeViewer.replace(TreeViewer.java:469) at org.eclipse.debug.internal.ui.viewers.model.TreeModelContentProvider.handleAdd(TreeModelContentProvider.java:1358) at org.eclipse.debug.internal.ui.viewers.model.TreeModelContentProvider.updateNodes(TreeModelContentProvider.java:1276) at org.eclipse.debug.internal.ui.viewers.model.TreeModelContentProvider.updateNodes(TreeModelContentProvider.java:1312) at org.eclipse.debug.internal.ui.viewers.model.TreeModelContentProvider.updateNodes(TreeModelContentProvider.java:1312) at org.eclipse.debug.internal.ui.viewers.model.TreeModelContentProvider.updateNodes(TreeModelContentProvider.java:1312) at org.eclipse.debug.internal.ui.viewers.model.TreeModelContentProvider.updateModel(TreeModelContentProvider.java:576) at org.eclipse.debug.internal.ui.viewers.model.TreeModelContentProvider.doModelChanged(TreeModelContentProvider.java:543) at org.eclipse.debug.internal.ui.viewers.model.TreeModelContentProvider$DelayedDoModelChangedJob.runInUIThread(TreeModelContentProvider.java:449) at org.eclipse.ui.progress.UIJob.lambda$0(UIJob.java:148) at org.eclipse.ui.progress.UIJob$$Lambda/0x0000028981aa2438.run(Unknown Source) at org.eclipse.swt.widgets.RunnableLock.run(RunnableLock.java:40) at org.eclipse.swt.widgets.Synchronizer.runAsyncMessages(Synchronizer.java:132)

grandinj commented 9 months ago

This appears to be the same thing as this issue: https://bugs.eclipse.org/bugs/show_bug.cgi?id=552328

However, adding the system properties mentioned there:

-Dorg.eclipse.jdt.internal.debug.core.model.ThreadNameChangeListener.disable=true
-Dorg.eclipse.jdt.debug.ui/org.eclipse.jdt.debug.ui.javaDebug.ListenOnThreadNameChanges=false

does not help my situation. Taking a heap dump of the running process, I see I have 164 megabytes worth of TreeModelContentProvider$DelayedDoModelChangedJob.

Sampling some more stack traces, I see lots of: at org.eclipse.swt.internal.win32.OS.SendMessage(Native Method) at org.eclipse.swt.widgets.Tree.getSelection(Tree.java:3503) at org.eclipse.swt.widgets.Tree.getSelection(Tree.java:3523) at org.eclipse.swt.widgets.Tree.getSelection(Tree.java:3523) at org.eclipse.swt.widgets.Tree.getSelection(Tree.java:3573) at org.eclipse.jface.viewers.TreeViewer.getSelection(TreeViewer.java:232) at org.eclipse.jface.viewers.AbstractTreeViewer.getSelection(AbstractTreeViewer.java:3109) at org.eclipse.jface.viewers.StructuredViewer.preservingSelection(StructuredViewer.java:1414) at org.eclipse.jface.viewers.TreeViewer.preservingSelection(TreeViewer.java:366) at org.eclipse.jface.viewers.StructuredViewer.preservingSelection(StructuredViewer.java:1364) at org.eclipse.jface.viewers.TreeViewer.remove(TreeViewer.java:822)

which leads me to think that someone implemented some kind of "preserve the selection when updating the tree" in JFace, which is leading to a dramatic slowdown in processing tree updates.

Looking at this, it seems to me that (a) TreeViewer really really needs some kind of bulk-update mechanism to reduce the number of times it needs to call getSelection() (b) either the job queue needs some kind of coalescing mechanism, so that new entries are merged with existing entries, or the thing that adds items to the job queue needs to be taught to generate updates in bulk, rather than in single items.

grandinj commented 9 months ago

This bug is most likely caused by https://github.com/eclipse-platform/eclipse.platform/commit/485d05449115e746767fb9516931c39249d5ecec

iloveeclipse commented 9 months ago

This bug is most likely caused by eclipse-platform/eclipse.platform@485d054

Why do you think so? Without that change UI will be not slow but simply frozen.

grandinj commented 9 months ago

Why do you think so? Without that change UI will be not slow but simply frozen.

Previously the tree would have processed very large batches at a time, only calling the very slow getSelection() once per batch.

Now the batches are much much smaller, meaning the tree calls getSelection() very often, and getSelection() is very slow.

grandinj commented 9 months ago

Please note that I mean no disrespect, and I may well be wrong here - I am a long-time Java developer and Eclipse user, but I am making educated guesses based on what I see in the Eclipse code.

iloveeclipse commented 9 months ago

meaning the tree calls getSelection() very often

Can you provide full stack trace that shows this method called from the debugger code? The issue description only shows some incomplete stack trace.

Also if you could provide an example project that shows the issue, it would be much easier to discuss about possible root cause & solution.

grandinj commented 9 months ago

The full stack trace looks like the below. I unfortunately cannot share this project, it is a proprietary application I am developing.

"main" #1 [3984] prio=6 os_prio=0 cpu=116000.00ms elapsed=386.28s tid=0x000001cfd6621be0 nid=3984 runnable [0x00000076d64fd000] java.lang.Thread.State: RUNNABLE at org.eclipse.swt.internal.win32.OS.SendMessage(Native Method) at org.eclipse.swt.widgets.Tree.getSelection(Tree.java:3503) at org.eclipse.swt.widgets.Tree.getSelection(Tree.java:3523) at org.eclipse.swt.widgets.Tree.getSelection(Tree.java:3523) at org.eclipse.swt.widgets.Tree.getSelection(Tree.java:3573) at org.eclipse.jface.viewers.TreeViewer.getSelection(TreeViewer.java:232) at org.eclipse.jface.viewers.AbstractTreeViewer.getSelection(AbstractTreeViewer.java:3109) at org.eclipse.jface.viewers.StructuredViewer.preservingSelection(StructuredViewer.java:1414) at org.eclipse.jface.viewers.TreeViewer.preservingSelection(TreeViewer.java:366) at org.eclipse.jface.viewers.StructuredViewer.preservingSelection(StructuredViewer.java:1364) at org.eclipse.jface.viewers.TreeViewer.remove(TreeViewer.java:822) at org.eclipse.debug.internal.ui.viewers.model.TreeModelContentProvider.handleRemove(TreeModelContentProvider.java:1560) at org.eclipse.debug.internal.ui.viewers.model.TreeModelContentProvider.updateNodes(TreeModelContentProvider.java:1279) at org.eclipse.debug.internal.ui.viewers.model.TreeModelContentProvider.updateNodes(TreeModelContentProvider.java:1312) at org.eclipse.debug.internal.ui.viewers.model.TreeModelContentProvider.updateNodes(TreeModelContentProvider.java:1312) at org.eclipse.debug.internal.ui.viewers.model.TreeModelContentProvider.updateNodes(TreeModelContentProvider.java:1312) at org.eclipse.debug.internal.ui.viewers.model.TreeModelContentProvider.updateModel(TreeModelContentProvider.java:575) at org.eclipse.debug.internal.ui.viewers.model.TreeModelContentProvider.doModelChanged(TreeModelContentProvider.java:543) at org.eclipse.debug.internal.ui.viewers.model.TreeModelContentProvider$DelayedDoModelChangedJob.runInUIThread(TreeModelContentProvider.java:449) at org.eclipse.ui.progress.UIJob.lambda$0(UIJob.java:148) at org.eclipse.ui.progress.UIJob$$Lambda/0x000001cf81979b88.run(Unknown Source) at org.eclipse.swt.widgets.RunnableLock.run(RunnableLock.java:40) at org.eclipse.swt.widgets.Synchronizer.runAsyncMessages(Synchronizer.java:132)

grandinj commented 9 months ago

Attaching leak report from the heap dump I took while Eclipse was chewing away on the queue of jobs (after I had already quite the applications I was debugging) leak-report.pdf

iloveeclipse commented 9 months ago

I unfortunately cannot share this project, it is a proprietary application I am developing.

We have limited resources. If the problem is important to you, maybe you can try to provide an example project "inspired" by your application, that can demonstrate the issue.

I see that the stack doesn't match current master. Which Eclipse version do you use? Can you please try with 4.30 RC2? See https://download.eclipse.org/eclipse/downloads/

grandinj commented 9 months ago

So I tried to create a replica project to demonstrate the problem. But a simple application that just spawns lots of threads does not trigger the problem (obviously, or you would likely have noticed it yourself).

So it must be something weird about my application that is triggering the debug code (either in the VM or in Eclipse) to generate large numbers of events. Unfortunately this is a very old and large application with lots of moving parts, so tricky to isolate the problem area.

But I have used the eclipse heap dump to examine one of the events (see screenshot below). Does this mean anything to you?

For example I see that the event is called "JDI thread evaluations" ?

image

iloveeclipse commented 9 months ago

Does this mean anything to you?

Not really.

grandinj commented 9 months ago

So I have a simple reproducer project, which confirms a thought I had last night, that something in my codebase is creating a very large number of short-lived threads.

SlowDebugTreeProject.zip

grandinj commented 9 months ago

Run the reproducer for 10 or 20 seconds (with the JDT debug view open), then close the sample window. The debug tree will keep processing for 30 seconds or more after the application is closed.

grandinj commented 9 months ago

Hmmm, my bug looks exactly like this one: https://bugs.eclipse.org/bugs/show_bug.cgi?id=573810

And similar to that one, it looks like all the high-velocity threads in my debugger view are GC threads, they don't seem to be coming from my application (I checked this by comparing that I see in eclipse to what I see when running the jstack command)

But I have "Show System Threads" turned off, so it seems to me that the problem is that Eclipse is not filtering out the GC threads properly. Or maybe the VM is not reporting the fact that they are system threads? This is running with jdk-11.0.20.8-hotspot on a Windows10 machine. Altthough I can reproduce the problem with jdk-17.0.5.8-hotspot and jdk-21-01

jukzi commented 7 months ago

Removed needinfo, as the reproducer project is given in https://github.com/eclipse-jdt/eclipse.jdt.debug/issues/351#issuecomment-1833183225 i can reproduce it is slow - but at least it does not freeze. Pull Request with an improvement would be very welcome. If you won't work on it yourself it is unlikely to be further improved and we would close the issue as "not planned"

grandinj commented 7 months ago

Pull Request with an improvement would be very welcome.

Any code pointers as to where the events originate? From my initial debugging it looks like the filtering needs to be pushed to the source, we cannot rely on improving the processing of events, we need to prevent the source from generating the events.

jukzi commented 7 months ago

I do not remember, but you could put a breakpoint in the Constructor of the Event classes created, probably somewhere here: image