Java 22.0.2虚拟线程高负载下调用DatagramSocket.receive永久挂起

线程池配置 #

使用如下代码创建虚拟线程池：

private final ScheduledExecutorService serverExecutor2 = Executors.newScheduledThreadPool(2000, Thread.ofVirtual().name("COAP-SERVER2-", 0).factory());

卡顿现象 #

高负载状态下线程池出现卡顿，状态信息显示：

serverExecutor2=@ScheduledThreadPoolExecutor[java.util.concurrent.ScheduledThreadPoolExecutor@327e5be5[Running, pool size = 2000, active threads = 0, queued tasks = 60000, completed tasks = 97847]]

虚拟线程状态 #

所有虚拟线程均处于parking状态，栈信息如下：

#75 "COAP-SERVER2-5" virtual
      java.base/java.lang.VirtualThread.park(VirtualThread.java:592)
      java.base/java.lang.System$2.parkVirtualThread(System.java:2639)
      java.base/jdk.internal.misc.VirtualThreads.park(VirtualThreads.java:54)
      java.base/java.util.concurrent.locks.LockSupport.park(LockSupport.java:369)
      java.base/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionNode.block(AbstractQueuedSynchronizer.java:519)
      java.base/java.util.concurrent.ForkJoinPool.unmanagedBlock(ForkJoinPool.java:3780)
      java.base/java.util.concurrent.ForkJoinPool.managedBlock(ForkJoinPool.java:3725)
      java.base/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:1707)
      java.base/java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1177)
      java.base/java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:899)
      java.base/java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1070)
      java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130)
      java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642)
      java.base/java.lang.VirtualThread.run(VirtualThread.java:311)

VirtualThread-unparker阻塞问题 #

问题根源指向VirtualThread-unparker线程阻塞，其队列堆积大量等待任务，线程栈信息：

"VirtualThread-unparker" #92 [593799] daemon prio=5 os_prio=0 cpu=2238.28ms elapsed=373.27s tid=0x00007f1b3002fd50 nid=593799 waiting on condition  [0x00007f1e6db43000]
   java.lang.Thread.State: TIMED_WAITING (parking)
        at jdk.internal.misc.Unsafe.park(java.base@22.0.2/Native Method)
        - parking to wait for  <0x00001000177791b8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
        at java.util.concurrent.locks.LockSupport.parkNanos(java.base@22.0.2/LockSupport.java:269)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(java.base@22.0.2/AbstractQueuedSynchronizer.java:1758)
        at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(java.base@22.0.2/ScheduledThreadPoolExecutor.java:1182)
        at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(java.base@22.0.2/ScheduledThreadPoolExecutor.java:899)
        at java.util.concurrent.ThreadPoolExecutor.getTask(java.base@22.0.2/ThreadPoolExecutor.java:1070)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@22.0.2/ThreadPoolExecutor.java:1130)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@22.0.2/ThreadPoolExecutor.java:642)
        at java.lang.Thread.runWith(java.base@22.0.2/Thread.java:1583)
        at java.lang.Thread.run(java.base@22.0.2/Thread.java:1570)
        at jdk.internal.misc.InnocuousThread.run(java.base@22.0.2/InnocuousThread.java:186)

   Locked ownable synchronizers:
        - None

调试发现任务时间异常 #

通过Arthas调试发现，unparker队列头部的任务本应早已执行，但未被处理：

