Как показывает опыт Netflix, использование виртуальных потоков, представленных в Java 21, может спровоцировать возникновение неожиданных проблем. В новом переводе от команды Spring АйО мы подробно исследуем уникальные трудности, возникшие у команды Netflix при интеграции виртуальных потоков в Spring Boot на Tomcat. 

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

Введение

У Netflix имеется богатая история использования Java в качестве основного языка программирования, используемого для создания огромного количества микросервисов. Когда мы переходим на новую версию Java, наша команда JVM Ecosystem выискивает новые возможности языка, которые смогут улучшить эргономику и производительность наших систем. В недавно опубликованной статье мы детально описали, как наша рабочая нагрузка получает преимущества от перехода на ZGC нового поколения  в качестве сборщика мусора по умолчанию при миграции на Java 21.  Виртуальные потоки — это еще одна функция, которую мы с энтузиазмом планируем внедрить в рамках этой миграции.

Для тех из вас, кому виртуальные потоки в новинку, они описываются как “легковесные потоки, которые радикально снижают количество усилий, требуемых для написания, поддержки и наблюдения за высокопроизводительными многопоточными приложениями”. Их сила в их способности приостанавливаться и восстанавливаться автоматически, когда происходят операции блокирования, таким образом освобождая внутренние потоки операционной системы для повторного использования другими операциями. Использование виртуальных потоков может достичь высокую производительность, когда они применяются в правильном контексте. 

В этой статье мы обсуждаем один из необычных случаев, с которыми мы столкнулись на пути к внедрению виртуальных потоков в Java 21.

Проблема

Инженеры Netflix отправили несколько независимых отчетов о периодических таймаутах и случаях подвисания в команды Performance Engineering и JVM Ecosystem. После внимательного рассмотрения мы заметили набор общих признаков и симптомов. Во всех случаях затронутые приложения работали на Java 21 со SpringBoot 3 и встроенным Tomcat, принимающим трафик на REST эндпоинты. Инстансы, где была зафиксирована эта проблема, просто переставали принимать трафик, несмотря на то, что JVM на них оставалась в рабочем состоянии. Один явный симптом, характеризующий эту проблему — это устойчивый рост числа сокетов в состоянии closeWait, как показано на графике ниже:

Собранная диагностика

Сокеты, остающиеся в состоянии closeWait, указывают нам на то, что удаленный сетевой узел закрыл сокет, но он не был закрыт на локальном узле, предположительно из-за того, что этого не сделало само приложение.

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

Чтобы устранить эту проблему, мы сначала воспользовались нашей системой оповещений, чтобы зафиксировать случай, когда это состояние возникло. Поскольку мы периодически собираем и сохраняем дампы потоков для всех рабочих нагрузок JVM, мы часто можем ретроспективно восстановить поведение, изучая эти дампы потоков из конкретного экземпляра. Однако нас удивило, что все наши дампы потоков показывают идеально простаивающую JVM без какой-либо явной активности. Изучив последние изменения, мы обнаружили, что в затронутых сервисах были включены виртуальные потоки, и мы знали, что стеки вызовов виртуальных потоков не отображаются в дампах потоков, созданных с помощью команды jstack. Чтобы получить более полный дамп потоков, содержащий состояние виртуальных потоков, мы использовали команду «jcmd Thread.dump_to_file». В качестве последней попытки для изучения состояния JVM мы также собрали дамп кучи из экземпляра.

Анализ

Thread dumps показали тысячи “пустых” виртуальных потоков:

#119821 "" virtual

#119820 "" virtual

#119823 "" virtual

#120847 "" virtual

#119822 "" virtual
...

