← назад к разделу

Сервис перестал отвечать. Процесс жив, процессор почти свободен, ошибок в логе нет, только метрика задержки ушла в потолок. Второй сюжет — память растёт трое суток, и график из статьи про утечки уже показал, что нижняя точка после сборки мусора ползёт вверх. В обоих случаях метрики честно сказали, что происходит, а на вопросы «где стоят потоки» и «кто держит память» ответить не могут — в них нет ни стеков, ни объектов.

Отвечают два снимка. Дамп потоков — фотография всех потоков процесса: имя, состояние, стек и замки, которые поток держит или ждёт. Он снимается за миллисекунды и весит килобайты. Дамп кучи — копия всех объектов и ссылок между ними: снимается секундами, весит примерно с живую часть кучи, зато показывает, кто кого держит.

Все фрагменты ниже сняты на Java 21 с небольшой программы, в которой специально сломано всё сразу: два потока-обработчика заказов встали в дедлок, восемь потоков с именами как у Tomcat делят пул HikariCP из двух соединений, четыре виртуальных потока спят, а кэш сессий на 200 тысяч записей лежит в обычной HashMap.

Как снять thread dump

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

jcmd — штатная утилита JDK, которая отправляет команду работающей JVM через сокет:

jcmd <pid> Thread.print        # дамп в вашу консоль
jcmd <pid> Thread.print -l     # плюс замки java.util.concurrent, которые держит каждый поток

jstack <pid> — старшая утилита с тем же результатом, jstack -l равен Thread.print -l. Обеим нужен JDK рядом с процессом: в образе с одной JRE их нет.

kill -3 <pid> посылает сигнал SIGQUIT, и JVM печатает дамп в свой stdout, а не в ваш терминал. В контейнере это лог пода, то есть kubectl logs. Процесс продолжает работать; способ выручает там, где есть оболочка, но нет JDK.

Actuator отдаёт тот же текст по HTTP, если endpoint threaddump включён в management.endpoints.web.exposure.include:

curl -H 'Accept: text/plain' http://localhost:8081/actuator/threaddump

Без заголовка Accept придёт JSON с теми же полями. Порт management при этом закрыт снаружи: в дампе имена потоков, классы и строки кода.

В Kubernetes дамп снимают через kubectl exec; PID у JVM обычно 1, потому что java — точка входа контейнера:

kubectl exec <pod> -c app -- jcmd 1 Thread.print > td-1.txt

Оболочка для этого не нужна: kubectl exec запускает исполняемый файл напрямую, так что в distroless-образе команда работает, если образ собран на JDK. Если в нём только JRE, JDK приносят с собой временным контейнером:

kubectl debug -it <pod> --image=eclipse-temurin:21 --target=app -- jcmd 1 Thread.print

--target подключает временный контейнер к пространству процессов контейнера app, и JVM видна оттуда под своим PID. Грабля одна: JVM принимает подключение только от того же uid или от root. Если политика кластера запрещает root и временный контейнер запущен под другим пользователем, jcmd через десять секунд отвечает target process 1 doesn't respond within 10500ms or HotSpot VM not loaded, а сама JVM трактует сигнал как обычный kill -3 и печатает дамп в лог пода. Побочным эффектом можно пользоваться: дамп уже лежит в kubectl logs.

Один дамп — фотография, по которой не понять, идёт поток или стоит. Поэтому снимают три с интервалом в десять секунд: поток, стоящий во всех трёх на одной строке, стоит по-настоящему.

for i in 1 2 3; do jcmd 1 Thread.print > td-$i.txt; sleep 10; done

Цена снимка — пауза: чтобы стеки не менялись под ногами, JVM останавливает все потоки в safepoint. На нашей программе с 45 потоками пауза, по журналу -Xlog:safepoint, составила от половины до трёх миллисекунд, а с ключом -l в том же прогоне — 46 мс: обход замков дороже стеков. На сервисе с пятью сотнями потоков и глубокими стеками это десятки миллисекунд, и на это время встают все запросы. Размер тоже предсказуем: 45 потоков дали 31 КБ, три дампа с трёхсот потоков уложатся в мегабайт.

