Как положить приложение 21 запросом* к /actuator/health01.08.2024 10:15

yi9cnezkau6e4u88sth5zx35na0.png
Уточнение для въедливых :)

* 21 и более параллельным запросом в определённых условиях :)

Привет, сегодня поговорим о подводных камнях использования виртуальных потоков в написанных на Java веб-приложениях. В статье описан случай из жизни, сперва поставивший в тупик, но оказавшийся не столь уж и запутанным, а причина и вовсе была известна и документирована.


Как всё начиналось

Для тестирования нашего приложения (ничего особенного: Spring Boot 3, OpenFeign, Java 21) применяется Spock Framework, который позволяет писать лаконичные тесты на груви. В какой-то момент тестов стало много и встал вопрос их распараллеливания, что и было сделано добавлением файла SpockConfig.groovy: 

runner {
  parallel {
    enabled true
    dynamic(4)
  }
}

Одновременно с этим мы решили включить виртуальные потоки на стороне сервера (гулять так гулять, у нас же модная Java 21). Всё это замечательно работало и разработка продолжилась как ни в чём не бывало. Однако со временем тесты начали подвисать, при чём это наблюдалось исключительно во время прогонов на локальных машинах (запуск этих же тестов в GitHub Actions проходил без сучка, без задоринки, а почему — я так и не понял).

Отсечением лишнего получилось собрать минималистичное показательное приложение.

Воспроизведение тоже очень простое:


  1. Открыв проект в «Идее» нужно запустить бутовые сервисы DependencyApplication и ConcurrencyDemoApplication.
  2. Убедившись, что оба приложения поднялись, запускаем StuckApplicationTest.
  3. Дожидаемся завершения теста, убеждаемся в работоспособности системы.
  4. Теперь нужно открыть application.yml, лежащий в модуле demo-service и включить виртуальные потоки выставлением spring.threads.virtual.enabled: true (по умолчанию они выключены).
  5. Перезапускаем ConcurrencyDemoApplication и снова гоним StuckApplicationTest.
  6. Убедившись в зависании теста подключаемся к процессу ConcurrencyDemoApplication с помощью YourKit. Почти сразу мы увидим предупреждение о возможном дедлоке.

Ниже станет ясно, что никакого дедлока там нет, но и ложной тревогу не назовёшь.


По верхам

Прежде чем перейти к исследованию предупреждения, слепка состояния потоков и цепочки вызовов посмотрим на испытательный стенд и его окружение.

Под капотом у нас Liberica JDK 21.0.4 (OpenJDK, Coretto или Zulu тоже годятся), Spring Boot 3.3.2, Spring Cloud Starter OpenFeign 4.1.3, Actuator ну и по мелочи ломбок и т.п. Отправной точкой является StuckApplicationTest: 

@Test
void run() {
  var restTemplate = new RestTemplate();
  var latch = new CountDownLatch(1);
  var executor = Executors.newVirtualThreadPerTaskExecutor();
  try (executor) {
    for (int i = 0; i < 100; i++) {
      executor.submit(() -> {
        waitOn(latch);
        var path = "http://localhost:8081/actuator/health";
        assertNotNull(restTemplate.getForEntity(path, ResponseEntity.class));
      });
    }
    latch.countDown();
  }
  assertTrue(executor.isTerminated());
}

private static void waitOn(CountDownLatch latch) {
  try {
    latch.await();
  } catch (InterruptedException e) {
    throw new RuntimeException(e);
  }
}

Это самопальный нагрузочный тест, в котором создаётся исполнитель (он может быть любым, Executors.newCachedThreadPool() тоже сойдёт) и 100 потоков. Потоки останавливаются у шлагбаума, после поднятия которого они все вместе ломятся на /actuator/health.

На стороне сервера у нас два приложения и три класса: 

public class DownstreamServiceHealthIndicator implements HealthIndicator {
  private final HealthClient healthClient;

