Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

java.util.concurrent.TimeoutException after sometime of usage when using content assist #136

Closed
jonashungershausen opened this Issue Nov 10, 2018 · 16 comments

Comments

Projects
None yet
5 participants
@jonashungershausen
Copy link

jonashungershausen commented Nov 10, 2018

Hi,

sometimes after some usage of the Eclipse Spring Tools version, I'm getting UI freezes when trying to use content-assist (Ctrl+Space). There is also a stacktrace in my journalctl -f [1].

I'm not sure why it happens though. I always just use the IDE as normal and after some time of usage without problems, I'm getting this problem. A restart of the IDE fixes the problem.

Specs:

  • Fedora 29
  • Java 11 (not sure if this could be the cause, I will try Java 8 for some time and then report back here)
  • Eclipse STS Version: 4.0.1.RELEASE
  • No plugins installed

I'm happy to provide additional info if needed.

[1]:

Nov 10 15:56:54 localhost.localdomain Spring Tool Suite 4.desktop[1878]:         at java.util.concurrent.CompletableFuture.timedGet(CompletableFuture.java:1771)
Nov 10 15:56:54 localhost.localdomain Spring Tool Suite 4.desktop[1878]:         at java.util.concurrent.CompletableFuture.get(CompletableFuture.java:1915)
Nov 10 15:56:54 localhost.localdomain Spring Tool Suite 4.desktop[1878]:         at org.springframework.tooling.boot.ls.jdt.SpringBootJavaCompletionProposalComputer.computeCompletionProposals(SpringBootJavaCompletionProposalComputer.java:55)
Nov 10 15:56:54 localhost.localdomain Spring Tool Suite 4.desktop[1878]:         at org.eclipse.jdt.internal.ui.text.java.CompletionProposalComputerDescriptor.computeCompletionProposals(CompletionProposalComputerDescriptor.java:336)
Nov 10 15:56:54 localhost.localdomain Spring Tool Suite 4.desktop[1878]:         at org.eclipse.jdt.internal.ui.text.java.CompletionProposalCategory.computeCompletionProposals(CompletionProposalCategory.java:340)
Nov 10 15:56:54 localhost.localdomain Spring Tool Suite 4.desktop[1878]:         at org.eclipse.jdt.internal.ui.text.java.ContentAssistProcessor.collectProposals(ContentAssistProcessor.java:334)
Nov 10 15:56:54 localhost.localdomain Spring Tool Suite 4.desktop[1878]:         at org.eclipse.jdt.internal.ui.text.java.ContentAssistProcessor.computeCompletionProposals(ContentAssistProcessor.java:291)
Nov 10 15:56:54 localhost.localdomain Spring Tool Suite 4.desktop[1878]:         at org.eclipse.jface.text.contentassist.ContentAssistant$2.lambda$0(ContentAssistant.java:2012)
Nov 10 15:56:54 localhost.localdomain Spring Tool Suite 4.desktop[1878]:         at java.util.Collections$SingletonSet.forEach(Collections.java:4767)
Nov 10 15:56:54 localhost.localdomain Spring Tool Suite 4.desktop[1878]:         at org.eclipse.jface.text.contentassist.ContentAssistant$2.run(ContentAssistant.java:2011)
Nov 10 15:56:54 localhost.localdomain Spring Tool Suite 4.desktop[1878]:         at org.eclipse.core.runtime.SafeRunner.run(SafeRunner.java:45)
Nov 10 15:56:54 localhost.localdomain Spring Tool Suite 4.desktop[1878]:         at org.eclipse.jface.text.contentassist.ContentAssistant.computeCompletionProposals(ContentAssistant.java:2008)
Nov 10 15:56:54 localhost.localdomain Spring Tool Suite 4.desktop[1878]:         at org.eclipse.jface.text.contentassist.CompletionProposalPopup.computeProposals(CompletionProposalPopup.java:561)
Nov 10 15:56:54 localhost.localdomain Spring Tool Suite 4.desktop[1878]:         at org.eclipse.jface.text.contentassist.CompletionProposalPopup.lambda$0(CompletionProposalPopup.java:491)
Nov 10 15:56:54 localhost.localdomain Spring Tool Suite 4.desktop[1878]:         at org.eclipse.swt.custom.BusyIndicator.showWhile(BusyIndicator.java:72)
Nov 10 15:56:54 localhost.localdomain Spring Tool Suite 4.desktop[1878]:         at org.eclipse.jface.text.contentassist.CompletionProposalPopup.showProposals(CompletionProposalPopup.java:486)
Nov 10 15:56:54 localhost.localdomain Spring Tool Suite 4.desktop[1878]:         at org.eclipse.jface.text.contentassist.ContentAssistant.showPossibleCompletions(ContentAssistant.java:1822)
Nov 10 15:56:54 localhost.localdomain Spring Tool Suite 4.desktop[1878]:         at org.eclipse.jdt.internal.ui.javaeditor.CompilationUnitEditor$AdaptedSourceViewer.doOperation(CompilationUnitEditor.java:189)
Nov 10 15:56:54 localhost.localdomain Spring Tool Suite 4.desktop[1878]:         at org.eclipse.ui.texteditor.ContentAssistAction.lambda$0(ContentAssistAction.java:85)
Nov 10 15:56:54 localhost.localdomain Spring Tool Suite 4.desktop[1878]:         at org.eclipse.swt.custom.BusyIndicator.showWhile(BusyIndicator.java:72)
Nov 10 15:56:54 localhost.localdomain Spring Tool Suite 4.desktop[1878]:         at org.eclipse.ui.texteditor.ContentAssistAction.run(ContentAssistAction.java:84)
Nov 10 15:56:54 localhost.localdomain Spring Tool Suite 4.desktop[1878]:         at org.eclipse.jface.action.Action.runWithEvent(Action.java:476)
Nov 10 15:56:54 localhost.localdomain Spring Tool Suite 4.desktop[1878]:         at org.eclipse.jface.commands.ActionHandler.execute(ActionHandler.java:121)
Nov 10 15:56:54 localhost.localdomain Spring Tool Suite 4.desktop[1878]:         at org.eclipse.ui.internal.handlers.E4HandlerProxy.execute(E4HandlerProxy.java:96)
Nov 10 15:56:54 localhost.localdomain Spring Tool Suite 4.desktop[1878]:         at sun.reflect.GeneratedMethodAccessor72.invoke(Unknown Source)
Nov 10 15:56:54 localhost.localdomain Spring Tool Suite 4.desktop[1878]:         at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
Nov 10 15:56:54 localhost.localdomain Spring Tool Suite 4.desktop[1878]:         at java.lang.reflect.Method.invoke(Method.java:498)
Nov 10 15:56:54 localhost.localdomain Spring Tool Suite 4.desktop[1878]:         at org.eclipse.e4.core.internal.di.MethodRequestor.execute(MethodRequestor.java:58)
Nov 10 15:56:54 localhost.localdomain Spring Tool Suite 4.desktop[1878]:         at org.eclipse.e4.core.internal.di.InjectorImpl.invokeUsingClass(InjectorImpl.java:320)
Nov 10 15:56:54 localhost.localdomain Spring Tool Suite 4.desktop[1878]:         at org.eclipse.e4.core.internal.di.InjectorImpl.invoke(InjectorImpl.java:254)
Nov 10 15:56:54 localhost.localdomain Spring Tool Suite 4.desktop[1878]:         at org.eclipse.e4.core.contexts.ContextInjectionFactory.invoke(ContextInjectionFactory.java:164)
Nov 10 15:56:54 localhost.localdomain Spring Tool Suite 4.desktop[1878]:         at org.eclipse.e4.core.commands.internal.HandlerServiceHandler.execute(HandlerServiceHandler.java:156)
Nov 10 15:56:54 localhost.localdomain Spring Tool Suite 4.desktop[1878]:         at org.eclipse.core.commands.Command.executeWithChecks(Command.java:497)
Nov 10 15:56:54 localhost.localdomain Spring Tool Suite 4.desktop[1878]:         at org.eclipse.core.commands.ParameterizedCommand.executeWithChecks(ParameterizedCommand.java:490)
Nov 10 15:56:54 localhost.localdomain Spring Tool Suite 4.desktop[1878]:         at org.eclipse.e4.core.commands.internal.HandlerServiceImpl.executeHandler(HandlerServiceImpl.java:207)
Nov 10 15:56:54 localhost.localdomain Spring Tool Suite 4.desktop[1878]:         at org.eclipse.e4.ui.bindings.keys.KeyBindingDispatcher.executeCommand(KeyBindingDispatcher.java:308)
Nov 10 15:56:54 localhost.localdomain Spring Tool Suite 4.desktop[1878]:         at org.eclipse.e4.ui.bindings.keys.KeyBindingDispatcher.press(KeyBindingDispatcher.java:582)
Nov 10 15:56:54 localhost.localdomain Spring Tool Suite 4.desktop[1878]:         at org.eclipse.e4.ui.bindings.keys.KeyBindingDispatcher.processKeyEvent(KeyBindingDispatcher.java:651)
Nov 10 15:56:54 localhost.localdomain Spring Tool Suite 4.desktop[1878]:         at org.eclipse.e4.ui.bindings.keys.KeyBindingDispatcher.filterKeySequenceBindings(KeyBindingDispatcher.java:441)
Nov 10 15:56:54 localhost.localdomain Spring Tool Suite 4.desktop[1878]:         at org.eclipse.e4.ui.bindings.keys.KeyBindingDispatcher.access$2(KeyBindingDispatcher.java:384)
Nov 10 15:56:54 localhost.localdomain Spring Tool Suite 4.desktop[1878]:         at org.eclipse.e4.ui.bindings.keys.KeyBindingDispatcher$KeyDownFilter.handleEvent(KeyBindingDispatcher.java:96)
Nov 10 15:56:54 localhost.localdomain Spring Tool Suite 4.desktop[1878]:         at org.eclipse.swt.widgets.EventTable.sendEvent(EventTable.java:89)
Nov 10 15:56:54 localhost.localdomain Spring Tool Suite 4.desktop[1878]:         at org.eclipse.swt.widgets.Display.filterEvent(Display.java:1752)
Nov 10 15:56:54 localhost.localdomain Spring Tool Suite 4.desktop[1878]:         at org.eclipse.swt.widgets.Widget.sendEvent(Widget.java:1373)
Nov 10 15:56:54 localhost.localdomain Spring Tool Suite 4.desktop[1878]:         at org.eclipse.swt.widgets.Widget.sendEvent(Widget.java:1400)
Nov 10 15:56:54 localhost.localdomain Spring Tool Suite 4.desktop[1878]:         at org.eclipse.swt.widgets.Widget.sendEvent(Widget.java:1383)
Nov 10 15:56:54 localhost.localdomain Spring Tool Suite 4.desktop[1878]:         at org.eclipse.swt.widgets.Widget.sendKeyEvent(Widget.java:1412)
Nov 10 15:56:54 localhost.localdomain Spring Tool Suite 4.desktop[1878]:         at org.eclipse.swt.widgets.Widget.gtk_key_press_event(Widget.java:787)
Nov 10 15:56:54 localhost.localdomain Spring Tool Suite 4.desktop[1878]:         at org.eclipse.swt.widgets.Control.gtk_key_press_event(Control.java:3794)
Nov 10 15:56:54 localhost.localdomain Spring Tool Suite 4.desktop[1878]:         at org.eclipse.swt.widgets.Composite.gtk_key_press_event(Composite.java:862)
Nov 10 15:56:54 localhost.localdomain Spring Tool Suite 4.desktop[1878]:         at org.eclipse.swt.widgets.Widget.windowProc(Widget.java:1990)
Nov 10 15:56:54 localhost.localdomain Spring Tool Suite 4.desktop[1878]:         at org.eclipse.swt.widgets.Control.windowProc(Control.java:6524)
Nov 10 15:56:54 localhost.localdomain Spring Tool Suite 4.desktop[1878]:         at org.eclipse.swt.widgets.Display.windowProc(Display.java:6014)
Nov 10 15:56:54 localhost.localdomain Spring Tool Suite 4.desktop[1878]:         at org.eclipse.swt.internal.gtk.GTK._gtk_main_do_event(Native Method)
Nov 10 15:56:54 localhost.localdomain Spring Tool Suite 4.desktop[1878]:         at org.eclipse.swt.internal.gtk.GTK.gtk_main_do_event(GTK.java:4118)
Nov 10 15:56:54 localhost.localdomain Spring Tool Suite 4.desktop[1878]:         at org.eclipse.swt.widgets.Display.eventProc(Display.java:1414)
Nov 10 15:56:54 localhost.localdomain Spring Tool Suite 4.desktop[1878]:         at org.eclipse.swt.internal.gtk.OS._g_main_context_iteration(Native Method)
Nov 10 15:56:54 localhost.localdomain Spring Tool Suite 4.desktop[1878]:         at org.eclipse.swt.internal.gtk.OS.g_main_context_iteration(OS.java:1596)
Nov 10 15:56:54 localhost.localdomain Spring Tool Suite 4.desktop[1878]:         at org.eclipse.swt.widgets.Display.readAndDispatch(Display.java:4581)
Nov 10 15:56:54 localhost.localdomain Spring Tool Suite 4.desktop[1878]:         at org.eclipse.e4.ui.internal.workbench.swt.PartRenderingEngine$5.run(PartRenderingEngine.java:1173)
Nov 10 15:56:54 localhost.localdomain Spring Tool Suite 4.desktop[1878]:         at org.eclipse.core.databinding.observable.Realm.runWithDefault(Realm.java:339)
Nov 10 15:56:54 localhost.localdomain Spring Tool Suite 4.desktop[1878]:         at org.eclipse.e4.ui.internal.workbench.swt.PartRenderingEngine.run(PartRenderingEngine.java:1062)
Nov 10 15:56:54 localhost.localdomain Spring Tool Suite 4.desktop[1878]:         at org.eclipse.e4.ui.internal.workbench.E4Workbench.createAndRunUI(E4Workbench.java:156)
Nov 10 15:56:54 localhost.localdomain Spring Tool Suite 4.desktop[1878]:         at org.eclipse.ui.internal.Workbench.lambda$3(Workbench.java:628)
Nov 10 15:56:54 localhost.localdomain Spring Tool Suite 4.desktop[1878]:         at org.eclipse.core.databinding.observable.Realm.runWithDefault(Realm.java:339)
Nov 10 15:56:54 localhost.localdomain Spring Tool Suite 4.desktop[1878]:         at org.eclipse.ui.internal.Workbench.createAndRunWorkbench(Workbench.java:563)
Nov 10 15:56:54 localhost.localdomain Spring Tool Suite 4.desktop[1878]:         at org.eclipse.ui.PlatformUI.createAndRunWorkbench(PlatformUI.java:151)
Nov 10 15:56:54 localhost.localdomain Spring Tool Suite 4.desktop[1878]:         at org.eclipse.ui.internal.ide.application.IDEApplication.start(IDEApplication.java:155)
Nov 10 15:56:54 localhost.localdomain Spring Tool Suite 4.desktop[1878]:         at org.eclipse.equinox.internal.app.EclipseAppHandle.run(EclipseAppHandle.java:199)
Nov 10 15:56:54 localhost.localdomain Spring Tool Suite 4.desktop[1878]:         at org.eclipse.core.runtime.internal.adaptor.EclipseAppLauncher.runApplication(EclipseAppLauncher.java:137)
Nov 10 15:56:54 localhost.localdomain Spring Tool Suite 4.desktop[1878]:         at org.eclipse.core.runtime.internal.adaptor.EclipseAppLauncher.start(EclipseAppLauncher.java:107)
Nov 10 15:56:54 localhost.localdomain Spring Tool Suite 4.desktop[1878]:         at org.eclipse.core.runtime.adaptor.EclipseStarter.run(EclipseStarter.java:391)
Nov 10 15:56:54 localhost.localdomain Spring Tool Suite 4.desktop[1878]:         at org.eclipse.core.runtime.adaptor.EclipseStarter.run(EclipseStarter.java:246)
Nov 10 15:56:54 localhost.localdomain Spring Tool Suite 4.desktop[1878]:         at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
Nov 10 15:56:54 localhost.localdomain Spring Tool Suite 4.desktop[1878]:         at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
Nov 10 15:56:54 localhost.localdomain Spring Tool Suite 4.desktop[1878]:         at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
Nov 10 15:56:54 localhost.localdomain Spring Tool Suite 4.desktop[1878]:         at java.lang.reflect.Method.invoke(Method.java:498)
Nov 10 15:56:54 localhost.localdomain Spring Tool Suite 4.desktop[1878]:         at org.eclipse.equinox.launcher.Main.invokeFramework(Main.java:659)
Nov 10 15:56:54 localhost.localdomain Spring Tool Suite 4.desktop[1878]:         at org.eclipse.equinox.launcher.Main.basicRun(Main.java:595)
Nov 10 15:56:54 localhost.localdomain Spring Tool Suite 4.desktop[1878]:         at org.eclipse.equinox.launcher.Main.run(Main.java:1501)
Nov 10 15:56:54 localhost.localdomain Spring Tool Suite 4.desktop[1878]:         at org.eclipse.equinox.launcher.Main.main(Main.java:1474)