Это виртуальные потоки, для которых был создан объект потока, но которые еще не начали выполнение и, следовательно, не имеют stack trace`а. На самом деле, количество таких пустых виртуальных потоков примерно совпадало с количеством сокетов в состоянии closeWait. Чтобы понять, что именно мы наблюдаем, для начала нам следует разобраться, как работают виртуальные потоки.

Виртуальный поток не сопоставляется один к одному с выделенным потоком на уровне операционной системы. Скорее, его можно рассматривать как задачу, которая планируется для выполнения в пуле потоков fork-join. Когда виртуальный поток попадает в блокирующий вызов, например, ожидая завершения Future, он освобождает поток операционной системы, который он занимал, и просто остается в памяти до тех пор, пока не будет готов возобновить выполнение. Тем временем поток операционной системы может быть переназначен для выполнения других виртуальных потоков в том же пуле fork-join. Это позволяет нам мультиплексировать множество виртуальных потоков на небольшое количество основных потоков операционной системы. В терминологии JVM основной поток операционной системы называется «carrier thread» (несущий поток), к которому виртуальный поток может быть «смонтирован» во время выполнения и «демонтирован» во время ожидания. Отличное подробное описание виртуальных потоков доступно в JEP 444.

В нашей среде мы используем блокирующую модель для Tomcat, которая фактически удерживает рабочий поток на протяжении всего времени выполнения запроса. При включении виртуальных потоков Tomcat переключается на виртуальное выполнение. Каждый входящий запрос создает новый виртуальный поток, который просто планируется как задача на Virtual Thread Executor. Мы можем увидеть, как Tomcat создает VirtualThreadExecutor здесь.

Связывая эту информацию с нашей проблемой, симптомы соответствуют состоянию, когда Tomcat продолжает создавать новый виртуальный поток для работы в сети для каждого входящего запроса, но доступных потоков уровня ОС, к которым их можно было бы примонтировать, не существует.

Почему завис Tomcat?

Что случилось с нашими потоками уровня ОС и чем они были заняты? Как описано здесь, виртуальный поток будет прикреплен к несущему ОС потоку, если он выполняет блокирующую операцию, пока находится внутри synchronized блока или метода. Именно это здесь и происходит. Ниже приведен соответствующий фрагмент thread dump, полученный с зависшего инстанса. 

#119515 "" virtual
      java.base/jdk.internal.misc.Unsafe.park(Native Method)
      java.base/java.lang.VirtualThread.parkOnCarrierThread(VirtualThread.java:661)
      java.base/java.lang.VirtualThread.park(VirtualThread.java:593)
      java.base/java.lang.System$2.parkVirtualThread(System.java:2643)
      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)
      zipkin2.reporter.internal.CountBoundedQueue.offer(CountBoundedQueue.java:54)
      zipkin2.reporter.internal.AsyncReporter$BoundedAsyncReporter.report(AsyncReporter.java:230)
      zipkin2.reporter.brave.AsyncZipkinSpanHandler.end(AsyncZipkinSpanHandler.java:214)
      brave.internal.handler.NoopAwareSpanHandler$CompositeSpanHandler.end(NoopAwareSpanHandler.java:98)
      brave.internal.handler.NoopAwareSpanHandler.end(NoopAwareSpanHandler.java:48)
      brave.internal.recorder.PendingSpans.finish(PendingSpans.java:116)
      brave.RealSpan.finish(RealSpan.java:134)
      brave.RealSpan.finish(RealSpan.java:129)
      io.micrometer.tracing.brave.bridge.BraveSpan.end(BraveSpan.java:117)
      io.micrometer.tracing.annotation.AbstractMethodInvocationProcessor.after(AbstractMethodInvocationProcessor.java:67)
      io.micrometer.tracing.annotation.ImperativeMethodInvocationProcessor.proceedUnderSynchronousSpan(ImperativeMethodInvocationProcessor.java:98)
      io.micrometer.tracing.annotation.ImperativeMethodInvocationProcessor.process(ImperativeMethodInvocationProcessor.java:73)
      io.micrometer.tracing.annotation.SpanAspect.newSpanMethod(SpanAspect.java:59)
      java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:103)
      java.base/java.lang.reflect.Method.invoke(Method.java:580)
      org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethodWithGivenArgs(AbstractAspectJAdvice.java:637)
...

В этом stack trace мы видим, что происходит синхронизация в brave.RealSpan.finish(RealSpan.java:134). Этот виртуальный поток эффективно закреплен — он привязан к реальному потоку уровня ОС, даже если он ждет получения reentrant lock (команда Spring АйО: об этом мы обязательно отдельно расскажем чуть позже). Есть 3 виртуальных потока в точно таком состоянии и еще один виртуальный поток, идентифицированный как “<redacted> @DefaultExecutor - 46542”, который следует тому же самому пути внутри кода. Эти 4 виртуальных потока закреплены в ожидании захвата lock. Поскольку приложение развернуто на экземпляре с 4 vCPU, пул fork-join, обеспечивающий выполнение виртуальных потоков, также содержит 4 потока ОС. Теперь, когда мы их исчерпали, ни один другой виртуальный поток не может прогрессировать дальше. Это объясняет, почему Tomcat перестал обрабатывать запросы и почему количество сокетов в состоянии closeWait постоянно растет. Действительно, Tomcat принимает соединение на сокете, создает запрос вместе с виртуальным потоком и передает этот запрос/поток в executor для обработки. Однако вновь созданный виртуальный поток не может быть зашедулен, потому что все потоки операционной системы в пуле fork-join зафиксированы и никогда не освобождаются. Таким образом, эти вновь созданные виртуальные потоки застревают в очереди, при этом продолжая удерживать сокет.

У кого находится lock?

Теперь, когда мы знаем, что виртуальные потоки ждут получения lock, следующим вопросом будет: кто удерживает lock? Ответ на этот вопрос является ключом к пониманию того, что изначально вызвало такое положение вещей. Обычно thread dump показывает, кто удерживает lock при помощи команды “- locked <0x…> (at …)” или “Locked ownable synchronizers,” но ни одна из этих команд не дает результата на наших thread dumps. Фактически, никакая информация о блокировке/парковке/ожидании не включена в дампы потоков, созданные с помощью команды jcmd. Это ограничение в Java 21, и оно будет устранено в будущих выпусках. Тщательный анализ дампа потоков показывает, что всего шесть потоков конкурируют за один и тот же ReentrantLock и связанный с ним Condition. Четыре из этих шести потоков описаны в предыдущем разделе. Ниже приведено содержимое еще одного потока:

#119516 "" virtual
      java.base/java.lang.VirtualThread.park(VirtualThread.java:582)
      java.base/java.lang.System$2.parkVirtualThread(System.java:2643)
      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)
      zipkin2.reporter.internal.CountBoundedQueue.offer(CountBoundedQueue.java:54)
      zipkin2.reporter.internal.AsyncReporter$BoundedAsyncReporter.report(AsyncReporter.java:230)
      zipkin2.reporter.brave.AsyncZipkinSpanHandler.end(AsyncZipkinSpanHandler.java:214)
      brave.internal.handler.NoopAwareSpanHandler$CompositeSpanHandler.end(NoopAwareSpanHandler.java:98)
      brave.internal.handler.NoopAwareSpanHandler.end(NoopAwareSpanHandler.java:48)
      brave.internal.recorder.PendingSpans.finish(PendingSpans.java:116)
      brave.RealScopedSpan.finish(RealScopedSpan.java:64)
      ...

Заметьте, что в то время как этот поток вроде бы проходит через тот же путь в коде, чтобы завершить прогон, он не проходит через synchronized блок. И, наконец, далее приведем содержимое шестого потока:

#107 "AsyncReporter <redacted>"
      java.base/jdk.internal.misc.Unsafe.park(Native Method)
      java.base/java.util.concurrent.locks.LockSupport.park(LockSupport.java:221)
      java.base/java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:754)
      java.base/java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:1761)
      zipkin2.reporter.internal.CountBoundedQueue.drainTo(CountBoundedQueue.java:81)
      zipkin2.reporter.internal.AsyncReporter$BoundedAsyncReporter.flush(AsyncReporter.java:241)
      zipkin2.reporter.internal.AsyncReporter$Flusher.run(AsyncReporter.java:352)
      java.base/java.lang.Thread.run(Thread.java:1583)

Это на самом деле обычный связанный с платформой поток, а не виртуальный поток. Если обратить особое внимание на количество строк в этом stack trace, мы заметим довольно странную вещь, а именно, поток кажется заблокированным внутри метода acquire()(который является внутренним) после завершения ожидания. Другими словами, этот вызывающий поток забрал себе lock во время входа в awaitNanos(). Мы знаем, что lock был в явном виде получен здесь. Однако к тому моменту, когда ожидание завершилось, поток не смог повторно захватить lock. Подводя итог нашему анализу дампа потоков:

Имеются пять виртуальных потоков и один обычный поток, ожидающие получения lock. Из пяти виртуальных потоков четыре прикреплены к ОС потокам в fork-join пуле. Все еще нет информации о том, кто присвоил себе lock. Поскольку мы больше ничего не можем узнать, анализируя thread dump, логически наш следующий шаг — это заглянуть в heap dump и проанализировать состояние lock.

Инспекция lock

Найти lock внутри heap dump было относительно просто. Используя отличный инструмент Eclipse MAT, мы проверили объекты в стеке невиртуального потока AsyncReporter , чтобы идентифицировать объект lock. Размышления по поводу текущего состояния lock были, пожалуй, самой сложной частью нашего расследования. Большую часть релевантного кода можно найти в AbstractQueuedSynchronizer.java. Мы не претендуем на полное понимание внутренних механизмов работы этого кода, но мы дизассемблировали достаточно, чтобы сравнить с тем, что мы видим в heap dump. Приведенная ниже схема иллюстрирует наши выводы:

Во-первых, поле exclusiveOwnerThread имеет значение null (2), что означает, что lock никому не принадлежит. Мы имеем “пустой” ExclusiveNode (3) в начале списка (его поле waiter равно null, а status очищен); далее следует другая ExclusiveNode, где waiter указывает на один из виртуальных потоков, конкурирующих за lock — #119516 (4). Единственное место, где мы обнаружили, что поле exclusiveOwnerThread очищается, находится внутри метода ReentrantLock.Sync.tryRelease( (ссылка на исходник). Там же мы устанавливаем state = 0, что соответствует состоянию,которое мы видим в  heap dump (1).

Держа это в голове, мы отследили путь в коде до release() метода, освобождающего lock. После успешного вызова tryRelease(), поток, удерживающий lock, пытается послать сигнал следующему waiter в списке. На этом этапе поток, удерживающий lock, все еще находится в начале списка, даже несмотря на то, что право владения lock фактически освобождено. Следующий узел в списке указывает на поток, который вот-вот должен захватить lock.

Чтобы понять, как работает это сигнализирование, давайте рассмотрим путь захвата замка в методе AbstractQueuedSynchronizer.acquire(). В грубо упрощенном виде это бесконечный цикл, где потоки пытаются захватить lock и затем паркуются, если попытка была неудачной:

while(true) {
   if (tryAcquire()) {
      return; // lock acquired
   }
   park();
}

Когда поток, удерживающий lock, отпускает его и сигнализирует, что необходимо распарковать следующий ожидающий поток, распаркованный поток снова проходит полную итерацию цикла, что дает ему еще одну возможность получить lock. Действительно, наш thread dump показывает, что все наши ожидающие потоки запаркованы, на строке 754. После распарковки поток, который смог получить lock, должен оказаться в этом блоке кода, по сути переустанавливая голову списка и очищая ссылку на ожидающий поток.

Выражаясь более кратко, на поток, владеющий lock, ссылается головная нода из списка. Освобождение lock подает сигнал следующей ноде в списке, в то время как получение lock переустанавливает голову списка на текущую ноду. Это означает, что то, что мы видим в heap dump, отражает состояние, когда один поток уже отпустил lock, а следующий еще только должен его получить. Это странное промежуточное состояние, которое должно быть быстротечным, но наша JVM в нем застревает. Мы знаем, что поток #119516 был оповещен и должен получать lock прямо сейчас по причине состояния ExclusiveNode, которое мы идентифицировали в голове списка. Однако thread dumps показывают, что поток #119516 продолжает ждать, как и другие потоки, соревнующиеся за тот же lock. Как же нам примирить то, что мы видим в thread dumps и то, что находится в heap dumps?

Lock, для которого нет места 

Зная, что поток #119516 был реально оповещен, мы пошли назад в thread dump, чтобы перепроверить состояние потоков. Напомним, что у нас есть 6 потоков, ожидающих захвата lock, из которых 4 виртуальных потока закреплены за потоками операционной системы. Эти 4 потока не освободят свои потоки ОС, пока не захватят lock и не выйдут из synchronized блока. #107 “AsyncReporter <redacted>” — это обычный платформенный поток, так что ничто не должно помешать ему продолжать работу, если он получит lock. Остается один последний поток: #119516. Это виртуальный поток, но не закреплен за потоком операционной системы. Даже если ему было отправлено уведомление о выходе из состояния "парковки", он не может продолжить выполнение, так как в пуле fork-join не осталось потоков ОС, на которые его можно было бы назначить. Именно это здесь и происходит — хотя #119516 получил сигнал для выхода из состояния "парковки", он не может выйти из этого состояния, потому что пул fork-join занят четырьмя другими виртуальными потоками, которые также ожидают захвата того же замка. Ни один из этих закрепленных виртуальных потоков не может продолжить выполнение, пока не захватит lock. Это своего рода вариация классической проблемы deadlock, но вместо двух locks мы получаем один lock и семафор с четырьмя разрешениями, которые представляет пул fork-join.

Теперь, когда мы точно знаем, что произошло, было несложно создать воспроизводимый test case.

Вывод

Ожидается, что виртуальные потоки улучшат производительность посредством уменьшения непроизводительных издержек, относящихся к созданию потоков и переключению контекстов. Несмотря на некоторые шероховатости Java 21, виртуальные потоки в целом оправдывают ожидания. В нашем стремлении создавать более производительные Java приложения, мы видим потенциал к дальнейшему внедрению виртуальных потоков, являющихся ключом к достижению цели. Мы с нетерпением ждем Java 23 и ее дальнейших версий, что принесет нам множество обновления и, как мы надеемся, исправит проблемы интеграции между виртуальными потоками и блокирующими примитивами. 

Это исследование подчеркивает лишь один тип проблем, которые решают инженеры по производительности в Netflix. Мы надеемся, что этот взгляд на наш подход к решению проблем будет полезен другим в их будущих расследованиях.

Присоединяйтесь к русскоязычному сообществу разработчиков на Spring Boot в телеграм - Spring АйО, чтобы быть в курсе последних новостей из мира разработки на Spring Boot и всего, что с ним связано.

Ждем всех, присоединяйтесь