  @Override
  public Health health() {
    var response = healthClient.checkHealth();
    if (response.getStatusCode().is2xxSuccessful()) {
      return new Health.Builder().up().build();
    }
    return new Health.Builder().down().withDetails(Map.of("response", response)).build();
  }
}

@FeignClient(name = "healthClient", url = "http://localhost:8087/actuator/health", configuration = InternalFeignConfiguration.class)
public interface HealthClient {
  @GetMapping
  ResponseEntity checkHealth();
}

public class InternalFeignConfiguration {
  @Bean
  public Client client() {
    return new ApacheHttpClient(HttpClients.createDefault());
  }
}

Логика такая:


  1. Тест одновременно отправляет множественные запросы на localhost:8081/actuator/health.
  2. Приложение ConcurrencyDemoApplication принимает запросы и перенаправляет их на http://localhost:8087/actuator/health с помощью обычного Фейн-клиента, настроенного на использование HttpClients.createDefault() из библиотеки org.apache.httpcomponents:httpclient:4.5.14 (вспомогательный ApacheHttpClient служит для оборачивания запросов/ответов в объекты классов, с которым работает Фейн).
  3. Приложение DependencyApplication отправляет ответ.

Читатель уже догадался, что собака зарыта в использовании промежуточного клиента. Если мы перепишем код вот так: 

public class DownstreamServiceHealthIndicator implements HealthIndicator {
  private final HealthClient healthClient;

  @Override
  public Health health() {
    return new Health.Builder().up().build();
  }
}

то всё будет замечательно работать. Но так неинтересно :)

С логикой разобрались, посмотрим на предупреждение профайлера. Первое выглядело вот так: 

+-----------------------------------------------------------------------------------------------------------------------------+
|                                                            Name                                                             |
+-----------------------------------------------------------------------------------------------------------------------------+
|  +---Read-Updater Frozen for at least 10s                                                          |
|  | +---jdk.internal.misc.Unsafe.park(boolean, long) Unsafe.java (native)                                                    |
|  | +---java.util.concurrent.locks.LockSupport.park() LockSupport.java:371                                                   |
|  | +---java.util.concurrent.LinkedTransferQueue$DualNode.await(Object, long, Object, boolean) LinkedTransferQueue.java:458  |
|  | +---java.util.concurrent.LinkedTransferQueue.xfer(Object, long) LinkedTransferQueue.java:613                             |
|  | +---java.util.concurrent.LinkedTransferQueue.take() LinkedTransferQueue.java:1257                                        |
|  | +---sun.nio.ch.Poller.updateLoop() Poller.java:286                                                                       |
|  | +---sun.nio.ch.Poller$$Lambda.0x000001ac8947d8d8.run()                                                                   |
|  | +---java.lang.Thread.runWith(Object, Runnable) Thread.java:1596                                                          |
|  | +---java.lang.Thread.run() Thread.java:1583                                                                              |
|  | +---jdk.internal.misc.InnocuousThread.run() InnocuousThread.java:186                                                     |
|  +---Write-Updater Frozen for at least 10s                                                         |
|    +---jdk.internal.misc.Unsafe.park(boolean, long) Unsafe.java (native)                                                    |
|    +---java.util.concurrent.locks.LockSupport.park() LockSupport.java:371                                                   |
|    +---java.util.concurrent.LinkedTransferQueue$DualNode.await(Object, long, Object, boolean) LinkedTransferQueue.java:458  |
|    +---java.util.concurrent.LinkedTransferQueue.xfer(Object, long) LinkedTransferQueue.java:613                             |
|    +---java.util.concurrent.LinkedTransferQueue.take() LinkedTransferQueue.java:1257                                        |
|    +---sun.nio.ch.Poller.updateLoop() Poller.java:286                                                                       |
|    +---sun.nio.ch.Poller$$Lambda.0x000001ac8947d8d8.run()                                                                   |
|    +---java.lang.Thread.runWith(Object, Runnable) Thread.java:1596                                                          |
|    +---java.lang.Thread.run() Thread.java:1583                                                                              |
|    +---jdk.internal.misc.InnocuousThread.run() InnocuousThread.java:186                                                     |
+-----------------------------------------------------------------------------------------------------------------------------+

