Как анализировать Thread Dump

В программе курса Разработчик Java довольно много тем,посвященных внутренностям работы JVM. Мы разбираемся в механизмах работы коллекций, байт-кода, сборщика мусора и т.д.
Сегодня предлагаем Вашему внимаю перевод довольно интересной статьи о thread dump-е. Что это такое, как его получить и как использовать.

Хотите узнать, как анализировать thread dump (дамп потоков)? Заходите под кат, чтобы узнать больше о том как в Java получить thread dump и что с ним потом делать.

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

В случае многопоточных приложений необходимо найти компромисс между усложнением программы и возможным повышением производительности, когда несколько потоков могут использовать все доступные (часто больше одного) ядра центрального процессора (CPU). Если сделать все правильно, то используя многопоточность (формализована в Amdahl's Law), можно добиться существенного прироста производительности приложения. Однако при этом надо помнить об обеспечении синхронного доступа нескольких потоков к разделяемому ресурсу. В большинстве случаев, фреймворки, такие как Spring, инкапсулируют работу с потоками и скрывают от пользователей многие технические детали. Однако и в случае применения современных сложных фреймворков что-то может пойти не так, и мы, как пользователи, столкнемся со сложно решаемыми багами многопоточности.

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

Основная терминология

С первого взгляда Java thread dump-ы могут показаться «китайской грамотой», ключом к ее понимаю являются следующие понятия. В общем, давайте, повторим основные термины многопоточности, которые будем использовать для анализа дампов.

• Thread или поток — дискретная единица многопоточности, управляемая Java Virtual Machine (JVM). Потоки JVM соответствуют потокам в операционной системе (OS) — native threads («естественные потоки»), которые и реализуют механизм выполнения кода.
  У каждого потока есть уникальный идентификатор и имя. Потоки могут быть «демонами» и «не демонами».Программа завершает свою работу, когда завершаются все потоки «не демоны» или вызывается метод Runtime.exit. Работающие «демоны» не влияют на завершение работы программы. Т.е. JVM ждем когда доработают все «не демоны» и завершает работу, на «не демонов» не обращает внимание.
  За более подробной информацией обращайтесь к документации класса Thread.
  Поток может находится в одном из следующих состояний:
  • Alive thread или «живой» — поток, который выполняет некоторую работу (нормальное состояние).
  • Blocked thread или «заблокированный» — поток, который попытался зайти в секцию синхронизации (synchronized), однако другой поток уже успел зайти в этот блок первым, и все следующие потоки, которые попытаются зайти в этот же блок оказываются заблокированными.
  • Waiting thread или «ожидающий» — поток, который вызвал метод wait (возможно, с указанием таймаута) и сейчас ждет, когда другой метод выполнит notify или nonifyAll на этом же объекте.
    Обратите внимание, поток не считается «ожидающим», если он вызвал wait с таймаутом и этот таймаут истек.
  • Sleeping thread или «спящий» — поток, который сейчас не выполняется, т.к. выполнил метод Thread.sleep (с указанием длительности «сна»).
• Monitor — это механизм, используемый в JVM для обеспечения многопоточного доступа к одному объекту. Механизм запускается при помощи специального ключевого слова synchronized.Каждый объект в Java имеет монитор, при помощи которого поток может синхронизоваться, т.е. выставить блокировку, которая гарантирует, что ни один другой поток не получит доступ к этому объекту, пока блокировка не будет снята, т.е. поток — владелец блокировки не выйдет из блока synchronized.
  Более подробную информацию смотрите в Synchronization section (17.1) of the Java Langauge Specification (JLS).
• Deadlock — это ситуация, в которой поток, скажем А, блокирует ресурс, ему нужен другой ресурс, который заблокирован другим потоком, скажем Б. Поток Б не отпускает этот ресурс, т.к. для завершения некой операции ему нужен ресурс, который заблокирован потоком А. Получается, что поток А ждет разблокировки ресурса потоком Б, который ждет разблокировку другого ресурса потоком А. И, таким образом, потоки ждут друг друга. В итоге, вся программа «висит» и ждет, когда потоки как-то разблокируются и продолжат работу. Во взаимной блокировке может быть много потоков. Эта проблема хорошо известна как «Проблема обедающих философов».
  
• Livelock — это ситуация, когда поток A заставляет поток В выполнить некое действие, которое в свою очередь приводит в выполнению поток А первоначального действия, которое в очередной раз вызывает действие потока В. Получается циклическая зависимость. Это можно представить, как собаку, бегающую за своим хвостом. Аналогично Deadlock, в ситуации Livelock программа не совершает прогресс, т.е. не выполняет полезное действие, однако в этой ситуации потоки не блокируются.

Представленная терминология не является исчерпывающей для описания мира многопоточности, однако этого достаточно, чтобы начинать анализировать thread dump-ы.
Более детальную информацию можно найти в этих источниках: Section 17 of the JLS и Java Concurrency in Practice

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

Создание примера программы

Прежде, чем создать thread dump, нам надо разработать Java-приложение. Традиционный «hello, world!» для нашей цели слишком прост, а дамп среднего размера приложения может оказаться слишком сложным для демонстрации. Исходя из этого, мы создадим достаточно простое приложение, в котором создаются два потока. Причем потоки попадают в deadlock:

public class DeadlockProgram {
    public static void main(String[] args) throws Exception {
        Object resourceA = new Object();
        Object resourceB = new Object();
        Thread threadLockingResourceAFirst = new Thread(new DeadlockRunnable(resourceA, resourceB));
        Thread threadLockingResourceBFirst = new Thread(new DeadlockRunnable(resourceB, resourceA));
        threadLockingResourceAFirst.start();
        Thread.sleep(500);
        threadLockingResourceBFirst.start();
    }
    private static class DeadlockRunnable implements Runnable {
        private final Object firstResource;
        private final Object secondResource;
        public DeadlockRunnable(Object firstResource, Object secondResource) {
            this.firstResource = firstResource;
            this.secondResource = secondResource;
        }
        @Override
        public void run() {
            try {
                synchronized(firstResource) {
                    printLockedResource(firstResource);
                    Thread.sleep(1000);
                    synchronized(secondResource) {
                        printLockedResource(secondResource);
                    }
                }
            } catch (InterruptedException e) {
                System.out.println("Exception occurred: " + e);
            }
        }
        private static void printLockedResource(Object resource) {
            System.out.println(Thread.currentThread().getName() + ": locked resource -> " + resource);
        }
    }
}

Эта программа создает два ресурса: resourceA и resourceB, и стартует два потока: threadLockingResourceAFirst и threadLockingResourceBFirst, которые блокируют ресурсы друг друга.Причиной возникновения deadlock-а является «перекрестная» блокировка ресурсов потоками.Причиной возникновения deadlock является попытка «взаимного» захвата ресурсов, т.е. поток threadLockingResourceAFirst захватывает ресурс resourceA, поток threadLockingResourceBFirst захватывает ресурс resourceB. После этого поток threadLockingResourceAFirst, не отпуская свой ресурс, пытается захватить resourceB, а поток threadLockingResourceBFirst, не отпуская свой ресурс, пытается захватить ресурс resourceA. В результате потоки блокируются. Задержка в 1с добавлена, чтобы гарантировать возникновение блокировки. Потоки ждут освобождение нужных ресурсов, но это никогда не случится.

Вывод программы будет таким (числа после java.lang.Object@ будут разные для каждого запуска):

Thread-0: locked resource -> java.lang.Object@149bc794Thread-1: locked resource -> java.lang.Object@17c10009

После вывода этих сообщений программа будет выглядеть как работающая (процесс, выполняющий эту программу, не завершен), при этом программа не выполняет никакой работы. Вот так вот и выглядит deadlock на практике. Чтобы решить проблему, нам надо вручную создать tread dump и проанализировать состояние потоков.

Генерация Thread Dump

На практике, Java-программа может аварийно завершиться и при этом создать thread dump. Однако в ряде случаев (например в случае deadlock-ов), программа не завершается и thread dump не создает, она просто зависает. Для создания дампа таких зависших программ, прежде всего надо выяснить идентификатор процесса программы, т.е. Process ID (PID). Для этого можно воспользоваться утилитой JVM Process Status (JPS), которая начиная с версии 7, входит в состав Java Development Kit (JDK). Чтобы найти PID процесса нашей зависшей программы, мы просто выполним jps в терминале (Windows или Linux):

$ jps11568 DeadlockProgram15584 Jps15636

Первая колонка — это идентификатор локальной виртуальной машины (Local VM ID, т.е. lvmid) для выполняемого Java-процесса. В контексте локальной JVM, lvmid указывает на PID Java-процесса. Надо отметить, что это значение, скорее всего, будет отличаться от значения выше. Вторая колонка — это имя приложения, которое может указывать на имя main-класса, jar-файла или быть равно «Unknown». Все зависит от того, как приложение было запущено.

В нашем случае имя приложения DeadlockProgram — это имя main-классы, который был запущен при старте программы. В примере выше PID программы 11568, этой информации достаточно для генерации thread dump'а. Для генерации дампа мы воспользуемся утилитой jstack, которая входит в состав JDK, начиная с версии 7. Чтобы получить дамп мы передадим в jstack в качестве параметра PID нашей программы и укажем флаг -l (создание длинного листинга). Вывод утилиты перенаправим в текстовый файл, т.е. thread_dump.txt:

jstack -l 11568 > thread_dump.txt

Полученный файл thread_dump.txt содержит thread dump нашей зависшей программы и содержит важную информацию для диагностики причин возникновения deadlock-а.
Если используется JDK до 7 версии, то для генерации дампа можно воспользоваться утилитой Linux — kill с флагом -3. Вызов kill -3 отправит программе сигнал SIGQUIT.
В нашем случае вызов будет такой:

kill -3 11568

Анализ простого Thread Dump

Открыв файл thread_dump.txt, мы увидим примерно следующее содержание:

2018-06-19 16:44:44
Full thread dump Java HotSpot(TM) 64-Bit Server VM (10.0.1+10 mixed mode):
Threads class SMR info:
_java_thread_list=0x00000250e5488a00, length=13, elements={
0x00000250e4979000, 0x00000250e4982800, 0x00000250e52f2800, 0x00000250e4992800,
0x00000250e4995800, 0x00000250e49a5800, 0x00000250e49ae800, 0x00000250e5324000,
0x00000250e54cd800, 0x00000250e54cf000, 0x00000250e54d1800, 0x00000250e54d2000,
0x00000250e54d0800
}
"Reference Handler" #2 daemon prio=10 os_prio=2 tid=0x00000250e4979000 nid=0x3c28 waiting on condition  [0x000000b82a9ff000]
   java.lang.Thread.State: RUNNABLE
    at java.lang.ref.Reference.waitForReferencePendingList(java.base@10.0.1/Native Method)
    at java.lang.ref.Reference.processPendingReferences(java.base@10.0.1/Reference.java:174)
    at java.lang.ref.Reference.access$000(java.base@10.0.1/Reference.java:44)
    at java.lang.ref.Reference$ReferenceHandler.run(java.base@10.0.1/Reference.java:138)
   Locked ownable synchronizers:
    - None
"Finalizer" #3 daemon prio=8 os_prio=1 tid=0x00000250e4982800 nid=0x2a54 in Object.wait()  [0x000000b82aaff000]
   java.lang.Thread.State: WAITING (on object monitor)
    at java.lang.Object.wait(java.base@10.0.1/Native Method)
    - waiting on <0x0000000089509410> (a java.lang.ref.ReferenceQueue$Lock)
    at java.lang.ref.ReferenceQueue.remove(java.base@10.0.1/ReferenceQueue.java:151)
    - waiting to re-lock in wait() <0x0000000089509410> (a java.lang.ref.ReferenceQueue$Lock)
    at java.lang.ref.ReferenceQueue.remove(java.base@10.0.1/ReferenceQueue.java:172)
    at java.lang.ref.Finalizer$FinalizerThread.run(java.base@10.0.1/Finalizer.java:216)
   Locked ownable synchronizers:
    - None
"Signal Dispatcher" #4 daemon prio=9 os_prio=2 tid=0x00000250e52f2800 nid=0x2184 runnable  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
   Locked ownable synchronizers:
    - None
"Attach Listener" #5 daemon prio=5 os_prio=2 tid=0x00000250e4992800 nid=0x1624 waiting on condition  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
   Locked ownable synchronizers:
    - None
"C2 CompilerThread0" #6 daemon prio=9 os_prio=2 tid=0x00000250e4995800 nid=0x4198 waiting on condition  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
   No compile task
   Locked ownable synchronizers:
    - None
"C2 CompilerThread1" #7 daemon prio=9 os_prio=2 tid=0x00000250e49a5800 nid=0x3b98 waiting on condition  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
   No compile task
   Locked ownable synchronizers:
    - None
"C1 CompilerThread2" #8 daemon prio=9 os_prio=2 tid=0x00000250e49ae800 nid=0x1a84 waiting on condition  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
   No compile task
   Locked ownable synchronizers:
    - None
"Sweeper thread" #9 daemon prio=9 os_prio=2 tid=0x00000250e5324000 nid=0x5f0 runnable  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
   Locked ownable synchronizers:
    - None
"Service Thread" #10 daemon prio=9 os_prio=0 tid=0x00000250e54cd800 nid=0x169c runnable  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
   Locked ownable synchronizers:
    - None
"Common-Cleaner" #11 daemon prio=8 os_prio=1 tid=0x00000250e54cf000 nid=0x1610 in Object.wait()  [0x000000b82b2fe000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
    at java.lang.Object.wait(java.base@10.0.1/Native Method)
    - waiting on <0x000000008943e600> (a java.lang.ref.ReferenceQueue$Lock)
    at java.lang.ref.ReferenceQueue.remove(java.base@10.0.1/ReferenceQueue.java:151)
    - waiting to re-lock in wait() <0x000000008943e600> (a java.lang.ref.ReferenceQueue$Lock)
    at jdk.internal.ref.CleanerImpl.run(java.base@10.0.1/CleanerImpl.java:148)
    at java.lang.Thread.run(java.base@10.0.1/Thread.java:844)
    at jdk.internal.misc.InnocuousThread.run(java.base@10.0.1/InnocuousThread.java:134)
   Locked ownable synchronizers:
    - None
"Thread-0" #12 prio=5 os_prio=0 tid=0x00000250e54d1800 nid=0xdec waiting for monitor entry  [0x000000b82b4ff000]
   java.lang.Thread.State: BLOCKED (on object monitor)
    at DeadlockProgram$DeadlockRunnable.run(DeadlockProgram.java:34)
    - waiting to lock <0x00000000894465b0> (a java.lang.Object)
    - locked <0x00000000894465a0> (a java.lang.Object)
    at java.lang.Thread.run(java.base@10.0.1/Thread.java:844)
   Locked ownable synchronizers:
    - None
"Thread-1" #13 prio=5 os_prio=0 tid=0x00000250e54d2000 nid=0x415c waiting for monitor entry  [0x000000b82b5ff000]
   java.lang.Thread.State: BLOCKED (on object monitor)
    at DeadlockProgram$DeadlockRunnable.run(DeadlockProgram.java:34)
    - waiting to lock <0x00000000894465a0> (a java.lang.Object)
    - locked <0x00000000894465b0> (a java.lang.Object)
    at java.lang.Thread.run(java.base@10.0.1/Thread.java:844)
   Locked ownable synchronizers:
    - None
"DestroyJavaVM" #14 prio=5 os_prio=0 tid=0x00000250e54d0800 nid=0x2b8c waiting on condition  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
   Locked ownable synchronizers:
    - None
"VM Thread" os_prio=2 tid=0x00000250e496d800 nid=0x1920 runnable  
"GC Thread#0" os_prio=2 tid=0x00000250c35b5800 nid=0x310c runnable  
"GC Thread#1" os_prio=2 tid=0x00000250c35b8000 nid=0x12b4 runnable  
"GC Thread#2" os_prio=2 tid=0x00000250c35ba800 nid=0x43f8 runnable  
"GC Thread#3" os_prio=2 tid=0x00000250c35c0800 nid=0x20c0 runnable  
"G1 Main Marker" os_prio=2 tid=0x00000250c3633000 nid=0x4068 runnable  
"G1 Conc#0" os_prio=2 tid=0x00000250c3636000 nid=0x3e28 runnable  
"G1 Refine#0" os_prio=2 tid=0x00000250c367e000 nid=0x3c0c runnable  
"G1 Refine#1" os_prio=2 tid=0x00000250e47fb800 nid=0x3890 runnable  
"G1 Refine#2" os_prio=2 tid=0x00000250e47fc000 nid=0x32a8 runnable  
"G1 Refine#3" os_prio=2 tid=0x00000250e47fd800 nid=0x3d00 runnable  
"G1 Young RemSet Sampling" os_prio=2 tid=0x00000250e4800800 nid=0xef4 runnable  
"VM Periodic Task Thread" os_prio=2 tid=0x00000250e54d6800 nid=0x3468 waiting on condition  
JNI global references: 2
Found one Java-level deadlock:
=============================
"Thread-0":
  waiting to lock monitor 0x00000250e4982480 (object 0x00000000894465b0, a java.lang.Object),
  which is held by "Thread-1"
"Thread-1":
  waiting to lock monitor 0x00000250e4982380 (object 0x00000000894465a0, a java.lang.Object),
  which is held by "Thread-0"
Java stack information for the threads listed above:
===================================================
"Thread-0":
    at DeadlockProgram$DeadlockRunnable.run(DeadlockProgram.java:34)
    - waiting to lock <0x00000000894465b0> (a java.lang.Object)
    - locked <0x00000000894465a0> (a java.lang.Object)
    at java.lang.Thread.run(java.base@10.0.1/Thread.java:844)
"Thread-1":
    at DeadlockProgram$DeadlockRunnable.run(DeadlockProgram.java:34)
    - waiting to lock <0x00000000894465a0> (a java.lang.Object)
    - locked <0x00000000894465b0> (a java.lang.Object)
    at java.lang.Thread.run(java.base@10.0.1/Thread.java:844)
Found 1 deadlock.

Introductory Information

Хотя на первый взгляд этот файл может показаться слишком сложным и запутанным, в действительности он весьма прост, если разбирать его по частям шаг за шагом.
В первой строке указывается время, когда дамп был сформирован, во второй — диагностическая информация о JVM, на которой дамп был получен:

2018-06-19 16:44:44Full thread dump Java HotSpot(TM) 64-Bit Server VM (10.0.1+10 mixed mode):

В этой секции нет информации о потоках. Тут задается общий контекст системы, в которой был собран дамп.

Общие сведенья о потоках

В следующей секции представлена информация о потоках, которые выполнялись в системе в момент сбора дампа:

Threads class SMR info:
_java_thread_list=0x00000250e5488a00, length=13, elements={
0x00000250e4979000, 0x00000250e4982800, 0x00000250e52f2800, 0x00000250e4992800,
0x00000250e4995800, 0x00000250e49a5800, 0x00000250e49ae800, 0x00000250e5324000,
0x00000250e54cd800, 0x00000250e54cf000, 0x00000250e54d1800, 0x00000250e54d2000,
0x00000250e54d0800
}

В следующей секции приводится список Safe Memory Reclamation (SMR) information.В нем содержится информация о потоках за пределами JVM, т.е. это не потоки виртуальной машины и не потоки сборщика мусора. Если посмотреть на адреса этих потоков, то можно заметить, что они соответствуют значению tid — «естественному, железному» (native) адресу в операционной системе, а не Thread ID. Троеточия используются для сокрытия излишней информации:

"Reference Handler" #2 ... tid=0x00000250e4979000 ...
"Finalizer" #3 ... tid=0x00000250e4982800 ...
"Signal Dispatcher" #4 ... tid=0x00000250e52f2800 ...
"Attach Listener" #5 ... tid=0x00000250e4992800 ...
"C2 CompilerThread0" #6 ... tid=0x00000250e4995800 ...
"C2 CompilerThread1" #7 ... tid=0x00000250e49a5800 ...
"C1 CompilerThread2" #8 ... tid=0x00000250e49ae800 ...
"Sweeper thread" #9 ... tid=0x00000250e5324000 ...
"Service Thread" #10 ... tid=0x00000250e54cd800 ...
"Common-Cleaner" #11 ... tid=0x00000250e54cf000 ...
"Thread-0" #12 ... tid=0x00000250e54d1800 ...
"Thread-1" #13 ... tid=0x00000250e54d2000 ...
"DestroyJavaVM" #14 ... tid=0x00000250e54d0800 ...

Потоки

Сразу после блока SMR следует список потоков. Первый поток в нашем списке — Reference Handler:

"Reference Handler" #2 daemon prio=10 os_prio=2 tid=0x00000250e4979000 nid=0x3c28 waiting on condition  [0x000000b82a9ff000]
   java.lang.Thread.State: RUNNABLE
    at java.lang.ref.Reference.waitForReferencePendingList(java.base@10.0.1/Native Method)
    at java.lang.ref.Reference.processPendingReferences(java.base@10.0.1/Reference.java:174)
    at java.lang.ref.Reference.access$000(java.base@10.0.1/Reference.java:44)
    at java.lang.ref.Reference$ReferenceHandler.run(java.base@10.0.1/Reference.java:138)
   Locked ownable synchronizers:
    - None

Краткое описание потока

В первой строке для каждого потока приводится общее описание. Описание содержит следующие пункты:

st->print("tid=" INTPTR_FORMAT " ", p2i(this));

st->print("nid=0x%x ", thread_id());

  st->print_cr("[" INTPTR_FORMAT "]", 
    (intptr_t)last_Java_sp() & ~right_n_bits(12));

Состояние потока

Вторая строка — это текущее состояние потока. Возможные состояния потока приведены в enum:Thread.State: NEW RUNNABLE BLOCKED WAITING TIMED_WAITING TERMINATEDБолее подробную информацию смотрите вдокументации.

Thread Stack Trace

Следующая секция содержит stack trace потока в момент снятия дампа. Этот stack trace очень похож на stack trace, который формируется не перехваченным исключением.И содержит имена классов и строк, которые выполнялись в момент формирования дампа.В случае потока Reference Handler мы не видим ничего интересного.Однако в трассировке потока Thread-02 есть кое-что интересное, отличное от стандартного трейса:

"Thread-0" #12 prio=5 os_prio=0 tid=0x00000250e54d1800 nid=0xdec waiting for monitor entry  [0x000000b82b4ff000]
   java.lang.Thread.State: BLOCKED (on object monitor)
    at DeadlockProgram$DeadlockRunnable.run(DeadlockProgram.java:34)
    - waiting to lock <0x00000000894465b0> (a java.lang.Object)
    - locked <0x00000000894465a0> (a java.lang.Object)
    at java.lang.Thread.run(java.base@10.0.1/Thread.java:844)
   Locked ownable synchronizers:
    - None

В трассировке мы видим, что добавилась информация о блокировке. Этот поток ожидает блокировкуна объекте с адресом 0x00000000894465b0 (тип объекта java.lang.Object). Более того поток сам удерживает блокировку с адресом 0x00000000894465a0 (тоже объект java.lang.Object). Эта информация нам пригодится далее для диагностики deadlock-а.

Захваченные примитивы синхронизации (Ownable Synchronizer)

В последней секции приводится список примитивов синхронизации (synchronizers), захваченных потоком. Это объекты, которые могут быть использованы для синхронизации потоков, например, защелки (locks).В соответствии с официальной документацией Java, Ownable Synchronizer — этонаследники AbstractOwnableSynchronizer (или его подкласса), которые могут быть эксклюзивно захвачены потоком для целей синхронизации.ReentrantLock и write-lock, но не read-lock класса ReentrantReadWriteLock — два хороших примера таких «ownable synchronizers», предлагаемых платформой.
Для получения более подробной информации по этому вопросу можно обратиться к этому посту.

Потоки JVM

В следующей секции дампа содержится информация о технических потоках JVM, которые не являются частью приложения и связаны с потоками операционной системы. Т.к. эти потоки работают вне приложения, у них нет идентификаторов потока. Чаще всего это потоки сборщика мусора и другие технические потоки JVM:

"VM Thread" os_prio=2 tid=0x00000250e496d800 nid=0x1920 runnable  
"GC Thread#0" os_prio=2 tid=0x00000250c35b5800 nid=0x310c runnable  
"GC Thread#1" os_prio=2 tid=0x00000250c35b8000 nid=0x12b4 runnable  
"GC Thread#2" os_prio=2 tid=0x00000250c35ba800 nid=0x43f8 runnable  
"GC Thread#3" os_prio=2 tid=0x00000250c35c0800 nid=0x20c0 runnable  
"G1 Main Marker" os_prio=2 tid=0x00000250c3633000 nid=0x4068 runnable  
"G1 Conc#0" os_prio=2 tid=0x00000250c3636000 nid=0x3e28 runnable  
"G1 Refine#0" os_prio=2 tid=0x00000250c367e000 nid=0x3c0c runnable  
"G1 Refine#1" os_prio=2 tid=0x00000250e47fb800 nid=0x3890 runnable  
"G1 Refine#2" os_prio=2 tid=0x00000250e47fc000 nid=0x32a8 runnable  
"G1 Refine#3" os_prio=2 tid=0x00000250e47fd800 nid=0x3d00 runnable  
"G1 Young RemSet Sampling" os_prio=2 tid=0x00000250e4800800 nid=0xef4 runnable  
"VM Periodic Task Thread" os_prio=2 tid=0x00000250e54d6800 nid=0x3468 waiting on condition

Глобальные ссылки JNI

В этой секции указывается количество глобальных ссылок, используемых JVM через JNI.Эти ссылки не обслуживаются сборщиком мусора и в определенных обстоятельствах могут стать причинойутечки памяти.

JNI global references: 2

В большинстве простых случаев эта информация не используется. Однако важность глобальных ссылок надопонимать. Более подробную информацию смотрите в этом постепосте.

Взаимно заблокированные (Deadlocked) потоки

Последний раздел содержит информацию о найденных взаимных блокировках (deadlocks).Если такие не обнаружатся, то и раздел будет пустым. Т.к. мы специально разработали приложение сблокировками, в нашем случае этот раздел есть. Блокировка обнаружена во время формирования дампа и представлена следующим сообщением:

Found one Java-level deadlock:
=============================
"Thread-0":
  waiting to lock monitor 0x00000250e4982480 (object 0x00000000894465b0, a java.lang.Object),
  which is held by "Thread-1"
"Thread-1":
  waiting to lock monitor 0x00000250e4982380 (object 0x00000000894465a0, a java.lang.Object),
  which is held by "Thread-0"
Java stack information for the threads listed above:
===================================================
"Thread-0":
    at DeadlockProgram$DeadlockRunnable.run(DeadlockProgram.java:34)
    - waiting to lock <0x00000000894465b0> (a java.lang.Object)
    - locked <0x00000000894465a0> (a java.lang.Object)
    at java.lang.Thread.run(java.base@10.0.1/Thread.java:844)
"Thread-1":
    at DeadlockProgram$DeadlockRunnable.run(DeadlockProgram.java:34)
    - waiting to lock <0x00000000894465a0> (a java.lang.Object)
    - locked <0x00000000894465b0> (a java.lang.Object)
    at java.lang.Thread.run(java.base@10.0.1/Thread.java:844)
Found 1 deadlock.

В первом подразделе описывается сценарий взаимной блокировки (deadlock):Поток Thread-0 ожидает возможность захватить монитор(это обращение к блоку synchronized(secondResource) в нашем приложении), в то же времяэтот поток удерживает монитор, который пытается захватить поток Thread-1 (это обращение ктому же фрагменту кода: synchronized(secondResource) в нашем приложении). Эта циклическая блокировка по другому называется deadlock. На рисунке нижеэта ситуация представлена в графическом виде:

Во втором подразделе для обоих заблокированных потоков приведен stack trace.Этот stack trace позволяет нам проследить за работой каждого потока до появления блокировки.В нашем случае, если мы посмотрим на строку: at DeadlockProgram$DeadlockRunnable.run(DeadlockProgram.java:34), то увидим проблемный участок кода:

printLockedResource(secondResource);

Эта строка является первой строкой блока synchronized, который является причиной блокировки,и подсказывает нам, что синхронизация на secondResource и является причиной взаимной блокировки.

Чтобы исправить ситуацию, мы должны обеспечить в обоих потоках одинаковый порядок синхронизации на ресурсах resourceA и resourceB. Если мы сделаем это, то придем к следующему приложению:

public class DeadlockProgram {
    public static void main(String[] args) throws Exception {
        Object resourceA = new Object();
        Object resourceB = new Object();
        Thread threadLockingResourceAFirst = new Thread(new DeadlockRunnable(resourceA, resourceB));
        Thread threadLockingResourceBFirst = new Thread(new DeadlockRunnable(resourceA, resourceB));
        threadLockingResourceAFirst.start();
        Thread.sleep(500);
        threadLockingResourceBFirst.start();
    }
    private static class DeadlockRunnable implements Runnable {
        private final Object firstResource;
        private final Object secondResource;
        public DeadlockRunnable(Object firstResource, Object secondResource) {
            this.firstResource = firstResource;
            this.secondResource = secondResource;
        }
        @Override
        public void run() {
            try {
                synchronized (firstResource) {
                    printLockedResource(firstResource);
                    Thread.sleep(1000);
                    synchronized (secondResource) {
                        printLockedResource(secondResource);
                    }
                }
            } catch (InterruptedException e) {
                System.out.println("Exception occurred: " + e);
            }
        }
        private static void printLockedResource(Object resource) {
            System.out.println(Thread.currentThread().getName() + ": locked resource -> " + resource);
        }
    }
}

Это приложение завершится без взаимной блокировки, и в качестве результата мы получим следующий вывод (обратите внимание на то, что адреса экземпляров класса Object изменились):

Thread-0: locked resource -> java.lang.Object@1ad895d1
Thread-0: locked resource -> java.lang.Object@6e41d7dd
Thread-1: locked resource -> java.lang.Object@1ad895d1
Thread-1: locked resource -> java.lang.Object@6e41d7dd

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

Анализ более сложных Thread Dump-ов

Дампы настоящих приложений могут быть очень большими и сложнымиВ одной JVM одновременно могут быть запущены сотни тысяч потоков. И заблокированными могут оказаться больше чем два потока (или может быть несколько проблем многопоточности, вызванных одной проблемой).Анализ такого громадного объема информации может стать настоящей проблемой.

Для анализа больших дампов предназначены специальные утилиты-анализаторы — Thread Dump Analyzers (TDAs). Эти утилиты парсят Java thread dump-ы и выводят информацию в человеко-читаемом виде, часто с применением графических средств. Более того, некоторые из них могут выполнить статический анализ и найти причину проблемы. Конечно, выбор конкретной утилиты зависит от целого ряда обстоятельств.Тем не менее приведем список наиболее популярных TDA:

• fastThread
• Spotify TDA
• IBM Thread and Monitor Dump Analyze for Java
• irockel TDA

Это далеко не полный список утилит подобного рода. Каждая утилита из этого списка выполняет достаточно качественный анализ и упрощает ручной труд анализа дампов.

Заключение

Thread dump-ы — это отличное средство анализа состояния Java-приложения, особенно в случаях неожиданного поведения многопоточных приложений. Однако без надлежащего багажа знаний, дампымогут внести дополнительную сложность и в без того сложную ситуацию.
В этой статье мы разработали приложение с deadlock, сформировали дамп зависшего приложения.Проанализировали дамп и нашли причину блокировки и исправили её. Это не всегда так просто,для анализа большинства реальных приложений очень полезно использовать специальные утилиты — анализаторы.

Тем не менее, каждый профессиональный Java-разработчик должен понимать основы анализа thread dump-ов. Должен ориентироваться в их структуре, знать какую информацию можно извлечь и как ее использоватьдля решения проблем многопоточности.
Хотя, thread dump — это не «серебряная пуля» в мире многопоточности, тем не менее это важное средстводиагностирования сложных, но довольно распространенных проблем многопоточных Java-приложений.

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

Как всегда интересны ваши мнения и комментарии, которые можно оставить тут или заглянуть к Виталию на день открытых дверей.

Автор: Petrelevich

Источник