Как читать thread dump

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

"http-nio-8080-exec-1" #25 [42499] prio=5 os_prio=31 cpu=0.50ms elapsed=16.48s ... waiting on condition имя номер в JVM id в ОС процессор за всю жизнь возраст что делает, словами JVM

Заголовок потока в дампе. Первый фильтр — cpu=: поток живёт 16 секунд и потратил полмиллисекунды процессора, значит он не работает, а ждёт. По id в ОС его находят в top -H.

cpu= — процессорное время за всю жизнь потока, и это первый фильтр. Поток http-nio-8080-exec-1 живёт 16 секунд и потратил полмиллисекунды: что бы ни было написано дальше, он не работает, а ждёт.

Следующая строка — java.lang.Thread.State, и четыре её значения значат не совсем то, что написано.

RUNNABLE — JVM считает, что поток выполняется или находится в нативном коде. Чтение из сокета — нативный код, поэтому поток, который минуту ждёт ответа базы, тоже RUNNABLE. Вот два потока из восьми, которые получили соединения и ждут ответа на pg_sleep(3600):

"http-nio-8080-exec-3" #27 [41475] prio=5 os_prio=31 cpu=0.74ms elapsed=16.48s ... runnable
   java.lang.Thread.State: RUNNABLE
	at sun.nio.ch.Net.poll(java.base@21.0.11/Native Method)
	...
	at org.postgresql.core.PGStream.receiveChar(PGStream.java:487)
	...
	at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:315)
	at com.zaxxer.hikari.pool.ProxyStatement.execute(ProxyStatement.java:95)
	at DumpDemo.handleRequest(DumpDemo.java:69)

Отличить работу от ожидания в сокете можно по двум признакам: cpu=0.74ms за 16 секунд и верхний кадр Net.poll, SocketRead, epollWait — всё это ожидание данных снаружи.

BLOCKED — поток ждёт монитор synchronized, который держит другой поток. В стеке у него - waiting to lock <адрес>, а у держателя тот же адрес с пометкой - locked. Адреса — то, по чему дамп читают с grep: нашли, кого ждут, нашли, кто держит.

WAITING — поток припаркован без срока: Object.wait(), LockSupport.park(), take() у очереди. Так выглядит свободный поток пула, который ждёт задачу через ThreadPoolExecutor.getTask; сотни таких потоков — норма, а не проблема.

TIMED_WAITING — то же, но с таймаутом: sleep, parkNanos, poll(timeout), await(timeout). Шесть потоков из наших восьми стоят именно так:

"http-nio-8080-exec-1" #25 [42499] prio=5 os_prio=31 cpu=0.50ms elapsed=16.48s ... waiting on condition
   java.lang.Thread.State: TIMED_WAITING (parking)
	at jdk.internal.misc.Unsafe.park(java.base@21.0.11/Native Method)
	- parking to wait for  <0x000000058aa7de98> (a java.util.concurrent.SynchronousQueue$Transferer)
	...
	at java.util.concurrent.SynchronousQueue.poll(java.base@21.0.11/SynchronousQueue.java:338)
	at com.zaxxer.hikari.util.ConcurrentBag.borrow(ConcurrentBag.java:162)
	at com.zaxxer.hikari.pool.HikariPool.getConnection(HikariPool.java:160)
	at com.zaxxer.hikari.HikariDataSource.getConnection(HikariDataSource.java:99)
	at DumpDemo.handleRequest(DumpDemo.java:68)
	...
	at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@21.0.11/ThreadPoolExecutor.java:1144)
	at java.lang.Thread.run(java.base@21.0.11/Thread.java:1583)