Ввиду малой содержательности, а также зная о том, что показания могут отличать от прогона к прогону (и вообще профайлеры иногда безбожно врут), тест был запущен ещё несколько раз и в конце-концов удалось получить более информативный вывод, точнее сразу два:
1) Этот приведён полностью ввиду краткости и содержательности: 

+---------------------------------------------------------------------------------------------------------------------------+
|                                                           Name                                                            |
+---------------------------------------------------------------------------------------------------------------------------+
| +---Read-Updater Frozen for at least 10s                                                         |
| | +---jdk.internal.misc.Unsafe.park(boolean, long) Unsafe.java (native)                                                   |
| | +---java.util.concurrent.locks.LockSupport.park() LockSupport.java:371                                                  |
| | +---java.util.concurrent.LinkedTransferQueue$DualNode.await(Object, long, Object, boolean) LinkedTransferQueue.java:458 |
| | +---java.util.concurrent.LinkedTransferQueue.xfer(Object, long) LinkedTransferQueue.java:613                            |
| | +---java.util.concurrent.LinkedTransferQueue.take() LinkedTransferQueue.java:1257                                       |
| | +---sun.nio.ch.Poller.updateLoop() Poller.java:286                                                                      |
| | +---sun.nio.ch.Poller$$Lambda.0x0000024081474670.run()                                                                  |
| | +---java.lang.Thread.runWith(Object, Runnable) Thread.java:1596                                                         |
| | +---java.lang.Thread.run() Thread.java:1583                                                                             |
| | +---jdk.internal.misc.InnocuousThread.run() InnocuousThread.java:186                                                    |
| +---spring.cloud.inetutils Frozen for at least 10s                                               |
| | +---java.net.Inet6AddressImpl.getHostByAddr(byte[]) Inet6AddressImpl.java (native)                                      |
| | +---java.net.InetAddress$PlatformResolver.lookupByAddress(byte[]) InetAddress.java:1225                                 |
| | +---java.net.InetAddress.getHostFromNameService(InetAddress, boolean) InetAddress.java:840                              |
| | +---java.net.InetAddress.getHostName(boolean) InetAddress.java:782                                                      |
| | +---java.net.InetAddress.getHostName() InetAddress.java:754                                                             |
| | +---org.springframework.cloud.commons.util.InetUtils$$Lambda.0x0000024081187240.call()                                  |
| | +---java.util.concurrent.FutureTask.run() FutureTask.java:317                                                           |
| | +---java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor$Worker) ThreadPoolExecutor.java:1144           |
| | +---java.util.concurrent.ThreadPoolExecutor$Worker.run() ThreadPoolExecutor.java:642                                    |
| | +---java.lang.Thread.runWith(Object, Runnable) Thread.java:1596                                                         |
| | +---java.lang.Thread.run() Thread.java:1583                                                                             |
| +---Write-Updater Frozen for at least 10s                                                        |
|   +---jdk.internal.misc.Unsafe.park(boolean, long) Unsafe.java (native)                                                   |
|   +---java.util.concurrent.locks.LockSupport.park() LockSupport.java:371                                                  |
|   +---java.util.concurrent.LinkedTransferQueue$DualNode.await(Object, long, Object, boolean) LinkedTransferQueue.java:458 |
|   +---java.util.concurrent.LinkedTransferQueue.xfer(Object, long) LinkedTransferQueue.java:613                            |
|   +---java.util.concurrent.LinkedTransferQueue.take() LinkedTransferQueue.java:1257                                       |
|   +---sun.nio.ch.Poller.updateLoop() Poller.java:286                                                                      |
|   +---sun.nio.ch.Poller$$Lambda.0x0000024081474670.run()                                                                  |
|   +---java.lang.Thread.runWith(Object, Runnable) Thread.java:1596                                                         |
|   +---java.lang.Thread.run() Thread.java:1583                                                                             |
|   +---jdk.internal.misc.InnocuousThread.run() InnocuousThread.java:186                                                    |
+---------------------------------------------------------------------------------------------------------------------------+