@martinlippert martinlippert transferred this issue from spring-projects/spring-ide Nov 10, 2018

@martinlippert

This comment has been minimized.

Copy link
Member

martinlippert commented Nov 10, 2018

It looks like the language server for spring boot is not responding in time, which then causes the completion processor to timeout and go crazy. To track this down, it would be very interesting what the language server process is doing while this happens. Can you look up the process ID (you will see that process showing up in the list when you do a jps) and capture a thread dump for that process while the UI hangs? I really would like to take a look inside.

You could also enable the language server logging in the preferences (Language Servers -> Spring Language Servers). Once you did that and the language server got restarted (for example when you restarted STS or after closing every open Java and property editor and opening a new one), the log output of the language server will appear in the Console View. Maybe that reveals some interesting things, too.

@martinlippert

This comment has been minimized.

Copy link
Member

martinlippert commented Nov 10, 2018

(oh, and btw, I moved this issue over to the sts4 project, which is the one for the STS4 efforts)

@jonashungershausen

This comment has been minimized.

Copy link
Author

jonashungershausen commented Nov 12, 2018

I didn't face this issue anymore after I opened this issue oddly. But that could be because I switched back to Java8. I will now change it back to Java11 to track this down. I will post the logs if I encounter it again.

(oh, and btw, I moved this issue over to the sts4 project, which is the one for the STS4 efforts)