Стек читают снизу вверх. Внизу — как поток родился: Thread.run, runWorker пула. Наверху — где он стоит прямо сейчас: Unsafe.park. Кадры JDK и библиотек между ними объясняют, почему он там стоит: ConcurrentBag.borrow — это HikariCP ждёт свободное соединение. А первый кадр из вашего пакета — DumpDemo.handleRequest(DumpDemo.java:68) — та строка вашего кода, которая ждёт.

Дедлок JVM находит сама и печатает в конце дампа отдельным блоком:

Found one Java-level deadlock:
=============================
"order-worker-1":
  waiting to lock monitor 0x000000098f4382a0 (object 0x000000058aa974b0, a java.lang.Object),
  which is held by "order-worker-2"

"order-worker-2":
  waiting to lock monitor 0x000000098f438000 (object 0x000000058aa974c0, a java.lang.Object),
  which is held by "order-worker-1"

Поиск запускается сразу после печати стеков и умеет находить круги только на мониторах и на замках вроде ReentrantLock. Круг из Semaphore, CountDownLatch или очереди JVM не увидит: потоки будут просто WAITING, и искать «каждый ждёт то, что держит другой» придётся глазами.

Пулы читают не по потокам, а по местам: если все потоки Tomcat стоят на одном кадре, узкое место — это он. Считается одной командой по трём строкам после заголовка:

grep -A3 '^"http-nio' td-1.txt | grep -E '^\s+at ' | sort | uniq -c | sort -rn
      6 	at jdk.internal.misc.Unsafe.park(java.base@21.0.11/Native Method)
      2 	at sun.nio.ch.Net.poll(java.base@21.0.11/Native Method)
Tomcat: 8 потоков exec-1 exec-2 exec-3 exec-4 exec-5 exec-6 exec-7 exec-8 HikariCP: 2 соединения conn-1 conn-2 PostgreSQL pg_sleep 3600 с exec-2 exec-3 RUNNABLE, cpu=0.74ms верхний кадр Net.poll: ждут базу ? TIMED_WAITING, cpu=0.50ms ConcurrentBag.borrow → parkNanos: ждут свободное соединение в дампе: 6 × Unsafe.park, 2 × Net.poll — узкое место соединения, SQL смотрят в pg_stat_activity

Исчерпанный пул в дампе: два потока держат соединения и в состоянии RUNNABLE ждут базу на чтении из сокета, шесть стоят в TIMED_WAITING внутри ConcurrentBag.borrow. Все потоки пула на одном кадре — узкое место найдено.

Шесть в Unsafe.park под ConcurrentBag.borrow — ждут соединение из пула; два в Net.poll под PgStatement.execute — держат соединения и ждут базу. Дамп ответил, что узкое место — соединения, но не сказал, какие именно запросы их заняли: текста SQL в стеке нет, его в ту же минуту берут из pg_stat_activity. Через connectionTimeout (по умолчанию 30 секунд) ожидающие получат исключение, в котором та же картина сжата в скобки:

SQLTransientConnectionException: HikariPool-1 - Connection is not available,
request timed out after 240003ms (total=2, active=2, idle=0, waiting=2)

С виртуальными потоками у Thread.print есть слепое пятно: он печатает только платформенные потоки. Наши четыре виртуальных в дампе отсутствуют вовсе, а их носители из ForkJoinPool выглядят так:

"ForkJoinPool-1-worker-2" #38 [40195] daemon prio=5 os_prio=31 cpu=0.82ms elapsed=16.48s
   Carrying virtual thread #39
	at jdk.internal.vm.Continuation.run(java.base@21.0.11/Continuation.java:248)
	at java.lang.VirtualThread.runContinuation(java.base@21.0.11/VirtualThread.java:245)

Есть номер виртуального потока и ни одного его кадра. Полный список даёт другая команда:

jcmd <pid> Thread.dump_to_file -format=json /tmp/td.json   # или без -format, тогда текст

В файле потоки сгруппированы по контейнерам — по пулам, которые их создали, — и виртуальные на месте:

