Bug ID: JDK-8315544 java/nio/channels/vthread/BlockingChannelOps.java timed out with ZGC

JDK-8315544 : java/nio/channels/vthread/BlockingChannelOps.java timed out with ZGC

Type: Bug
Component: core-libs
Sub-Component: java.nio
Affected Version: 22

Priority: P4
Status: Closed
Resolution: Duplicate
OS: windows
CPU: x86_64

Submitted: 2023-09-01
Updated: 2023-11-20
Resolved: 2023-11-20

Versions (Unresolved/Resolved/Fixed)

The Version table provides details related to the release that this issue/RFE will be addressed.

Unresolved : Release in which this issue/RFE will be addressed.
Resolved: Release in which this issue/RFE has been resolved.
Fixed : Release in which this issue/RFE has been fixed. The release containing this fix may be available for download as an Early Access Release or a General Availability Release.

To download the current JDK release, click here.

Other
tbdResolved

Related Reports

Duplicate :	JDK-8282726 - java/net/vthread/BlockingSocketOps.java timeout/hang intermittently on Windows
Duplicate :	JDK-8314665 - java/nio/channels/vthread/BlockingChannelOps.java timed out
Relates :	JDK-8318422 - Allow poller threads be virtual threads
Relates :	JDK-8282726 - java/net/vthread/BlockingSocketOps.java timeout/hang intermittently on Windows

Sub Tasks

JDK-8318042 :	ProblemList java/nio/channels/vthread/BlockingChannelOps.java#direct-register with GenZGC - Resolved
JDK-8320386 :	Remove java/nio/channels/vthread/BlockingChannelOps.java#direct-register from ProblemList - Resolved

Description

The following test timed out in the JDK22 CI:

java/nio/channels/vthread/BlockingChannelOps.java#direct-register

Here's a snippet from the log file:

#section:junit
----------messages:(8/353)----------
command: junit -Djdk.useDirectRegister BlockingChannelOps
reason: User specified action: run junit/othervm -Djdk.useDirectRegister BlockingChannelOps 
started: Fri Sep 01 09:53:08 UTC 2023
Mode: othervm [/othervm specified]
Timeout information:
--- Timeout information end.
finished: Fri Sep 01 10:03:31 UTC 2023
elapsed time (seconds): 622.704
----------configuration:(0/0)----------
----------System.out:(871/62503)----------
-- VirtualThread[#106]/waiting --
  java.base/java.lang.VirtualThread.parkNanos(VirtualThread.java:621)
  java.base/java.lang.System$2.parkVirtualThread(System.java:2649)
  java.base/jdk.internal.misc.VirtualThreads.park(VirtualThreads.java:67)
  java.base/java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:408)
  java.base/sun.nio.ch.Poller.pollDirect(Poller.java:116)
  java.base/sun.nio.ch.Poller.poll(Poller.java:100)
  java.base/sun.nio.ch.Poller.poll(Poller.java:87)
  java.base/sun.nio.ch.DatagramChannelImpl.park(DatagramChannelImpl.java:494)
  java.base/sun.nio.ch.DatagramChannelImpl.tryBlockingReceive(DatagramChannelImpl.java:762)
  java.base/sun.nio.ch.DatagramChannelImpl.blockingReceive(DatagramChannelImpl.java:692)
  java.base/sun.nio.ch.DatagramSocketAdaptor.receive(DatagramSocketAdaptor.java:204)
  BlockingChannelOps.lambda$testDatagramSocketAdaptorReceive$24(BlockingChannelOps.java:530)
  jdk.test.lib.thread.VThreadRunner.lambda$run$0(VThreadRunner.java:71)
  java.base/java.lang.VirtualThread.run(VirtualThread.java:309)

<snip>