2) Этот я обрезал, ибо много кишков спринга и томката (полностью здесь): 

+-----------------------------------------------------------------------------------------------------------------------------------------------------------+
| +---http-nio-8081-exec-4 Frozen for at least 10s                                                                                 |
|   +---jdk.internal.misc.Unsafe.park(boolean, long) Unsafe.java (native)                                                                                   |
|   +---java.util.concurrent.locks.LockSupport.park() LockSupport.java:371                                                                                  |
|   +---java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionNode.block() AbstractQueuedSynchronizer.java:519                                     |
|   +---java.util.concurrent.ForkJoinPool.unmanagedBlock(ForkJoinPool$ManagedBlocker) ForkJoinPool.java:3780                                                |
|   +---java.util.concurrent.ForkJoinPool.managedBlock(ForkJoinPool$ManagedBlocker) ForkJoinPool.java:3725                                                  |
|   +---java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await() AbstractQueuedSynchronizer.java:1707                                  |
|   +---org.apache.http.pool.AbstractConnPool.getPoolEntryBlocking(Object, Object, long, TimeUnit, Future) AbstractConnPool.java:391                        |
|   +---org.apache.http.pool.AbstractConnPool.access$300(AbstractConnPool, Object, Object, long, TimeUnit, Future) AbstractConnPool.java:70                 |
|   +---org.apache.http.pool.AbstractConnPool$2.get(long, TimeUnit) AbstractConnPool.java:253                                                               |
|   +---org.apache.http.pool.AbstractConnPool$2.get(long, TimeUnit) AbstractConnPool.java:198                                                               |
|   +---org.apache.http.impl.conn.PoolingHttpClientConnectionManager.leaseConnection(Future, long, TimeUnit) PoolingHttpClientConnectionManager.java:306    |
|   +---org.apache.http.impl.conn.PoolingHttpClientConnectionManager$1.get(long, TimeUnit) PoolingHttpClientConnectionManager.java:282                      |
|   +---org.apache.http.impl.execchain.MainClientExec.execute(HttpRoute, HttpRequestWrapper, HttpClientContext, HttpExecutionAware) MainClientExec.java:190 |
|   +---org.apache.http.impl.execchain.ProtocolExec.execute(HttpRoute, HttpRequestWrapper, HttpClientContext, HttpExecutionAware) ProtocolExec.java:186     |
|   +---org.apache.http.impl.execchain.RetryExec.execute(HttpRoute, HttpRequestWrapper, HttpClientContext, HttpExecutionAware) RetryExec.java:89            |
|   +---org.apache.http.impl.execchain.RedirectExec.execute(HttpRoute, HttpRequestWrapper, HttpClientContext, HttpExecutionAware) RedirectExec.java:110     |
|   +---org.apache.http.impl.client.InternalHttpClient.doExecute(HttpHost, HttpRequest, HttpContext) InternalHttpClient.java:185                            |
|   +---org.apache.http.impl.client.CloseableHttpClient.execute(HttpUriRequest, HttpContext) CloseableHttpClient.java:83                                    |
|   +---org.apache.http.impl.client.CloseableHttpClient.execute(HttpUriRequest) CloseableHttpClient.java:108                                                |
|   +---org.apache.http.impl.client.CloseableHttpClient.execute(HttpUriRequest) CloseableHttpClient.java:56                                                 |
|   +---feign.httpclient.ApacheHttpClient.execute(Request, Request$Options) ApacheHttpClient.java:81                                                        |
|   +---feign.SynchronousMethodHandler.executeAndDecode(RequestTemplate, Request$Options) SynchronousMethodHandler.java:100                                 |
|   +---feign.SynchronousMethodHandler.invoke(Object[]) SynchronousMethodHandler.java:70                                                                    |
|   +---feign.ReflectiveFeign$FeignInvocationHandler.invoke(Object, Method, Object[]) ReflectiveFeign.java:99                                               |
|   +---jdk.proxy2.$Proxy70.checkHealth()                                                                                                                   |
|   +---org.example.concurrencydemo.health.DownstreamServiceHealthIndicator.health() DownstreamServiceHealthIndicator.java:20                               |
|   +---org.springframework.boot.actuate.health.HealthIndicator.getHealth(boolean) HealthIndicator.java:37                                                  |
+-----------------------------------------------------------------------------------------------------------------------------------------------------------+