#34 "vt-mailer-0" virtual
      java.base/java.lang.VirtualThread.parkNanos(VirtualThread.java:635)
      java.base/java.lang.Thread.sleep(Thread.java:507)
      DumpDemo.pause(DumpDemo.java:99)

Два отличия от Thread.print, которые важно знать заранее: в Java 21 в этом формате нет ни состояний, ни блока про дедлок, судить приходится по верхнему кадру. И кадр VirtualThread.parkOnCarrierThread в стеке виртуального потока означает, что он припаркован вместе с носителем, — в Java 21 так ведёт себя synchronized, и наш vt-report-pinned показывает ровно это.

На трёхстах потоках помогают инструменты. fastthread.io принимает файл и раскладывает потоки по состояниям, склеивает одинаковые стеки и подсвечивает дедлоки; помните только, что в дампе имена потоков и классов вашего сервиса, и наружу его отдавать можно не всегда. IntelliJ IDEA делает то же локально: Code → Analyze Stack Trace or Thread Dump, вставить текст — получится список потоков с состояниями, а каждый кадр открывается в коде.

Как снять heap dump

Дамп потоков отвечает, где стоят, но не отвечает, кто держит память. Для этого нужен снимок кучи, и у него всё дороже: и пауза, и файл, и правила, где его снимать.

Команда одна, и ей нужен путь на диске, доступный процессу JVM:

jcmd <pid> GC.heap_dump /dumps/heap.hprof         # только живые объекты, перед записью полная сборка мусора
jcmd <pid> GC.heap_dump -all /dumps/heap.hprof    # всё, что лежит в куче, включая мусор

Пока пишется файл, процесс стоит целиком: это одна остановка в safepoint на всё время записи. На нашей программе занято было 227 МБ, файл вышел 246 МБ и писался 0,45 секунды — по журналу safepoint остановка HeapDumper заняла 452 мс. Скорость около половины гигабайта в секунду на локальный SSD означает, что куча в 8 ГБ — это 15–20 секунд полной тишины, а на сетевом диске дольше.

Второй способ не требует человека у консоли:

-XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/dumps

Когда JVM признаёт нехватку памяти, она пишет файл сама. Если путь — каталог, файл назовётся java_pid<pid>.hprof; если файл — он и будет, но второй раз JVM его не перезапишет, а честно скажет Unable to create /dumps/fixed.hprof: File exists. На кучах поменьше это быстро: куча в 128 МБ дала файл 69 МБ за 21 мс, в 256 МБ — 136 МБ за 0,23 секунды:

java.lang.OutOfMemoryError: Java heap space
Dumping heap to /dumps/java_pid3339.hprof ...
Heap dump file created [69483435 bytes in 0.021 secs]

Третий — Actuator: GET /actuator/heapdump вызывает ту же операцию через HotSpotDiagnosticMXBean и отдаёт файл ответом. Параметр live=false включает мусор. Endpoint по умолчанию не открыт по HTTP, и открывать его наружу нельзя ни при каких условиях: в файле токены, телефоны и тела запросов ваших пользователей.

Три правила для контейнера.

Путь должен быть на настоящем диске. emptyDir с medium: Memory и tmpfs в /tmp считаются в лимит памяти контейнера: файл размером с почти полную кучу удваивает потребление, и под получает OOMKilled посреди записи. Записываемый слой контейнера исчезает вместе с ним, а падение по памяти как раз и заканчивается перезапуском — дамп, снятый флагом, пропадёт раньше, чем вы его увидите. Поэтому HeapDumpPath смотрит на том: emptyDir на диске переживает перезапуск контейнера, PVC — и пересоздание пода. Места нужно с -Xmx.

Проверка живости должна пережить паузу. Пока JVM пишет 8 ГБ, она не отвечает на /actuator/health/liveness; с обычными periodSeconds: 10, timeoutSeconds: 1, failureThreshold: 3 kubelet убьёт контейнер примерно на тридцатой секунде — как раз посреди файла. Перед снятием порог поднимают, а лучше снимают с экземпляра, выведенного из-под трафика, и никогда — со всех реплик сразу.

