Сервис перестал отвечать. Процесс жив, процессор почти свободен, ошибок в логе нет, только метрика задержки ушла в потолок. Второй сюжет — память растёт трое суток, и график из статьи про утечки уже показал, что нижняя точка после сборки мусора ползёт вверх. В обоих случаях метрики честно сказали, что происходит, а на вопросы «где стоят потоки» и «кто держит память» ответить не могут — в них нет ни стеков, ни объектов.
Отвечают два снимка. Дамп потоков — фотография всех потоков процесса: имя, состояние, стек и замки, которые поток держит или ждёт. Он снимается за миллисекунды и весит килобайты. Дамп кучи — копия всех объектов и ссылок между ними: снимается секундами, весит примерно с живую часть кучи, зато показывает, кто кого держит.
Все фрагменты ниже сняты на 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
Дамп на триста потоков — тысячи строк, подряд его не читают. Порядок другой: заголовок потока, состояние, стек снизу вверх — и только у подозрительных.
Заголовок потока в дампе. Первый фильтр — 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)
Исчерпанный пул в дампе: два потока держат соединения и в состоянии 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 тысяч записей: строка-ключ, массив-значение». Какая карта и кто на неё ссылается, гистограмма не знает.
Порядок разбора памяти: от дешёвого к дорогому. Гистограмма стоит одной сборки мусора и часто отвечает сама; дамп и 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; дедлок на мониторах иReentrantLockJVM находит сама, на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и по алерту.
Что почитать дальше
- Профилирование и утечки памяти — как по графику понять, что утечка есть, и когда вместо дампа нужен JFR.
- Дедлок, лайвлок и голодание — откуда берётся тот самый блок
Found one Java-level deadlockи как его не допустить. - Виртуальные потоки — почему
synchronizedв Java 21 приковывает носитель и как это выглядит вparkOnCarrierThread. - Health-проверки — что делает kubelet, когда liveness не отвечает, и почему это важно в момент снятия дампа.