Oh. must've missed that, sorry about that.

@martinlippert

This comment has been minimized.

Copy link
Member

martinlippert commented Nov 13, 2018

No problems at all and glad to hear that this is working again for you. So lets close this issue here for now, but please add the results from your Java11 experiences here, so that we can re-open this in case.

@jonashungershausen

This comment has been minimized.

Copy link
Author

jonashungershausen commented Nov 16, 2018

The problem just reappeared in a Java8 environment. This is a thread dump I took via jstack [1]. I took exactly during the UI freeze. The Exception from #136 (comment) is the same.

I'm not sure if this is what you needed and since the problem will go away when I need to restart the IDE to enable the language server logs I can't do that right now.

[1]:

2018-11-16 10:19:14
Full thread dump OpenJDK 64-Bit Server VM (25.181-b02 mixed mode):

"Attach Listener" #17 daemon prio=9 os_prio=0 tid=0x00007f33e8001000 nid=0x1577 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
	- None

"SimpleLanguaserver main thread" #16 daemon prio=5 os_prio=0 tid=0x00007f33c8754000 nid=0xe20 waiting on condition [0x00007f33ee22c000]
   java.lang.Thread.State: WAITING (parking)
	at sun.misc.Unsafe.park(Native Method)
	- parking to wait for  <0x00000000f0602a28> (a java.util.concurrent.CompletableFuture$Signaller)
	at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
	at java.util.concurrent.CompletableFuture$Signaller.block(CompletableFuture.java:1693)
	at java.util.concurrent.ForkJoinPool.managedBlock(ForkJoinPool.java:3323)
	at java.util.concurrent.CompletableFuture.waitingGet(CompletableFuture.java:1729)
	at java.util.concurrent.CompletableFuture.join(CompletableFuture.java:1934)
	at org.springframework.ide.vscode.commons.languageserver.jdt.ls.ClasspathListenerManager.addClasspathListener(ClasspathListenerManager.java:81)
	at org.springframework.ide.vscode.commons.languageserver.util.SimpleLanguageServer.addClasspathListener(SimpleLanguageServer.java:684)
	- locked <0x00000000c0015e68> (a org.springframework.ide.vscode.commons.languageserver.util.SimpleLanguageServer)
	at org.springframework.ide.vscode.boot.jdt.ls.JdtLsProjectCache.initialize(JdtLsProjectCache.java:168)
	at org.springframework.ide.vscode.boot.jdt.ls.JavaProjectsServiceWithFallback.lambda$new$1(JavaProjectsServiceWithFallback.java:48)
	at org.springframework.ide.vscode.boot.jdt.ls.JavaProjectsServiceWithFallback$$Lambda$173/1846412426.run(Unknown Source)
	at org.springframework.ide.vscode.commons.languageserver.util.SimpleLanguageServer.lambda$onInitialized$14(SimpleLanguageServer.java:661)
	at org.springframework.ide.vscode.commons.languageserver.util.SimpleLanguageServer$$Lambda$174/1206883981.accept(Unknown Source)
	at java.util.concurrent.CompletableFuture.uniAccept(CompletableFuture.java:656)
	at java.util.concurrent.CompletableFuture$UniAccept.tryFire(CompletableFuture.java:632)
	at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:474)
	at java.util.concurrent.CompletableFuture.complete(CompletableFuture.java:1962)
	at org.springframework.ide.vscode.commons.languageserver.util.SimpleLanguageServer.lambda$initialized$8(SimpleLanguageServer.java:276)
	at org.springframework.ide.vscode.commons.languageserver.util.SimpleLanguageServer$$Lambda$281/291100992.run(Unknown Source)
	at org.springframework.ide.vscode.commons.util.AsyncRunner.lambda$execute$1(AsyncRunner.java:66)
	at org.springframework.ide.vscode.commons.util.AsyncRunner$$Lambda$282/1553609669.run(Unknown Source)
	at reactor.core.publisher.MonoRunnable.call(MonoRunnable.java:67)
	at reactor.core.publisher.MonoRunnable.call(MonoRunnable.java:30)
	at reactor.core.publisher.FluxSubscribeOnCallable$CallableSubscribeOnSubscription.run(FluxSubscribeOnCallable.java:225)
	at reactor.core.scheduler.SchedulerTask.call(SchedulerTask.java:50)
	at reactor.core.scheduler.SchedulerTask.call(SchedulerTask.java:27)
	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at java.lang.Thread.run(Thread.java:748)

   Locked ownable synchronizers:
	- <0x00000000f024a098> (a java.util.concurrent.ThreadPoolExecutor$Worker)