Файл ещё нужно забрать. kubectl cp работает через tar внутри контейнера, и в distroless его нет; тогда файл читают с тома другим подом или через временный контейнер. Перед пересылкой — gzip: строки и нули сжимаются в разы, а массивы нулей в буферах — в десятки раз.

Как читать heap dump

Файл на несколько гигабайт открывают не сразу. Сначала — гистограмма классов, которая стоит одной полной сборки мусора и часто отвечает на вопрос без дампа:

jcmd <pid> GC.class_histogram
 num     #instances         #bytes  class name (module)
   1:        419377      215549112  [B (java.base@21.0.11)
   2:        204989        6559648  java.util.HashMap$Node (java.base@21.0.11)
   3:        218365        5240760  java.lang.String (java.base@21.0.11)
   4:           394        2157184  [Ljava.util.HashMap$Node; (java.base@21.0.11)

Читается это как улика, а не как ответ. 419 тысяч массивов байтов на 215 МБ — данные, которые кто-то держит. 205 тысяч узлов HashMap$Node и 218 тысяч строк — числа одного порядка, и вместе с массивами они складываются в «карту на 200 тысяч записей: строка-ключ, массив-значение». Какая карта и кто на неё ссылается, гистограмма не знает.

график памяти низ после GC ползёт вверх есть утечка GC.class_histogram что лежит: [B, HashMap$Node, String улика, но не держатель GC.heap_dump один экземпляр, диск, liveness файл к себе, gzip MAT: Leak Suspects кто держит и какую долю если отчёт не ответил Dominator Tree три верхних строки по retained по найденному объекту Path to GC Roots без слабых ссылок: static, Thread, стек

Порядок разбора памяти: от дешёвого к дорогому. Гистограмма стоит одной сборки мусора и часто отвечает сама; дамп и MAT — когда нужен держатель, а не список классов.

Это знает Eclipse MAT. При открытии он строит индексы рядом с файлом — на диске нужно ещё столько же, и самому MAT нужна память в MemoryAnalyzer.ini порядка размера дампа, — а потом сразу предлагает отчёт Leak Suspects: один-два подозреваемых объекта, доля кучи, которую каждый удерживает, и цепочка от корня до него. Для нашей программы подозреваемым будет экземпляр java.util.HashMap из статического поля DumpDemo.SESSION_CACHE. В девяти случаях из десяти отчёт и есть ответ.

Когда его нет, идут в Dominator Tree — список объектов, отсортированный по тому, сколько памяти освободится, если объект исчезнет. Это и есть разница между двумя размерами. Shallow — собственные байты объекта: у HashMap их 48. Retained — всё, до чего можно добраться только через него: у нашей карты это почти все 227 занятых мегабайт, потому что и таблица узлов, и ключи, и массивы-значения живут только благодаря ей. Первые три строки дерева, отсортированного по retained, — это и есть «кто держит».

Дальше — Path to GC Roots по найденному объекту, с исключением слабых и мягких ссылок: MAT показывает цепочку от корня до объекта, то есть причину, по которой сборщик не может его забрать. Корней несколько видов, и по виду корня сразу ясен класс ошибки: статическое поле класса — кэш или реестр без ограничения; объект Thread с полем threadLocals — значение, которое положили в ThreadLocal и не убрали, и поток пула унёс его с собой; локальная переменная в стеке — не утечка, а просто долгий запрос.

Когда объектов одного класса тысячи и нужны только большие, помогает OQL — язык запросов по дампу:

SELECT * FROM java.util.HashMap h WHERE h.size > 100000

Типичных картин четыре, и их узнают в лицо. Одна HashMap с retained в половину кучи — кэш без ограничения; лечится кэшем с размером и временем жизни. Десятки объектов Thread с одинаковым retained в несколько мегабайт — ThreadLocal в пуле: путь к корню проходит через Thread.threadLocals, и виноват тот, кто не вызвал remove() в finally. Немного массивов byte[] по мегабайту и больше, которые держат буферы клиентов HTTP или сериализаторов, — обычно не утечка, а цена буфера на поток; она бьёт, когда потоков стало много. И миллионы одинаковых String — гистограмма даёт число, а группировка по значению в MAT показывает, что это одна и та же строка, размноженная парсером; лечится дедупликацией на границе или флагом -XX:+UseStringDeduplication.

Смотрят в таком порядке: три верхних строки Dominator Tree и доля retained. Если самый большой объект держит меньше десятой части кучи и дальше идёт ровная россыпь — утечки нет, это рабочая нагрузка, и нужен второй дамп через час: MAT умеет сравнивать гистограммы двух файлов, и растущий класс виден по разнице счётчиков.

VisualVM и IntelliJ IDEA открывают тот же .hprof и показывают классы, экземпляры и retained size — для дампа на сотни мегабайт этого хватает. На гигабайтах MAT быстрее и единственный, у кого есть отчёт про подозреваемых, дерево доминаторов и OQL.

Два вопроса, которые задают чаще всего

jcmd или сразу VisualVM? В проде — jcmd и JFR, потому что там нет экрана и наружу не открыт ни один порт для JMX; VisualVM пришлось бы подключать через туннель, а он делает то же, что jcmd, только медленнее и с большим числом отказов. Порядок такой: на сервере снимают файл — дамп потоков, дамп кучи или запись JFR, — забирают его к себе и открывают VisualVM, MAT или Mission Control уже над файлом. VisualVM хорош на ноутбуке над локально запущенным сервисом.

Полезно ли включать thread dump во всех сервисах? Дамп не включают — его умеют снять за минуту. Это значит: в образе есть JDK или известен путь к временному контейнеру, у дежурного есть права на kubectl exec, есть том под файлы и на всех сервисах стоит -XX:+HeapDumpOnOutOfMemoryError. Автоматически дамп снимают по событию, а не постоянно: хук preStop с jcmd 1 Thread.print в файл на томе успевает отработать перед перезапуском по liveness, а скрипт по алерту снимает три дампа с интервалом в десять секунд. Постоянным бывает только фоновый JFR: он и так раз в 10–20 мс записывает состояния потоков, и картину момента аварии достают из его файла.

Коротко

  • Дамп потоков стоит миллисекунды и килобайты; дамп кучи — секунда полной остановки на каждые полгигабайта и файл размером с живую часть кучи.
  • Thread.print, jstack, kill -3 и /actuator/threaddump дают один текст и отличаются тем, куда он попадает; в Kubernetes — kubectl exec или kubectl debug --target от того же uid.
  • Три дампа с интервалом в десять секунд: поток, стоящий на одной строке во всех трёх, стоит по-настоящему.
  • RUNNABLE в Net.poll — не работа, а ожидание сети; смотрите cpu= в заголовке. WAITING у свободного потока пула — норма.
  • Стек читают снизу вверх до первого своего кадра; замки сводят по адресам locked / waiting to lock; дедлок на мониторах и ReentrantLock JVM находит сама, на Semaphore — нет.
  • Все потоки пула на одном кадре — узкое место найдено; ConcurrentBag.borrow — исчерпан пул соединений, SQL берут из pg_stat_activity.
  • Thread.print не видит виртуальные потоки; Thread.dump_to_file -format=json видит, но без состояний.
  • HeapDumpOnOutOfMemoryError стоит везде, HeapDumpPath смотрит на настоящий диск, не на tmpfs, и с запасом в -Xmx; liveness на время снимка ослабляют, снимают с одного экземпляра.
  • В дампе кучи первыми смотрят Leak Suspects и верх Dominator Tree по retained, затем Path to GC Roots без слабых ссылок.
  • В проде — jcmd, GUI открывают у себя над снятым файлом; дамп не включают, а умеют снять за минуту, автоматически — по preStop и по алерту.

Что почитать дальше