[arthas@593599]$ ognl '@java.lang.VirtualThread@UNPARKER.toString()'
@String[java.util.concurrent.ScheduledThreadPoolExecutor@154b1210[Running, pool size = 1, active threads = 0, queued tasks = 30027, completed tasks = 413674]]
[arthas@593599]$ ognl '@System@nanoTime()'
@Long[84707647860354]
[arthas@593599]$ ognl '@java.lang.VirtualThread@UNPARKER.queue.peek()'
@ScheduledFutureTask[
    sequenceNumber=@Long[1227676],
    time=**@Long[84137649857516]**,
    period=@Long[0],
    outerTask=@ScheduledFutureTask[java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask@5d021eb6[Not completed, task = java.util.concurrent.Executors$RunnableAdapter@7d5f12fb[Wrapped task = java.lang.VirtualThread$$Lambda/0x00007f1bf357cc70@56d5ca23]]],
    heapIndex=@Integer[0],
    this$0=@ScheduledThreadPoolExecutor[java.util.concurrent.ScheduledThreadPoolExecutor@154b1210[Running, pool size = 1, active threads = 0, queued tasks = 30027, completed tasks = 413674]],
    state=@Integer[0],
    NEW=@Integer[0],
    COMPLETING=@Integer[1],
    NORMAL=@Integer[2],
    EXCEPTIONAL=@Integer[3],
    CANCELLED=@Integer[4],
    INTERRUPTING=@Integer[5],
    INTERRUPTED=@Integer[6],
    callable=@RunnableAdapter[java.util.concurrent.Executors$RunnableAdapter@7d5f12fb[Wrapped task = java.lang.VirtualThread$$Lambda/0x00007f1bf357cc70@56d5ca23]],
    outcome=null,
    runner=null,
    waiters=null,
    STATE=@FieldInstanceReadWrite[VarHandle[varType=int, coord=[class java.util.concurrent.FutureTask]]],
    RUNNER=@FieldInstanceReadWrite[VarHandle[varType=java.lang.Thread, coord=[class java.util.concurrent.FutureTask]]],
    WAITERS=@FieldInstanceReadWrite[VarHandle[varType=java.util.concurrent.FutureTask$WaitNode, coord=[class java.util.concurrent.FutureTask]]],

当前系统时间为84707647860354，但队列头部任务的time值为84137649857516，远早于当前时间却未被执行。

疑问 #

是使用方式有误，还是JDK或操作系统存在Bug？

更新：发现DatagramChannel触发的时间溢出问题 #

进一步排查发现，当调用DatagramSocket.receive()时会触发时间计算溢出：

ts=2024-08-06 14:32:36;thread_name=ForkJoinPool-1-worker-1;id=97;is_daemon=true;priority=5;TCCL=jdk.internal.loader.ClassLoaders$AppClassLoader@5c647e05
    @java.util.concurrent.ScheduledThreadPoolExecutor.triggerTime() -- get a number close to Long.MAX_VALUE as param and output nagative number.
        at java.util.concurrent.ScheduledThreadPoolExecutor.schedule(ScheduledThreadPoolExecutor.java:560)
        at java.lang.VirtualThread.scheduleUnpark(VirtualThread.java:705)
        at java.lang.VirtualThread.parkNanos(VirtualThread.java:632)
        at java.lang.System$2.parkVirtualThread(System.java:2652)
        at jdk.internal.misc.VirtualThreads.park(VirtualThreads.java:67)
        at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:408)
        at sun.nio.ch.Poller.pollIndirect(Poller.java:137)
        at sun.nio.ch.Poller.poll(Poller.java:102)
        at sun.nio.ch.Poller.poll(Poller.java:87)
        at sun.nio.ch.DatagramChannelImpl.park(DatagramChannelImpl.java:494)
        at sun.nio.ch.DatagramChannelImpl.tryBlockingReceive(DatagramChannelImpl.java:762)
        at sun.nio.ch.DatagramChannelImpl.blockingReceive(DatagramChannelImpl.java:692)   ---- if nanos is zero, nanos = Long.MAX_VALUE, which caused overflow at ScheduledThreadPoolExecutor.schedule 
        at sun.nio.ch.DatagramSocketAdaptor.receive(DatagramSocketAdaptor.java:204)
        at java.net.DatagramSocket.receive(DatagramSocket.java:714)

当接收超时时间为0时，底层会将nanos设置为Long.MAX_VALUE，导致ScheduledThreadPoolExecutor.schedule()计算triggerTime时发生数值溢出，得到负数，进而导致unparker队列中的任务无法被正确调度。

内容的提问来源于stack exchange，提问作者Nick Allen