"pool-3-thread-1" #15 prio=5 os_prio=0 tid=0x00007f33d41a7800 nid=0xe1b runnable [0x00007f34081dd000]
   java.lang.Thread.State: RUNNABLE
	at java.io.FileInputStream.readBytes(Native Method)
	at java.io.FileInputStream.read(FileInputStream.java:255)
	at java.io.BufferedInputStream.fill(BufferedInputStream.java:246)
	at java.io.BufferedInputStream.read(BufferedInputStream.java:265)
	- locked <0x00000000c003d848> (a java.io.BufferedInputStream)
	at org.eclipse.lsp4j.jsonrpc.json.StreamMessageProducer.listen(StreamMessageProducer.java:75)
	at org.eclipse.lsp4j.jsonrpc.json.ConcurrentMessageProcessor.run(ConcurrentMessageProcessor.java:95)
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at java.lang.Thread.run(Thread.java:748)

   Locked ownable synchronizers:
	- <0x00000000eebb7228> (a java.util.concurrent.ThreadPoolExecutor$Worker)

"DestroyJavaVM" #14 prio=5 os_prio=0 tid=0x00007f342c00b000 nid=0xe02 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
	- None

"LanguageServerApp-lifecycle" #13 prio=5 os_prio=0 tid=0x00007f342ccfc800 nid=0xe1a waiting on condition [0x00007f34086e7000]
   java.lang.Thread.State: WAITING (parking)
	at sun.misc.Unsafe.park(Native Method)
	- parking to wait for  <0x00000000eebb70f8> (a java.util.concurrent.FutureTask)
	at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
	at java.util.concurrent.FutureTask.awaitDone(FutureTask.java:429)
	at java.util.concurrent.FutureTask.get(FutureTask.java:191)
	at org.eclipse.lsp4j.jsonrpc.json.ConcurrentMessageProcessor$1.get(ConcurrentMessageProcessor.java:44)
	at org.eclipse.lsp4j.jsonrpc.json.ConcurrentMessageProcessor$1.get(ConcurrentMessageProcessor.java:40)
	at org.springframework.ide.vscode.commons.languageserver.LanguageServerRunner.startAsClient(LanguageServerRunner.java:139)
	at org.springframework.ide.vscode.commons.languageserver.LanguageServerRunner.start(LanguageServerRunner.java:94)
	at org.springframework.ide.vscode.commons.languageserver.LanguageServerRunner.lambda$run$0(LanguageServerRunner.java:61)
	at org.springframework.ide.vscode.commons.languageserver.LanguageServerRunner$$Lambda$260/2050404090.run(Unknown Source)
	at java.lang.Thread.run(Thread.java:748)

   Locked ownable synchronizers:
	- None