В первом вроде бы находим указание на проблемный участок в пользовательском коде (не в кишках ВМ): 

spring.cloud.inetutils Frozen for at least 10s
java.net.InetAddress.getHostName(boolean) InetAddress.java:782
java.net.InetAddress.getHostName() InetAddress.java:754
org.springframework.cloud.commons.util.InetUtils$$Lambda.0x0000024081187240.call()

И вроде бы там действительно накосячили: 

// class org.springframework.cloud.commons.util.InetUtils

public InetUtils(final InetUtilsProperties properties) {
  this.properties = properties;
  this.executorService = Executors.newSingleThreadExecutor(r -> { // <---
    Thread thread = new Thread(r);
    thread.setName(InetUtilsProperties.PREFIX);
    thread.setDaemon(true);
    return thread;
  });
}

public HostInfo convertAddress(final InetAddress address) {
  Future result = this.executorService.submit(address::getHostName); // <---

  String = result.get(this.properties.getTimeoutSeconds(), TimeUnit.SECONDS);
}

Бутылочным горлышком здесь является использование Executors.newSingleThreadExecutor(), из имени которого следует невозможность исполнения более одной задачи одновременно. Иными словами, даже параллельные запросы в этом месте вынуждены стоять в очереди.

Наблюдениями я поделился на СО и не получив ответа продолжил поиск.

Забегая вперёд сразу скажу, что причина отнюдь не в InetUtils.


Глубже

Погнали копать второй фрагмент. Он интереснее: 

+---http-nio-8081-exec-4 Frozen for at least 10s                                                                
  +---jdk.internal.misc.Unsafe.park(boolean, long) Unsafe.java (native)                                                                  
  +---java.util.concurrent.locks.LockSupport.park() LockSupport.java:371                                                                 
  +---java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionNode.block() AbstractQueuedSynchronizer.java:519                    
  +---java.util.concurrent.ForkJoinPool.unmanagedBlock(ForkJoinPool$ManagedBlocker) ForkJoinPool.java:3780                               
  +---java.util.concurrent.ForkJoinPool.managedBlock(ForkJoinPool$ManagedBlocker) ForkJoinPool.java:3725                                 
  +---java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await() AbstractQueuedSynchronizer.java:1707                 
  +---org.apache.http.pool.AbstractConnPool.getPoolEntryBlocking(Object, Object, long, TimeUnit, Future) AbstractConnPool.java:391       
  +---org.apache.http.pool.AbstractConnPool.access$300(AbstractConnPool, Object, Object, long, TimeUnit, Future) AbstractConnPool.java:70
  +---org.apache.http.pool.AbstractConnPool$2.get(long, TimeUnit) AbstractConnPool.java:253                                              
  +---org.apache.http.pool.AbstractConnPool$2.get(long, TimeUnit) AbstractConnPool.java:198

Обращает на себя внимание метод AbstractConnPool.getPoolEntryBlocking(), уже своим названием говорящий о блокировке, что в общем-то естественно для пула соединений.

