Распаковщик Java 22.0.2 VirtualThread кажется припаркованным навсегда
Когда я использую следующий пул потоков с большой нагрузкой.
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]],
Весь соответствующий виртуальный поток является парковкой:
#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" #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([email protected]/Native Method)
- parking to wait for <0x00001000177791b8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
at java.util.concurrent.locks.LockSupport.parkNanos([email protected]/LockSupport.java:269)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos([email protected]/AbstractQueuedSynchronizer.java:1758)
at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take([email protected]/ScheduledThreadPoolExecutor.java:1182)
at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take([email protected]/ScheduledThreadPoolExecutor.java:899)
at java.util.concurrent.ThreadPoolExecutor.getTask([email protected]/ThreadPoolExecutor.java:1070)
at java.util.concurrent.ThreadPoolExecutor.runWorker([email protected]/ThreadPoolExecutor.java:1130)
at java.util.concurrent.ThreadPoolExecutor$Worker.run([email protected]/ThreadPoolExecutor.java:642)
at java.lang.Thread.runWith([email protected]/Thread.java:1583)
at java.lang.Thread.run([email protected]/Thread.java:1570)
at jdk.internal.misc.InnocuousThread.run([email protected]/InnocuousThread.java:186)
Locked ownable synchronizers:
- None
Я использовал инструмент отладки, чтобы получить очередь unparker. очевидно, что задача в начале очереди должна была быть запущена уже давно (время — 84137649857516, а текущее время — 84707647860354):
[arthas@593599]$ ognl '@[email protected]()'
@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 '@[email protected]()'
@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]]],
Я делаю что-то не так или это ошибка jdk или ОС?
---- обновлять ----
Я обнаружил, что при использовании DatagramChannel для получения пакета время срабатывания scheudleTask может быть отрицательным:
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)
Возможно, вы захотите создать виртуальную цепочку для каждой задачи и подождать (Отказ от ответственности: я написал это письмо).
@ dan1st Я передаю пул потоков в стороннюю библиотеку, поэтому я как бы вынужден это сделать. Просто очень странно, что эти темы висят.
Вы хотя бы измерили улучшение производительности? Если нет, то зачем вообще использовать виртуальные потоки?
@dan1st Да, я получаю прирост производительности примерно на 25%, нам нужно смоделировать тысячи клиентов, каждому из них нужен поток в текущей реализации библиотеки.
@dan1st После решения проблемы и настройки gc прирост производительности достиг 300% (и узкое место даже не в коде, оно ограничено доступным портом Linux).
Ответы 1
Это вызвано длительным переполнением java.util.concurrent.ScheduledThreadPoolExecutor#triggerTime(long, java.util.concurrent.TimeUnit)
Thread.ofVirtual().start(() -> {
try {
DatagramSocket datagramSocket = new DatagramSocket(null);
datagramSocket.bind(new InetSocketAddress("0.0.0.0", 0));
// set a breakpoint at java.lang.VirtualThread#scheduleUnpark before next line and we will find out that trigger time of unpark task is negative which may cause java.util.concurrent.ScheduledThreadPoolExecutor.ScheduledFutureTask#getDelay overflow again to a very large number.
datagramSocket.receive(new DatagramPacket(new byte[4096], 4096));
} catch (IOException e) {
throw new RuntimeException(e);
}
});
Thread.sleep(10000000);
После установки тайм-аута datagramSocket (чтобы при парковке nano не было Long.MAX_VALUE) все проблемы исчезают.
Я подал отчет об ошибке для jdk:
Вызов java.net.DatagramSocket#receive без soTimeout в виртуальном потоке приведет к тому, что разпарковка виртуального потока запланирована примерно через Long.MAX_VALUE, что приведет к отрицательному времени, возвращаемому java.util.concurrent.ScheduledThreadPoolExecutor#triggerTime(long)
Он может стать главой workQueue (зависит от того, переполнится ли она снова при сравнении). Если это произойдет и после головы останутся какие-то задачи, поток unparker может навсегда заблокироваться главной задачей и никогда не запускать некоторые задачи после головы.
Хуже того, когда первая задача отменяется (условие парковки выполнено), поток разпарковки все еще паркуется, потому что java.lang.VirtualThread#cancel передает false в MaybeInterruptIfRunning.
Я бы очень подозрительно отнесся к любой попытке объединить виртуальные потоки по любой причине.