"Service Thread" #8 daemon prio=9 os_prio=0 tid=0x00007f342c187800 nid=0xe0f runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
	- None

"C1 CompilerThread2" #7 daemon prio=9 os_prio=0 tid=0x00007f342c184800 nid=0xe0e waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
	- None

"C2 CompilerThread1" #6 daemon prio=9 os_prio=0 tid=0x00007f342c183000 nid=0xe0d waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
	- None

"C2 CompilerThread0" #5 daemon prio=9 os_prio=0 tid=0x00007f342c180000 nid=0xe0c waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
	- None

"Signal Dispatcher" #4 daemon prio=9 os_prio=0 tid=0x00007f342c17c000 nid=0xe0b runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
	- None

"Finalizer" #3 daemon prio=8 os_prio=0 tid=0x00007f342c14b800 nid=0xe0a in Object.wait() [0x00007f3408fee000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	- waiting on <0x00000000c00156a0> (a java.lang.ref.ReferenceQueue$Lock)
	at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:144)
	- locked <0x00000000c00156a0> (a java.lang.ref.ReferenceQueue$Lock)
	at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:165)
	at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:216)

   Locked ownable synchronizers:
	- None

"Reference Handler" #2 daemon prio=10 os_prio=0 tid=0x00007f342c147000 nid=0xe09 in Object.wait() [0x00007f34090ef000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	- waiting on <0x00000000c0015858> (a java.lang.ref.Reference$Lock)
	at java.lang.Object.wait(Object.java:502)
	at java.lang.ref.Reference.tryHandlePending(Reference.java:191)
	- locked <0x00000000c0015858> (a java.lang.ref.Reference$Lock)
	at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:153)

   Locked ownable synchronizers:
	- None