-- VirtualThread[#106]/waiting --
  java.base/java.lang.VirtualThread.parkNanos(VirtualThread.java:621)
  java.base/java.lang.System$2.parkVirtualThread(System.java:2649)
  java.base/jdk.internal.misc.VirtualThreads.park(VirtualThreads.java:67)
  java.base/java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:408)
  java.base/sun.nio.ch.Poller.pollDirect(Poller.java:116)
  java.base/sun.nio.ch.Poller.poll(Poller.java:100)
  java.base/sun.nio.ch.Poller.poll(Poller.java:87)
  java.base/sun.nio.ch.DatagramChannelImpl.park(DatagramChannelImpl.java:494)
  java.base/sun.nio.ch.DatagramChannelImpl.tryBlockingReceive(DatagramChannelImpl.java:762)
  java.base/sun.nio.ch.DatagramChannelImpl.blockingReceive(DatagramChannelImpl.java:692)
  java.base/sun.nio.ch.DatagramSocketAdaptor.receive(DatagramSocketAdaptor.java:204)
  BlockingChannelOps.lambda$testDatagramSocketAdaptorReceive$24(BlockingChannelOps.java:530)
  jdk.test.lib.thread.VThreadRunner.lambda$run$0(VThreadRunner.java:71)
  java.base/java.lang.VirtualThread.run(VirtualThread.java:309)
