[NETBEANS-5744] Avoid java.io deadlock of close vs. pending read. #2986
Conversation
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
entlicher
requested changes
Jun 3, 2021
...est/unit/src/org/netbeans/modules/java/lsp/server/debugging/launch/NbProcessConsoleTest.java
Outdated
Show resolved
Hide resolved
...a.lsp.server/src/org/netbeans/modules/java/lsp/server/debugging/launch/NbProcessConsole.java
Show resolved
Hide resolved
sdedic
force-pushed
the
lsp/consoleInputLockup
branch
from
a5040c7
to
ba5bb8a
Compare
|
Sharing the deadlock stacktraces would help me to investigate the sources at the right locations. |
JaroslavTulach
approved these changes
Jun 4, 2021
sdedic
commented
Jun 4, 2021
| @Override | ||
| public void close() throws IOException { | ||
| // the underlying StreamDecoder would just block on synchronized read(); close the underlying stream. | ||
| ioCtx.getStdIn().close(); |
There was a problem hiding this comment.
Without this explicit close, the following lockup occurs when LSP client initiates the process:
"pool-2-thread-1" #52 prio=5 os_prio=0 cpu=151.58ms
elapsed=22.34s tid=0x00007f3b388b3000 nid=0x43c3 waiting for monitor entry [0x00007f3b5d1bb000]
java.lang.Thread.State: BLOCKED (on object monitor)
at sun.nio.cs.StreamDecoder.close(java.base@11.0.5/StreamDecoder.java:191)
- waiting to lock <0x000000061a4d2068> (a org.netbeans.modules.java.lsp.server.ui.AbstractLspInputOutputProvider$LspIO$1)
at java.io.InputStreamReader.close(java.base@11.0.5/InputStreamReader.java:200)
at org.netbeans.modules.java.lsp.server.ui.AbstractLspInputOutputProvider$LspIO$1.close(AbstractLspInputOutputProvider.java:152)
at org.openide.util.io.ReaderInputStream.close(ReaderInputStream.java:130)
at org.netbeans.modules.gradle.execute.GradleDaemonExecutor.closeInOutErr(GradleDaemonExecutor.java:348)
- locked <0x000000061a4c7440> (a org.netbeans.modules.gradle.execute.GradleDaemonExecutor)
at org.netbeans.modules.gradle.execute.GradleDaemonExecutor.cancel(GradleDaemonExecutor.java:368)
at org.netbeans.modules.progress.spi.InternalHandle.requestCancel(InternalHandle.java:364)
at org.netbeans.modules.java.lsp.server.progress.LspInternalHandle.forceRequestCancel(LspInternalHandle.java:93)
at org.netbeans.modules.java.lsp.server.debugging.DebugAdapterContext.requestProcessTermination(DebugAdapterContext.java:140)
at org.netbeans.modules.java.lsp.server.debugging.launch.NbDisconnectRequestHandler.destroyDebugSession(NbDisconnectRequestHandler.java:49)
at org.netbeans.modules.java.lsp.server.debugging.launch.NbDisconnectRequestHandler.disconnect(NbDisconnectRequestHandler.java:35)
at org.netbeans.modules.java.lsp.server.debugging.NbProtocolServer.disconnect(NbProtocolServer.java:180)
at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(java.base@11.0.5/Native Method)
at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(java.base@11.0.5/NativeMethodAccessorImpl.java:62)
at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(java.base@11.0.5/DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(java.base@11.0.5/Method.java:566)
at org.eclipse.lsp4j.jsonrpc.services.GenericEndpoint.lambda$null$0(GenericEndpoint.java:65)
at org.eclipse.lsp4j.jsonrpc.services.GenericEndpoint$$Lambda$213/0x0000000800468440.apply(Unknown Source)
at org.eclipse.lsp4j.jsonrpc.services.GenericEndpoint.request(GenericEndpoint.java:120)
at org.eclipse.lsp4j.jsonrpc.RemoteEndpoint.handleRequest(RemoteEndpoint.java:261)
at org.eclipse.lsp4j.jsonrpc.RemoteEndpoint.consume(RemoteEndpoint.java:190)
at org.netbeans.modules.java.lsp.server.debugging.Debugger$ConsumeWithLookup.lambda$consume$0(Debugger.java:92)
at org.netbeans.modules.java.lsp.server.debugging.Debugger$ConsumeWithLookup$$Lambda$771/0x0000000800aa7c40.run(Unknown Source)
at org.netbeans.modules.openide.util.GlobalLookup.execute(GlobalLookup.java:45)
at org.openide.util.lookup.Lookups.executeWith(Lookups.java:278)
at org.netbeans.modules.java.lsp.server.debugging.Debugger$ConsumeWithLookup.consume(Debugger.java:90)
at org.eclipse.lsp4j.jsonrpc.json.StreamMessageProducer.handleMessage(StreamMessageProducer.java:194)
at org.eclipse.lsp4j.jsonrpc.json.StreamMessageProducer.listen(StreamMessageProducer.java:94)
at org.eclipse.lsp4j.jsonrpc.json.ConcurrentMessageProcessor.run(ConcurrentMessageProcessor.java:113)
at java.util.concurrent.Executors$RunnableAdapter.call(java.base@11.0.5/Executors.java:515)
at java.util.concurrent.FutureTask.run(java.base@11.0.5/FutureTask.java:264)
at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@11.0.5/ThreadPoolExecutor.java:1128)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@11.0.5/ThreadPoolExecutor.java:628)
at java.lang.Thread.run(java.base@11.0.5/Thread.java:834)
....
"DisconnectableInputStream source reader" #63 daemon prio=5 os_prio=0 cpu=1.19ms elapsed=20.00s tid=0x00007f3a796c2800 nid=0x43f2 in Object.wait() [0x00007f3a993e7000]
java.lang.Thread.State: TIMED_WAITING (on object monitor)
at java.lang.Object.wait(java.base@11.0.5/Native Method)
- waiting on <no object reference available>
at java.io.PipedInputStream.read(java.base@11.0.5/PipedInputStream.java:326)
- waiting to re-lock in wait() <0x000000061a485ed8> (a org.netbeans.modules.java.lsp.server.debugging.launch.NbProcessConsole$1)
at java.io.PipedInputStream.read(java.base@11.0.5/PipedInputStream.java:377)
- waiting to re-lock in wait() <0x000000061a485ed8> (a org.netbeans.modules.java.lsp.server.debugging.launch.NbProcessConsole$1)
at sun.nio.cs.StreamDecoder.readBytes(java.base@11.0.5/StreamDecoder.java:284)
at sun.nio.cs.StreamDecoder.implRead(java.base@11.0.5/StreamDecoder.java:326)
at sun.nio.cs.StreamDecoder.read(java.base@11.0.5/StreamDecoder.java:178)
- locked <0x000000061a4d2068> (a org.netbeans.modules.java.lsp.server.ui.AbstractLspInputOutputProvider$LspIO$1)
at sun.nio.cs.StreamDecoder.read0(java.base@11.0.5/StreamDecoder.java:127)
- locked <0x000000061a4d2068> (a org.netbeans.modules.java.lsp.server.ui.AbstractLspInputOutputProvider$LspIO$1)
at sun.nio.cs.StreamDecoder.read(java.base@11.0.5/StreamDecoder.java:112)
at java.io.InputStreamReader.read(java.base@11.0.5/InputStreamReader.java:168)
at org.openide.util.io.ReaderInputStream.read(ReaderInputStream.java:65)
at org.openide.util.io.ReaderInputStream.read(ReaderInputStream.java:88)
at org.gradle.util.DisconnectableInputStream$1.run(DisconnectableInputStream.java:98)
at java.lang.Thread.run(java.base@11.0.5/Thread.java:834)
The cancel request waits in sun.nio.cs.StreamDecoder.close blocked on monitor held by pending sun.nio.cs.StreamDecoder.read
Because of NETBEANS-2038, streams are closed before Gradle is instructed to stop the build. It could be possible to flag + filter the streams in Gradle, or close input stream after instructing Gradle to stop. The PipedInputStream waits on an input from LSP client which might never come.
Full thread dump:
threaddump-streamdecoder.txt
sdedic
commented
Jun 4, 2021
| // Bug in Piped*Stream: in.close() closes, but does | ||
| // not unblock waiters, nor returns -1 from writer to | ||
| // stop waiting. Close the writer - will also notifyAll(). | ||
| inputSource.close(); |
There was a problem hiding this comment.
Without this explicit close, the PipedInputStream won't wake up or receive -1 from the writer (which causes its read to return and release lock):
"pool-2-thread-1" #48 prio=5 os_prio=0 cpu=305.23ms elapsed=44.59s tid=0x00007feefc052800 nid=0x54c4 waiting for monitor entry [0x00007fef03703000]
java.lang.Thread.State: BLOCKED (on object monitor)
at sun.nio.cs.StreamDecoder.close(java.base@11.0.5/StreamDecoder.java:190)
- waiting to lock <0x000000060d8752c0> (a org.netbeans.modules.java.lsp.server.ui.AbstractLspInputOutputProvider$LspIO$1)
at java.io.InputStreamReader.close(java.base@11.0.5/InputStreamReader.java:200)
at org.netbeans.modules.java.lsp.server.ui.AbstractLspInputOutputProvider$LspIO$1.close(AbstractLspInputOutputProvider.java:152)
at org.openide.util.io.ReaderInputStream.close(ReaderInputStream.java:130)
at org.netbeans.modules.gradle.execute.GradleDaemonExecutor.closeInOutErr(GradleDaemonExecutor.java:348)
- locked <0x000000060ccc1400> (a org.netbeans.modules.gradle.execute.GradleDaemonExecutor)
at org.netbeans.modules.gradle.execute.GradleDaemonExecutor.cancel(GradleDaemonExecutor.java:368)
at org.netbeans.modules.progress.spi.InternalHandle.requestCancel(InternalHandle.java:364)
at org.netbeans.modules.java.lsp.server.progress.LspInternalHandle.forceRequestCancel(LspInternalHandle.java:93)
at org.netbeans.modules.java.lsp.server.debugging.DebugAdapterContext.requestProcessTermination(DebugAdapterContext.java:140)
at org.netbeans.modules.java.lsp.server.debugging.launch.NbDisconnectRequestHandler.destroyDebugSession(NbDisconnectRequestHandler.java:49)
at org.netbeans.modules.java.lsp.server.debugging.launch.NbDisconnectRequestHandler.disconnect(NbDisconnectRequestHandler.java:35)
at org.netbeans.modules.java.lsp.server.debugging.NbProtocolServer.disconnect(NbProtocolServer.java:180)
at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(java.base@11.0.5/Native Method)
at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(java.base@11.0.5/NativeMethodAccessorImpl.java:62)
at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(java.base@11.0.5/DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(java.base@11.0.5/Method.java:566)
at org.eclipse.lsp4j.jsonrpc.services.GenericEndpoint.lambda$null$0(GenericEndpoint.java:65)
at org.eclipse.lsp4j.jsonrpc.services.GenericEndpoint$$Lambda$216/0x000000080043d440.apply(Unknown Source)
at org.eclipse.lsp4j.jsonrpc.services.GenericEndpoint.request(GenericEndpoint.java:120)
at org.eclipse.lsp4j.jsonrpc.RemoteEndpoint.handleRequest(RemoteEndpoint.java:261)
at org.eclipse.lsp4j.jsonrpc.RemoteEndpoint.consume(RemoteEndpoint.java:190)
at org.netbeans.modules.java.lsp.server.debugging.Debugger$ConsumeWithLookup.lambda$consume$0(Debugger.java:92)
at org.netbeans.modules.java.lsp.server.debugging.Debugger$ConsumeWithLookup$$Lambda$259/0x00000008005ab040.run(Unknown Source)
at org.netbeans.modules.openide.util.GlobalLookup.execute(GlobalLookup.java:45)
at org.openide.util.lookup.Lookups.executeWith(Lookups.java:278)
at org.netbeans.modules.java.lsp.server.debugging.Debugger$ConsumeWithLookup.consume(Debugger.java:90)
at org.eclipse.lsp4j.jsonrpc.json.StreamMessageProducer.handleMessage(StreamMessageProducer.java:194)
at org.eclipse.lsp4j.jsonrpc.json.StreamMessageProducer.listen(StreamMessageProducer.java:94)
at org.eclipse.lsp4j.jsonrpc.json.ConcurrentMessageProcessor.run(ConcurrentMessageProcessor.java:113)
at java.util.concurrent.Executors$RunnableAdapter.call(java.base@11.0.5/Executors.java:515)
at java.util.concurrent.FutureTask.run(java.base@11.0.5/FutureTask.java:264)
at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@11.0.5/ThreadPoolExecutor.java:1128)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@11.0.5/ThreadPoolExecutor.java:628)
at java.lang.Thread.run(java.base@11.0.5/Thread.java:834)
...
"DisconnectableInputStream source reader" #58 daemon prio=5 os_prio=0 cpu=2.40ms elapsed=42.47s tid=0x00007feee14f8800 nid=0x54d6 in Object.wait() [0x00007fef03503000]
java.lang.Thread.State: TIMED_WAITING (on object monitor)
at java.lang.Object.wait(java.base@11.0.5/Native Method)
- waiting on <no object reference available>
at java.io.PipedInputStream.read(java.base@11.0.5/PipedInputStream.java:326)
- waiting to re-lock in wait() <0x000000060d8752e0> (a org.netbeans.modules.java.lsp.server.debugging.launch.NbProcessConsole$1)
at java.io.PipedInputStream.read(java.base@11.0.5/PipedInputStream.java:377)
- waiting to re-lock in wait() <0x000000060d8752e0> (a org.netbeans.modules.java.lsp.server.debugging.launch.NbProcessConsole$1)
at sun.nio.cs.StreamDecoder.readBytes(java.base@11.0.5/StreamDecoder.java:284)
at sun.nio.cs.StreamDecoder.implRead(java.base@11.0.5/StreamDecoder.java:326)
at sun.nio.cs.StreamDecoder.read(java.base@11.0.5/StreamDecoder.java:178)
- locked <0x000000060d8752c0> (a org.netbeans.modules.java.lsp.server.ui.AbstractLspInputOutputProvider$LspIO$1)
at sun.nio.cs.StreamDecoder.read0(java.base@11.0.5/StreamDecoder.java:127)
- locked <0x000000060d8752c0> (a org.netbeans.modules.java.lsp.server.ui.AbstractLspInputOutputProvider$LspIO$1)
at sun.nio.cs.StreamDecoder.read(java.base@11.0.5/StreamDecoder.java:112)
at java.io.InputStreamReader.read(java.base@11.0.5/InputStreamReader.java:168)
at org.openide.util.io.ReaderInputStream.read(ReaderInputStream.java:65)
at org.openide.util.io.ReaderInputStream.read(ReaderInputStream.java:88)
at org.gradle.util.DisconnectableInputStream$1.run(DisconnectableInputStream.java:98)
at java.lang.Thread.run(java.base@11.0.5/Thread.java:834)
super.close() would block on monitor of this Piped stream that would be still waiting on (never coming) input.
Full thread dump:
threaddump-pipedstream.txt
entlicher
approved these changes
Jun 5, 2021
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.
This suggestion is invalid because no changes were made to the code.
Suggestions cannot be applied while the pull request is closed.
Suggestions cannot be applied while viewing a subset of changes.
Only one suggestion per line can be applied in a batch.
Add this suggestion to a batch that can be applied as a single commit.
Applying suggestions on deleted lines is not supported.
You must change the existing code in this line in order to create a valid suggestion.
Outdated suggestions cannot be applied.
This suggestion has been applied or marked resolved.
Suggestions cannot be applied from pending reviews.
Suggestions cannot be applied on multi-line comments.
Suggestions cannot be applied while the pull request is queued to merge.
Suggestion cannot be applied right now. Please check back later.
During testing of NETBEANS-5744 I have found that there are two lockups related to stream closing, which is done during process termination:
StreamDecodersynchronizes around itsread()(reading the underlying InputStream) and so doesclose. So closing anInputStreamReaderwhile read is pending will block the close() thread.PipedInputStreamclose() just sets a flag, but does not actually wake up potentially waiting reader and does not cause writer to return-1EOF indicator.The patch attempts to fix it, as close() to streams bound to the process I/O may happen asynchronously when the client terminates the process. I've attempted to write tests that check the close can be done from other thread while read is pending / waiting for the data.