"VM Thread" os_prio=0 tid=0x00007f342c13f800 nid=0xe08 runnable 

"GC task thread#0 (ParallelGC)" os_prio=0 tid=0x00007f342c020000 nid=0xe04 runnable 

"GC task thread#1 (ParallelGC)" os_prio=0 tid=0x00007f342c022000 nid=0xe05 runnable 

"GC task thread#2 (ParallelGC)" os_prio=0 tid=0x00007f342c023800 nid=0xe06 runnable 

"GC task thread#3 (ParallelGC)" os_prio=0 tid=0x00007f342c025800 nid=0xe07 runnable 

"VM Periodic Task Thread" os_prio=0 tid=0x00007f342c18a000 nid=0xe10 waiting on condition 

JNI global references: 832
@kdvolder

This comment has been minimized.

Copy link
Member

kdvolder commented Nov 16, 2018

Thanks for that. It is a useful piece of information. Probably not enough yet to solve the whole puzzle, but at least a piece of the puzzle :-)

It shows that Eclipse process is trying to send classpath information to the spring-boot language server. My guess is that this is stuck for some reason. What reason? I don't know. We might know more if we can get two additional dump/logs.

  1. the output from language server console in Eclipse (yes, I read and understand why you didn't include it :-)
  2. a jstack dump of the language server process.

So if it should happen again, could you try collecting this info (actually the number 2 is more important than the server logs, though both could provide valuable clues).

For the server process, use jps to identify it. It should look something like this:

$ jps
...
11469 1.1.1.201811071816-spring-boot-language-server-1.1.1-SNAPSHOT.jar
...
@jonashungershausen

This comment has been minimized.

Copy link
Author

jonashungershausen commented Nov 17, 2018

the output from language server console in Eclipse (yes, I read and understand why you didn't include it :-)

I've turned on the logs now, and will update this thread if I get something.

a jstack dump of the language server process.

I actually thought I did exactly that? I typed in jps found the process ID of the language server (not the eclipse equinox launcher) and then typed jstack -l <id from jps> and got the output from #136 (comment).
I don't have much knowledge in Java process debugging so I researched online and mainly took the advice from the first articles I found.

@kdvolder

This comment has been minimized.

Copy link
Member

kdvolder commented Nov 19, 2018

I actually thought I did exactly that?

Actually... yes, you are right.

So I must correct what I said before. The trace is not showing being stuck when sending classpath information, but rather being stuck when registering for classpath information.

Either way, I guess the picture only shows half of what we want to see. The language server is trying to connect back to Eclipse to ask/subscribe for classpath change events. If that is 'stuck' it probably means the 'other end' is not responding. So we have to try to determine why. The other end in this case is Eclipse.

So a jps of the Eclipse process might be helpful, as well as the contents from the Eclipse error log.

I think your first paste was a fragment from the stuck Eclipse. But it seems to have been 'chopped'.

I suspect what is going on is some kind of a 'deadlock' situation where they are both kind of stuck waiting for eachother.

Sorry for the confusion. With two processes I got a little confused and junped to the wrong conclusion.

And sorry for asking more of you, you have been very accomodating so far. But... if it happens again, please get dumps from both stuck processes. And hopefully that will allow us to see exactly how things are getting 'deadlocked' waiting for eachother.

@kdvolder

This comment has been minimized.

Copy link
Member

kdvolder commented Nov 19, 2018

Also, if you collect the dumps, please don't try to cut out the 'interesting pieces'. I understand you might think this is helpful, and appreciate that intention. But it is better to have some extra but useless info than to accidentally leave out some pieces that could help us build a more complete picture of what is going on.

@kdvolder

This comment has been minimized.

Copy link
Member

kdvolder commented Nov 19, 2018

Afterthought. Even if we can't get more dumps perhaps there is enough information to attempt to 'unblock' this deadlock. This fragment of the last dump:

"SimpleLanguaserver main thread" #16 daemon prio=5 os_prio=0 tid=0x00007f33c8754000 nid=0xe20 waiting on condition [0x00007f33ee22c000]
   java.lang.Thread.State: WAITING (parking)
	at sun.misc.Unsafe.park(Native Method)
	- parking to wait for  <0x00000000f0602a28> (a java.util.concurrent.CompletableFuture$Signaller)
	at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
	at java.util.concurrent.CompletableFuture$Signaller.block(CompletableFuture.java:1693)
	at java.util.concurrent.ForkJoinPool.managedBlock(ForkJoinPool.java:3323)
	at java.util.concurrent.CompletableFuture.waitingGet(CompletableFuture.java:1729)
	at java.util.concurrent.CompletableFuture.join(CompletableFuture.java:1934)
	at org.springframework.ide.vscode.commons.languageserver.jdt.ls.ClasspathListenerManager.addClasspathListener(ClasspathListenerManager.java:81)
	at org.springframework.ide.vscode.commons.languageserver.util.SimpleLanguageServer.addClasspathListener(SimpleLanguageServer.java:684)
	- locked <0x00000000c0015e68> (a org.springframework.ide.vscode.commons.languageserver.util.SimpleLanguageServer)
	at org.springframework.ide.vscode.boot.jdt.ls.JdtLsProjectCache.initialize(JdtLsProjectCache.java:168)
	at org.springframework.ide.vscode.boot.jdt.ls.JavaProjectsServiceWithFallback.lambda$new$1(JavaProjectsServiceWithFallback.java:48)
	at org.springframework.ide.vscode.boot.jdt.ls.JavaProjectsServiceWithFallback$$Lambda$173/1846412426.run(Unknown Source)
	at org.springframework.ide.vscode.commons.languageserver.util.SimpleLanguageServer.lambda$onInitialized$14(SimpleLanguageServer.java:661)
	at org.springframework.ide.vscode.commons.languageserver.util.SimpleLanguageServer$$Lambda$174/1206883981.accept(Unknown Source)
	at java.util.concurrent.CompletableFuture.uniAccept(CompletableFuture.java:656)
	at java.util.concurrent.CompletableFuture$UniAccept.tryFire(CompletableFuture.java:632)
	at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:474)
	at java.util.concurrent.CompletableFuture.complete(CompletableFuture.java:1962)
	at org.springframework.ide.vscode.commons.languageserver.util.SimpleLanguageServer.lambda$initialized$8(SimpleLanguageServer.java:276)
	at org.springframework.ide.vscode.commons.languageserver.util.SimpleLanguageServer$$Lambda$281/291100992.run(Unknown Source)
	at org.springframework.ide.vscode.commons.util.AsyncRunner.lambda$execute$1(AsyncRunner.java:66)
	at org.springframework.ide.vscode.commons.util.AsyncRunner$$Lambda$282/1553609669.run(Unknown Source)
	at reactor.core.publisher.MonoRunnable.call(MonoRunnable.java:67)
	at reactor.core.publisher.MonoRunnable.call(MonoRunnable.java:30)
	at reactor.core.publisher.FluxSubscribeOnCallable$CallableSubscribeOnSubscription.run(FluxSubscribeOnCallable.java:225)
	at reactor.core.scheduler.SchedulerTask.call(SchedulerTask.java:50)
	at reactor.core.scheduler.SchedulerTask.call(SchedulerTask.java:27)
	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at java.lang.Thread.run(Thread.java:748)

is almost certainly part of the 'deadlock cycle'. So even without knowing the cause / shape of the whole cycle, if we somehow make this more asynchronous so it doesn't block, it will probably break the cycle.

@kdvolder kdvolder reopened this Nov 20, 2018

kdvolder added a commit that referenced this issue Nov 21, 2018

@spring-issuemaster spring-issuemaster added finished and removed started labels Nov 21, 2018

@kdvolder

This comment has been minimized.

Copy link
Member

kdvolder commented Nov 21, 2018

@jonashungershausen
I've pushed a (attempted) fix. It asynchronises theblocking calls in the trace we suspect of being the culprit.

I'm really not sure this is actually a real fix as don't still fully understand what is happening. But seeing as these are good changes to make regardless I went ahead with them.

It would be great if you could try using the latest nightly build, which includes the fix, and see if it helps alleviate the problem you are experiencing.

You can download a nightly snapshot from here:

http://dist.springsource.com/snapshot/STS4/nightly-distributions.html

@jonashungershausen

This comment has been minimized.

Copy link
Author

jonashungershausen commented Nov 22, 2018

And sorry for asking more of you, you have been very accomodating so far. But... if it happens again, please get dumps from both stuck processes. And hopefully that will allow us to see exactly how things are getting 'deadlocked' waiting for eachother.

No problem at all! I'm happy to help and as I'm using the STS on a daily basis I'm very interested in it working properly ;) (Which it does, otherwise).

Also, if you collect the dumps, please don't try to cut out the 'interesting pieces'. I understand you might think this is helpful, and appreciate that intention. But it is better to have some extra but useless info than to accidentally leave out some pieces that could help us build a more complete picture of what is going on.

I didn't and I will not in the future, I don't really have a clue about what I'm looking at with these dumps so I will just let you decide whats important and what's not.

I will try the new build today or tomorrow and report back. The problem with this error is obviously that it's not really regularly happening and thus I can't say if it's fixed or not. But I will report any finding I get back here! Also thank you very much for your work here.

@kdvolder

This comment has been minimized.

Copy link
Member

kdvolder commented Nov 22, 2018

can't say if it's fixed or not

Yes, that is the problem :-) Neither can I.

Just use it for a bit and report problems if you see any. If no problems... we will assume its fixed :-) If you do see prioblems we can try to fix them.

@jonashungershausen

This comment has been minimized.

Copy link
Author

jonashungershausen commented Nov 22, 2018

I came back home after I left the STS open on my suspended laptop for over 24 Hours and I got the same problem again. I figured I take the opportunity to dump the Eclipse & the langugage server thread while it was hanging but this is still with Version: 4.0.1.RELEASE. You can find the file attached. The file contains the dump of the eclipse process & the language server a little bit below.

Also there is no output in the language server console log.

jstack dump.txt

@kdvolder

This comment has been minimized.

Copy link
Member

kdvolder commented Nov 28, 2018

Haven't gotten any reports about problems with the snapshot builds made after my supposed fix. So will assume this is fixed for now.

@kdvolder kdvolder closed this Nov 28, 2018

@martinlippert martinlippert added this to the 4.0.2 milestone Dec 10, 2018

@semteXKG

This comment has been minimized.

Copy link

semteXKG commented Dec 17, 2018

had the same issue, update to 4.0.2 fixed it for me.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
You can’t perform that action at this time.