----------System.err:(69/6414)----------
STARTED    BlockingChannelOps::testPipeReadInterrupt 'testPipeReadInterrupt()'
SUCCESSFUL BlockingChannelOps::testPipeReadInterrupt 'testPipeReadInterrupt()'
STARTED    BlockingChannelOps::testServerSocketChannelAccept1 'testServerSocketChannelAccept1()'
SUCCESSFUL BlockingChannelOps::testServerSocketChannelAccept1 'testServerSocketChannelAccept1()'
STARTED    BlockingChannelOps::testServerSocketChannelAccept2 'testServerSocketChannelAccept2()'
SUCCESSFUL BlockingChannelOps::testServerSocketChannelAccept2 'testServerSocketChannelAccept2()'
STARTED    BlockingChannelOps::testServerSocketChannelAcceptAsyncClose 'testServerSocketChannelAcceptAsyncClose()'
SUCCESSFUL BlockingChannelOps::testServerSocketChannelAcceptAsyncClose 'testServerSocketChannelAcceptAsyncClose()'
STARTED    BlockingChannelOps::testSocketChannelRead 'testSocketChannelRead()'
SUCCESSFUL BlockingChannelOps::testSocketChannelRead 'testSocketChannelRead()'
STARTED    BlockingChannelOps::testSocketChannelReadInterrupt 'testSocketChannelReadInterrupt()'
SUCCESSFUL BlockingChannelOps::testSocketChannelReadInterrupt 'testSocketChannelReadInterrupt()'
STARTED    BlockingChannelOps::testSocketChannelAdaptorAccept1 'testSocketChannelAdaptorAccept1()'
SUCCESSFUL BlockingChannelOps::testSocketChannelAdaptorAccept1 'testSocketChannelAdaptorAccept1()'
STARTED    BlockingChannelOps::testSocketChannelAdaptorAccept2 'testSocketChannelAdaptorAccept2()'
SUCCESSFUL BlockingChannelOps::testSocketChannelAdaptorAccept2 'testSocketChannelAdaptorAccept2()'
STARTED    BlockingChannelOps::testServerSocketChannelAcceptInterrupt 'testServerSocketChannelAcceptInterrupt()'
SUCCESSFUL BlockingChannelOps::testServerSocketChannelAcceptInterrupt 'testServerSocketChannelAcceptInterrupt()'
STARTED    BlockingChannelOps::testPipeWriteAsyncClose 'testPipeWriteAsyncClose()'
SUCCESSFUL BlockingChannelOps::testPipeWriteAsyncClose 'testPipeWriteAsyncClose()'
STARTED    BlockingChannelOps::testPipeReadWrite1 'testPipeReadWrite1()'
SUCCESSFUL BlockingChannelOps::testPipeReadWrite1 'testPipeReadWrite1()'
STARTED    BlockingChannelOps::testPipeReadWrite2 'testPipeReadWrite2()'
SUCCESSFUL BlockingChannelOps::testPipeReadWrite2 'testPipeReadWrite2()'
STARTED    BlockingChannelOps::testPipeReadWrite3 'testPipeReadWrite3()'
SUCCESSFUL BlockingChannelOps::testPipeReadWrite3 'testPipeReadWrite3()'
STARTED    BlockingChannelOps::testSocketChannelWrite 'testSocketChannelWrite()'
SUCCESSFUL BlockingChannelOps::testSocketChannelWrite 'testSocketChannelWrite()'
STARTED    BlockingChannelOps::testDatagramSocketAdaptorReceiveInterrupt1 'testDatagramSocketAdaptorReceiveInterrupt1()'
SUCCESSFUL BlockingChannelOps::testDatagramSocketAdaptorReceiveInterrupt1 'testDatagramSocketAdaptorReceiveInterrupt1()'
STARTED    BlockingChannelOps::testDatagramSocketAdaptorReceiveInterrupt2 'testDatagramSocketAdaptorReceiveInterrupt2()'
SUCCESSFUL BlockingChannelOps::testDatagramSocketAdaptorReceiveInterrupt2 'testDatagramSocketAdaptorReceiveInterrupt2()'
STARTED    BlockingChannelOps::testDatagramSocketAdaptorReceiveAsyncClose1 'testDatagramSocketAdaptorReceiveAsyncClose1()'
SUCCESSFUL BlockingChannelOps::testDatagramSocketAdaptorReceiveAsyncClose1 'testDatagramSocketAdaptorReceiveAsyncClose1()'
STARTED    BlockingChannelOps::testDatagramSocketAdaptorReceiveAsyncClose2 'testDatagramSocketAdaptorReceiveAsyncClose2()'
SUCCESSFUL BlockingChannelOps::testDatagramSocketAdaptorReceiveAsyncClose2 'testDatagramSocketAdaptorReceiveAsyncClose2()'
STARTED    BlockingChannelOps::testSocketChannelReadWrite1 'testSocketChannelReadWrite1()'
SUCCESSFUL BlockingChannelOps::testSocketChannelReadWrite1 'testSocketChannelReadWrite1()'
STARTED    BlockingChannelOps::testSocketChannelWriteAsyncClose 'testSocketChannelWriteAsyncClose()'
SUCCESSFUL BlockingChannelOps::testSocketChannelWriteAsyncClose 'testSocketChannelWriteAsyncClose()'
STARTED    BlockingChannelOps::testSocketAdaptorRead1 'testSocketAdaptorRead1()'
SUCCESSFUL BlockingChannelOps::testSocketAdaptorRead1 'testSocketAdaptorRead1()'
STARTED    BlockingChannelOps::testSocketAdaptorRead2 'testSocketAdaptorRead2()'
SUCCESSFUL BlockingChannelOps::testSocketAdaptorRead2 'testSocketAdaptorRead2()'
STARTED    BlockingChannelOps::testDatagramChannelReceiveAsyncClose 'testDatagramChannelReceiveAsyncClose()'
SUCCESSFUL BlockingChannelOps::testDatagramChannelReceiveAsyncClose 'testDatagramChannelReceiveAsyncClose()'
STARTED    BlockingChannelOps::testDatagramChannelReceiveInterrupt 'testDatagramChannelReceiveInterrupt()'
SUCCESSFUL BlockingChannelOps::testDatagramChannelReceiveInterrupt 'testDatagramChannelReceiveInterrupt()'
STARTED    BlockingChannelOps::testDatagramChannelSendReceive1 'testDatagramChannelSendReceive1()'
SUCCESSFUL BlockingChannelOps::testDatagramChannelSendReceive1 'testDatagramChannelSendReceive1()'
STARTED    BlockingChannelOps::testDatagramChannelSendReceive2 'testDatagramChannelSendReceive2()'
SUCCESSFUL BlockingChannelOps::testDatagramChannelSendReceive2 'testDatagramChannelSendReceive2()'
STARTED    BlockingChannelOps::testPipeWriteInterrupt 'testPipeWriteInterrupt()'
SUCCESSFUL BlockingChannelOps::testPipeWriteInterrupt 'testPipeWriteInterrupt()'
STARTED    BlockingChannelOps::testSocketChannelWriteInterrupt 'testSocketChannelWriteInterrupt()'
SUCCESSFUL BlockingChannelOps::testSocketChannelWriteInterrupt 'testSocketChannelWriteInterrupt()'
STARTED    BlockingChannelOps::testDatagramSocketAdaptorReceive1 'testDatagramSocketAdaptorReceive1()'
SUCCESSFUL BlockingChannelOps::testDatagramSocketAdaptorReceive1 'testDatagramSocketAdaptorReceive1()'
STARTED    BlockingChannelOps::testDatagramSocketAdaptorReceive2 'testDatagramSocketAdaptorReceive2()'
SUCCESSFUL BlockingChannelOps::testDatagramSocketAdaptorReceive2 'testDatagramSocketAdaptorReceive2()'
STARTED    BlockingChannelOps::testPipeReadAsyncClose 'testPipeReadAsyncClose()'
SUCCESSFUL BlockingChannelOps::testPipeReadAsyncClose 'testPipeReadAsyncClose()'
STARTED    BlockingChannelOps::testSocketChannelReadAsyncClose 'testSocketChannelReadAsyncClose()'
SUCCESSFUL BlockingChannelOps::testSocketChannelReadAsyncClose 'testSocketChannelReadAsyncClose()'