Теперь определим место и причину зависания. Сначала снимем состояние потоков уже зависшего приложения. Там увидим 20 потоков-исполнителей в ForkJoinPool-е с одинаковыми (за исключением id) стек-трейсами: 

"ForkJoinPool-1-worker-1" prio=0 tid=0x0 nid=0x0 waiting on condition
     java.lang.Thread.State: WAITING
 on java.lang.VirtualThread at 121c8328 owned by "tomcat-handler-123" Id=214
    at java.base at 22.0.2/jdk.internal.vm.Continuation.run(Continuation.java:248)
    at java.base at 22.0.2/java.lang.VirtualThread.runContinuation(VirtualThread.java:245)
    at java.base at 22.0.2/java.lang.VirtualThread$$Lambda/0x000001579b475d08.run(Unknown Source)
    at java.base at 22.0.2/java.util.concurrent.ForkJoinTask$RunnableExecuteAction.compute(ForkJoinTask.java:1726)
    at java.base at 22.0.2/java.util.concurrent.ForkJoinTask$RunnableExecuteAction.compute(ForkJoinTask.java:1717)
    at java.base at 22.0.2/java.util.concurrent.ForkJoinTask$InterruptibleTask.exec(ForkJoinTask.java:1641)
    at java.base at 22.0.2/java.util.concurrent.ForkJoinTask.doExec(ForkJoinTask.java:507)
    at java.base at 22.0.2/java.util.concurrent.ForkJoinPool$WorkQueue.topLevelExec(ForkJoinPool.java:1489)
    at java.base at 22.0.2/java.util.concurrent.ForkJoinPool.scan(ForkJoinPool.java:2071)
    at java.base at 22.0.2/java.util.concurrent.ForkJoinPool.runWorker(ForkJoinPool.java:2033)
    at java.base at 22.0.2/java.util.concurrent.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:187)

Обратите внимание на состояние WAITING. Получается, что виртуальные потоки (ВП) формально не заблокированы (BLOCKED), а ожидают некоего сигнала, т. е. несмотря на наглухо зависшее приложение мы имеем дело не со взаимной блокировкой в её классическом виде. И раз зависание воспроизводится только с виртуальными потоками, то речь идёт о каком-то явлении, специфичном именно для них.


Пятиминутка истории

С внедрением виртуальных потоков в Java 21 возникло два «слоя» планирования задач:


  • JVM управляет платформенными потоками, 1:1 соотносящимися с «железными» потоками ОС
  • также JVM управляет виртуальными потоками

Когда ВМ запускает виртуальный поток, ему назначается т. н. поток-носитель (carrier thread), представляющий собой обыкновенный платформенный поток. При завершении или приостановке работы ВП он снимается с потока-носителя, освобождающегося для иных задач.

В связи с этим нововведением возникло явление связанного потока (pinned thread), иными словами ВП, который не может быть снят с потока-носителя в одном из двух случаев:


  • ВП исполняет код внутри блока синхронизации
  • ВП вызвал нативный метод или внешнюю функцию

Важное замечание: само по себе связывание потока не является свидетельством сломанного приложения, или каких-то проблем.


Нам-то что с того?

JDK 21 и старше предлагает инструмент для обнаружения связанных потоков: достаточно запустить JVM с флагом -Djdk.tracePinnedThreads=full и при возникновении связывания мы получим цепочку вызовов проблемного кода. Т. к. в исходном стек-трейсе 160 строк, то остановимся на интересном (здесь целиком): 

VirtualThread[#149,tomcat-handler-35]/runnable@ForkJoinPool-1-worker-20 reason:MONITOR
    java.base/java.lang.VirtualThread$VThreadContinuation.onPinned(VirtualThread.java:199)
    java.base/jdk.internal.vm.Continuation.onPinned0(Continuation.java:393)
    java.base/java.lang.VirtualThread.park(VirtualThread.java:596)
    java.base/java.lang.System$2.parkVirtualThread(System.java:2648)
    java.base/jdk.internal.misc.VirtualThreads.park(VirtualThreads.java:54)
    java.base/java.util.concurrent.locks.LockSupport.park(LockSupport.java:219)
    java.base/java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:754)
    java.base/java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:990)
    java.base/java.util.concurrent.locks.ReentrantLock$Sync.lock(ReentrantLock.java:153)
    java.base/java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:322)
    org.apache.http.pool.AbstractConnPool.getPoolEntryBlocking(AbstractConnPool.java:319)
    org.apache.http.pool.AbstractConnPool.access$300(AbstractConnPool.java:70)
    org.apache.http.pool.AbstractConnPool$2.get(AbstractConnPool.java:253) <== monitors:1

Похоже, причиной связывания потока является монитор в строке 253 класса AbstractConnPool, оттуда мы проваливаемся вглубь и дойдя до строчки 319 зависаем (далее идут кишки).

В том же файле pinned-threads.txt находим цепочку вызовов другого связанного потока: 

VirtualThread[#156,tomcat-handler-42]/runnable@ForkJoinPool-1-worker-8 reason:MONITOR
    java.base/java.lang.VirtualThread$VThreadContinuation.onPinned(VirtualThread.java:199)
    java.base/jdk.internal.vm.Continuation.onPinned0(Continuation.java:393)
    java.base/java.lang.VirtualThread.park(VirtualThread.java:596)
    java.base/java.lang.System$2.parkVirtualThread(System.java:2648)
    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:4011)
    java.base/java.util.concurrent.ForkJoinPool.managedBlock(ForkJoinPool.java:3959)
    java.base/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:1707)
    org.apache.http.pool.AbstractConnPool.getPoolEntryBlocking(AbstractConnPool.java:391)
    org.apache.http.pool.AbstractConnPool.access$300(AbstractConnPool.java:70)
    org.apache.http.pool.AbstractConnPool$2.get(AbstractConnPool.java:253) <== monitors:1

Здесь точка входа вновь в строке 253 класса AbstractConnPool, однако теперь мы упираемся в строку 391 (далее опять кишки).

Была смутная догадка, что по крайней мере частично это проблема JVM, но внятных мыслей у меня не было, поэтому я написал в рассылку loom-dev.

Алан Бейтман ответил быстро и помог расставить точки на «ё»:


Further up in the stack is AbstractConnPool.get with the synchronized block that is causing the issue here. A limitation right now is that a virtual thread cannot unmount when inside a synchronized statement or method. In this case it seems that all carriers are pinned by virtual threads that are all blocked in the same place. The other short term fix is to this to migrate this code to also use a j.u.concurrent lock.

There is work under way to remove this limitation. There are EA builds available that we looking for help testing before the changes are proposed for the main line and a future JDK release.

Теперь сложим воедино части головоломки: 

// AbstractConnPool

private final Lock lock;
private final Condition condition;

public AbstractConnPool() {
  this.lock = new ReentrantLock();
  this.condition = this.lock.newCondition();
}

@Override
public Future lease() {
  return new Future() {
    @Override
    public E get() {
      for (;;) {
        synchronized (this) {
          final E leasedEntry = getPoolEntryBlocking();
          return leasedEntry;
        }
      }
    }
  };
}

В работающем приложении каждый клиентский запрос обрабатывается в своём виртуальном потоке. Поток приходит в пул и получает соединение в виде Future, у которого метод get() содержит synchronized. Документация прямо предупреждает о невозможности отвязки ВП от носителя внутри блоков синхронизации. Получается, что как только все свободные соединения оказываются разобранными, каждый следующий поток, вызывающий AbstractConnPool.lease(), входит в блок синхронизации и внутри застревает в getPoolEntryBlocking(): 