[ JUnit Containers: found 4, started 4, succeeded 4, failed 0, aborted 0, skipped 0]
[ JUnit Tests: found 32, started 32, succeeded 32, failed 0, aborted 0, skipped 0]

STATUS:Passed.
----------rerun:(45/6493)*----------

<snip>

result: Error. Program `c:\ade\mesos\work_dir\jib-master\install\jdk-22+14-975\windows-x64-debug.jdk\jdk-22\fastdebug\bin\java' timed out (timeout set to 480000ms, elapsed time including timeout handling was 622687ms).


Default timeout value of 120 seconds/2 minutes with a default timeoutFactor 
of 4 means a total timeout of 480 seconds/8 minutes. The run executed 
for 622.704 seconds. The test did manage to pass while the timeout handler 
was running.

Comments

It is the same issue as JDK-8282726. I was able to reproduce the problem by adding a sleep() as described in https://bugs.openjdk.org/browse/JDK-8282726?focusedId=14627123&page=com.atlassian.jira.plugin.system.issuetabpanels%3Acomment-tabpanel#comment-14627123. With JDK-8318422 merged, the test failures should be much less frequent.
20-11-2023
It's very likely the same issue as JDK-8282726
17-11-2023
We collected 6 failures of the kind: Windows debug build (2019,2022), ZGC (singlegen or generational), no-vmcontinuations or direct-register, the blocking operation waits for (more or less) the full timeout and then succeeds. Most recent failure was before JDK-8318422, so it may indeed be fixed by the reduced timeout. There's a number of test runs after JDK-8318422 that took over 60 seconds to complete; it's not clear if any of these was affected by the same issue - the System.out section is missing from the jtreg log files for tests run in agentvm mode.
15-11-2023
May have been solved by JDK-8318422. The timeout may not be reproducible after this change which fixed the connect timeout duration (60_1000 => 60_000) https://github.com/openjdk/jdk/commit/c099cf53f25496c99629dc578045aa5186e1109d#diff-7ec19cb4394cc6ca6a49535fe96bbc85e746f613b59d509f9f75c056f24f0f63
14-11-2023
Daniel's latest sighting is unusual. It's a debug build, single gen ZGC, and VM continuations disabled . In this run, testDatagramSocketAdaptorReceive2 (the run of testDatagramSocketAdaptorReceive) seems to take 570+ seconds. We know this because there are 57 samples of the stack trace, they are taken every 10 seconds by this test when a virtual thread doesn't terminate in 10 seconds. I suspect the sighting was with a repo that is a bit behind main line because the test was recently corrected to use a timeout of 60_000 instead of 60_1000. With the corrected test then we would expect a lost packet to cause a SocketTimeoutException. Also, the stack traces shows that it is using the "indirect" polling mode that no longer exists in JDK 22. So from an initial look, it is "as if" the system was stalled for 10minutes before it continues and the test passes.
14-11-2023
I closed JDK-8314665 as a duplicate of this bug.
14-11-2023
Looks quite similar to JDK-8314665. I would expect the same root cause - the difference seems to be that ZGC is exciting the failure a bit more here? The log files seem to indicate that all tests passed successfully. There's no logging in the two DatagramChannel tests, and no time information in the logs either, so it's unclear what is happening here and why. Maybe starting to add time information and logging in the two datagram channel tests would help diagnosing this issue further.
14-11-2023
Is this the same issue as JDK-8314665 where a datagram is lost?
13-10-2023