private E getPoolEntryBlocking() {
  this.lock.lock(); // line 319
  try {
    for (;;) {
      E entry = pool.getFree(state);
      if (deadline != null) {
        success = this.condition.awaitUntil(deadline);
      } else {
        this.condition.await(); // line 391
        success = true;
      }
    }
  } finally {
    this.lock.unlock();
  }
}

@Override
public void release(final E entry, final boolean reusable) {
  this.lock.lock();
  try {
    if (this.leased.remove(entry)) {
      this.condition.signalAll();
    }
  } finally {
      this.lock.unlock();
  }
}

Поскольку мы имеем дело с Future, то для его завершения ВП нуждается в свободном носителе. Для получения носителя удерживающему его другому ВП нужно завершить свою работу и вызвать this.condition.signalAll() в методе release() или приостановиться. Но даже сделав это отпустить носитель невозможно, ибо мы всё ещё внутри synchronized.

Получается замкнутый круг: виртуальный поток А не может отвязаться от своего носителя, а виртуальный поток Б, даже уже стоящий в очереди на исполнение, не может продолжить свою работу, т. к. свободные носители разобраны.

Внимательный читатель сейчас чешет затылок и думает: постойте, но ведь войти в блок синхронизации в один момент времени может только один поток. У нас же получается так, что все потоки каким-то образом прошли через synchronized и упёрлись в один и тот же ReentrantLock. Неразбериха объясняется тем, что метод AbstractConnPool.lease() возвращает не само соединение, а Future, к которому и привязан монитор (synchronized (this)).

Соответственно, два разных потока, оперируя каждый своим объектом Future захватывают свои собственный мониторы, и приходят к ReentrantLock-у (он один на весь пул).

Таким образом, проблема имеет две грани:


  • количество соединений в пуле недостаточно для удовлетворения всех потоков потоков-носителей в ForkJoinPool-е не хватает для удовлетворения всех ВП, количество которых по меньшей мере равно количеству одновременных клиентских запросов
  • наличие двухуровневого планировщика ломает исполнение, которое прекрасно работает с одним уровнем (когда в работе только платформенные потоки)

Проверить предположение можно двумя способами:

В обоих случаях зависание чудесным образом пропадает. Также поможет использование клиента по умолчанию (читай удаление InternalFeignConfiguration).

Обратите внимание, что увеличение количества соединений в пуле не помогает. Даже если мы перепишем InternalFeignConfiguration вот так: 

public class InternalFeignConfiguration {
  @Bean
  public Client client() {
    return new ApacheHttpClient(HttpClients.custom().setMaxConnTotal(100).build());
  }
}

зависание останется, ведь потоков-носителей по прежнему 20. Поэтому в названии и указано число 21: лишняя соломинка ломает хребет верблюду один лишний запрос кладёт сервер на лопатки.

Итого:


  • некоторым веб-приложениям от виртуальных потоков сильно поплохеет
  • при использовании ВП работоспособность вашего приложения неочевидным образом зависит от кода используемых библиотек, а потенциальная проблема при низкой нагрузке вообще «спит»
  • ранние сборки JDK 24 помогут вам в том случае, когда переезд на обновлённую/другую библиотеку невозможен или затруднён, а починить нужно здесь и сейчас
  • если переезд на ЕА-сборку невозможен, то поможет размножение потоков-носителей с помощью -Djdk.virtualThreadScheduler.parallelism=x
  • если всё перечисленное выше не помогает/невозможно, то качайте исходный код злосчастной библиотеки, меняйте synchronized на ReentrantLock, собирайте и подкладывайте в dependencyManagement
  • «Идея» пока не умеет показывать виртуальные потоки и предупреждать об их связывании, YourKit не очень точен, так что пользуйтесь консольным инструментарием


Заключение

17 сентября выйдет Java 23, а значит ближе к концу марта 2025 года у нас появится стабильная Java 24, в которой вопрос с высокой долей вероятности будет окончательно решен. Ну, а пока просто не мешайте водку с портвейном synchronized и ReentrantLock;)

© Habrahabr.ru