[java] Deadlock Principle Analysis and Detection Tool

Posted by Thauwa on Wed, 25 Sep 2019 08:18:27 +0200

I recently read some blogs about multithreaded deadlock analysis, especially Java multithreaded thread dump and analysis (jstack) In this article, the explanation is the clearest. I have some experience in deadlock analysis, and I will summarize and record it below.

Catalog

1. Introduction to deadlock

2. Examples of deadlocks

3. Visual VM for Deadlock Analysis Tools

3.1 Introduction to Visual VM

3.2 Installation of Plug-ins in Visual VM

3.3 Thread Monitoring

3.4 Thread dump analysis

3.5 Dump Content Analysis

1. Introduction to deadlock

Threads run in different states from creating and starting, to waiting or blocking to continue running, and finally to finishing all tasks defined in the thread [code in the run method].

What is the difference between blocking and waiting?

  • A blocked thread is waiting for an exclusive lock, which is occupied by another thread. When another thread releases the lock, the thread can get the lock and exit the blocked state.
  • The thread in the waiting state waits for a period of time. When the system wakes up or other threads wake up, the thread exits the waiting state.

What are exclusive locks and shared locks?

  • Exclusive lock: If thread 1 adds exclusive lock to data A, other threads can no longer add any type of blockade to A. Threads that are allowed to lock exclusively can read and modify data.
  • Shared locks: If thread 1 adds shared locks to data A, other threads can only add shared locks to A, not exclusive locks. Threads that are allowed to share locks can only read data and cannot modify it.

Why does deadlock happen?

Several threads wait for each other to release the blockade, and then they fall into an indefinite waiting state. The system enters a deadlock, which is the phenomenon shown in the following figure:

2. Examples of deadlocks

Here is an example of a blogger who thinks he's a big blogger.

Write a deadlock with ReentrantLock. After thread-1 obtains lockA, wait for lockB. After thread-2 obtains lockB, wait for lockA. The test code is as follows:

import java.util.concurrent.locks.Lock;
import java.util.concurrent.locks.ReentrantLock;

public class TestDeadLock {

	private final static Lock lockA = new ReentrantLock(true);
	private final static Lock lockB = new ReentrantLock(true);

	public static void main(String[] args) {

		Thread t1 = new Thread(() -> {
			lockA.lock();
			try {
				System.out.println("thread-1 " + " get lockA. try to get lockB");
				lockB.lock();
			} finally {
				lockB.unlock();
				lockA.unlock();
				System.out.println("thread-1 finished.");
			}
		});
		t1.setName("Thread-1");

		Thread t2 = new Thread(() -> {
			lockB.lock();
			try {
				System.out.println("thread-2 " + " get lockB. try to get lockA ");
				lockA.lock();
			} finally {
				lockA.unlock();
				lockB.unlock();
				System.out.println("thread-2 finished.");
			}
		});
		t2.setName("Thread-2");

		t1.start();
		t2.start();
	}
}

The operation effect is shown as follows:

From the experimental results, we can see that threads 1 and 2 are waiting for the release of the lock held by the other side, but they are in blocking state, and the system is in deadlock state.

For such a simple multi-threaded deadlock, we can analyze and solve deadlocks by ourselves. When we encounter more complex problems, how can we analyze and solve deadlocks?

3. Visual VM for Deadlock Analysis Tools

3.1 Introduction to Visual VM

Visual VM is a profile subproject of Netbeans. It has been brought in JDK 6.0. Under the JDK_HOME/bin directory (default is C: Program Files Java jdk1.6.0_13 bin), there is a jvisual vm.exe file. Double-click to open it. From the UI point of view, the software is developed on NetBeans.

Visual VM provides a visual interface. Double-click to start jvisual vm.exe. After starting up, you can choose local and remote as jconsole. If you need to monitor remote, you also need to configure relevant parameters. Visual VM can install different plug-ins according to need. Each plug-in has different concerns. Some mainly monitor GC, some mainly monitor memory, some monitor threads and so on.

3.2 Installation of Plug-ins in Visual VM

1. Select Tools > Plug-ins from the main menu.
2. In the Available Plug-ins tab, select the Installation check box for the plug-in. Click Install.
3. Complete the plug-in installer step by step.

 

This paper mainly introduces three plug-ins used by the author: Visual GC, Thread Inspector and Visual VM-JConsole:

 

3.3 Thread Monitoring

With the three plug-ins above, we can analyze the deadlock, open the Visual VM, and then run the example in eclipse. You can see that there is an additional thread in the local directory of the Visual VM, as shown in the following figure:

Double-click the process to see the effect shown in the following figure:

Click on the "Monitor" tab to see the following picture:

From the figure above, we can see the cpu usage and gc recovery of threads, the heap capacity and heap usage size, the total number of classes loaded into memory, and the thread situation.

Click on the Thread tab, as shown in the following figure:

As shown in the figure above, we can not only see all threads in the program, but also see the state of all threads very clearly. Thread-1 and Thread-2 are both in the resident state, i.e. blocking state.

3.4 Thread dump analysis

As shown in the figure in the previous section, Visual VM has analyzed the existence of deadlocks in current programs. We can record the details of each thread running by clicking "thread Dump", and then analyze the causes of deadlocks. We can see that the following results are generated:

2019-09-25 13:40:45
Full thread dump Java HotSpot(TM) 64-Bit Server VM (25.131-b11 mixed mode):

"RMI TCP Connection(6)-10.21.17.115" #20 daemon prio=5 os_prio=0 tid=0x000000001ccd9800 nid=0x3728 runnable [0x000000001e2be000]
   java.lang.Thread.State: RUNNABLE
        at java.net.SocketInputStream.socketRead0(Native Method)
        at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
        at java.net.SocketInputStream.read(SocketInputStream.java:171)
        at java.net.SocketInputStream.read(SocketInputStream.java:141)
        at java.io.BufferedInputStream.fill(BufferedInputStream.java:246)
        at java.io.BufferedInputStream.read(BufferedInputStream.java:265)
        - locked <0x0000000783e10b38> (a java.io.BufferedInputStream)
        at java.io.FilterInputStream.read(FilterInputStream.java:83)
        at sun.rmi.transport.tcp.TCPTransport.handleMessages(TCPTransport.java:550)
        at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run0(TCPTransport.java:826)
        at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.lambda$run$0(TCPTransport.java:683)
        at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler$$Lambda$5/1445897752.run(Unknown Source)
        at java.security.AccessController.doPrivileged(Native Method)
        at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run(TCPTransport.java:682)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
        at java.lang.Thread.run(Thread.java:748)

   Locked ownable synchronizers:
        - <0x0000000783e10cc0> (a java.util.concurrent.ThreadPoolExecutor$Worker)

"JMX server connection timeout 17" #17 daemon prio=5 os_prio=0 tid=0x000000001adf6000 nid=0x3adc in Object.wait() [0x000000001c5ee000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        at com.sun.jmx.remote.internal.ServerCommunicatorAdmin$Timeout.run(ServerCommunicatorAdmin.java:168)
        - locked <0x0000000783e08db0> (a [I)
        at java.lang.Thread.run(Thread.java:748)

   Locked ownable synchronizers:
        - None

"RMI Scheduler(0)" #16 daemon prio=5 os_prio=0 tid=0x000000001adf4000 nid=0x3ab8 waiting on condition [0x000000001c4ee000]
   java.lang.Thread.State: TIMED_WAITING (parking)
        at sun.misc.Unsafe.park(Native Method)
        - parking to wait for  <0x0000000783e18178> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
        at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078)
        at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:1093)
        at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:809)
        at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1067)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1127)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
        at java.lang.Thread.run(Thread.java:748)

   Locked ownable synchronizers:
        - None

"RMI TCP Accept-0" #14 daemon prio=5 os_prio=0 tid=0x000000001ae55800 nid=0x13c4 runnable [0x000000001c1ee000]
   java.lang.Thread.State: RUNNABLE
        at java.net.DualStackPlainSocketImpl.accept0(Native Method)
        at java.net.DualStackPlainSocketImpl.socketAccept(DualStackPlainSocketImpl.java:131)
        at java.net.AbstractPlainSocketImpl.accept(AbstractPlainSocketImpl.java:409)
        at java.net.PlainSocketImpl.accept(PlainSocketImpl.java:199)
        - locked <0x0000000783e09080> (a java.net.SocksSocketImpl)
        at java.net.ServerSocket.implAccept(ServerSocket.java:545)
        at java.net.ServerSocket.accept(ServerSocket.java:513)
        at sun.management.jmxremote.LocalRMIServerSocketFactory$1.accept(LocalRMIServerSocketFactory.java:52)
        at sun.rmi.transport.tcp.TCPTransport$AcceptLoop.executeAcceptLoop(TCPTransport.java:400)
        at sun.rmi.transport.tcp.TCPTransport$AcceptLoop.run(TCPTransport.java:372)
        at java.lang.Thread.run(Thread.java:748)

   Locked ownable synchronizers:
        - None

"DestroyJavaVM" #12 prio=5 os_prio=0 tid=0x0000000002611000 nid=0xeb0 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
        - None

"Thread-2" #11 prio=5 os_prio=0 tid=0x000000001af21000 nid=0xbd4 waiting on condition [0x000000001b8ef000]
   java.lang.Thread.State: WAITING (parking)
        at sun.misc.Unsafe.park(Native Method)
        - parking to wait for  <0x0000000783e18550> (a java.util.concurrent.locks.ReentrantLock$FairSync)
        at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:836)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:870)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1199)
        at java.util.concurrent.locks.ReentrantLock$FairSync.lock(ReentrantLock.java:224)
        at java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:285)
        at com.thread.lock.TestDeadLock.lambda$1(TestDeadLock.java:30)
        at com.thread.lock.TestDeadLock$$Lambda$2/1044036744.run(Unknown Source)
        at java.lang.Thread.run(Thread.java:748)

   Locked ownable synchronizers:
        - <0x0000000783e09718> (a java.util.concurrent.locks.ReentrantLock$FairSync)

"Thread-1" #10 prio=5 os_prio=0 tid=0x000000001af1d000 nid=0x3d2c waiting on condition [0x000000001b7ef000]
   java.lang.Thread.State: WAITING (parking)
        at sun.misc.Unsafe.park(Native Method)
        - parking to wait for  <0x0000000783e09718> (a java.util.concurrent.locks.ReentrantLock$FairSync)
        at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:836)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:870)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1199)
        at java.util.concurrent.locks.ReentrantLock$FairSync.lock(ReentrantLock.java:224)
        at java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:285)
        at com.thread.lock.TestDeadLock.lambda$0(TestDeadLock.java:17)
        at com.thread.lock.TestDeadLock$$Lambda$1/303563356.run(Unknown Source)
        at java.lang.Thread.run(Thread.java:748)

   Locked ownable synchronizers:
        - <0x0000000783e18550> (a java.util.concurrent.locks.ReentrantLock$FairSync)

"Service Thread" #9 daemon prio=9 os_prio=0 tid=0x000000001ac79800 nid=0x89c runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
        - None

"C1 CompilerThread2" #8 daemon prio=9 os_prio=2 tid=0x000000001abff800 nid=0x3960 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
        - None

"C2 CompilerThread1" #7 daemon prio=9 os_prio=2 tid=0x000000001abf9000 nid=0x3aec waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
        - None

"C2 CompilerThread0" #6 daemon prio=9 os_prio=2 tid=0x00000000198fc000 nid=0x38a0 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
        - None

"Attach Listener" #5 daemon prio=5 os_prio=2 tid=0x00000000198af800 nid=0x17e0 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
        - None

"Signal Dispatcher" #4 daemon prio=9 os_prio=2 tid=0x000000001abf8800 nid=0x8fc runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
        - None

"Finalizer" #3 daemon prio=8 os_prio=1 tid=0x000000001988a800 nid=0x3658 in Object.wait() [0x000000001abef000]
   java.lang.Thread.State: WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:143)
        - locked <0x0000000783e19020> (a java.lang.ref.ReferenceQueue$Lock)
        at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:164)
        at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:209)

   Locked ownable synchronizers:
        - None

"Reference Handler" #2 daemon prio=10 os_prio=2 tid=0x0000000019869000 nid=0x1814 in Object.wait() [0x000000001aaef000]
   java.lang.Thread.State: WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        at java.lang.Object.wait(Object.java:502)
        at java.lang.ref.Reference.tryHandlePending(Reference.java:191)
        - locked <0x0000000783e191d8> (a java.lang.ref.Reference$Lock)
        at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:153)

   Locked ownable synchronizers:
        - None

"VM Thread" os_prio=2 tid=0x0000000019867800 nid=0x15dc runnable 

"GC task thread#0 (ParallelGC)" os_prio=0 tid=0x0000000002627000 nid=0xfd4 runnable 

"GC task thread#1 (ParallelGC)" os_prio=0 tid=0x0000000002628800 nid=0x3fdc runnable 

"GC task thread#2 (ParallelGC)" os_prio=0 tid=0x000000000262a800 nid=0x3c8c runnable 

"GC task thread#3 (ParallelGC)" os_prio=0 tid=0x000000000262c800 nid=0x3e24 runnable 

"VM Periodic Task Thread" os_prio=2 tid=0x000000001acb7800 nid=0x24d4 waiting on condition 

JNI global references: 248


Found one Java-level deadlock:
=============================
"Thread-2":
  waiting for ownable synchronizer 0x0000000783e18550, (a java.util.concurrent.locks.ReentrantLock$FairSync),
  which is held by "Thread-1"
"Thread-1":
  waiting for ownable synchronizer 0x0000000783e09718, (a java.util.concurrent.locks.ReentrantLock$FairSync),
  which is held by "Thread-2"

Java stack information for the threads listed above:
===================================================
"Thread-2":
        at sun.misc.Unsafe.park(Native Method)
        - parking to wait for  <0x0000000783e18550> (a java.util.concurrent.locks.ReentrantLock$FairSync)
        at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:836)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:870)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1199)
        at java.util.concurrent.locks.ReentrantLock$FairSync.lock(ReentrantLock.java:224)
        at java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:285)
        at com.thread.lock.TestDeadLock.lambda$1(TestDeadLock.java:30)
        at com.thread.lock.TestDeadLock$$Lambda$2/1044036744.run(Unknown Source)
        at java.lang.Thread.run(Thread.java:748)
"Thread-1":
        at sun.misc.Unsafe.park(Native Method)
        - parking to wait for  <0x0000000783e09718> (a java.util.concurrent.locks.ReentrantLock$FairSync)
        at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:836)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:870)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1199)
        at java.util.concurrent.locks.ReentrantLock$FairSync.lock(ReentrantLock.java:224)
        at java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:285)
        at com.thread.lock.TestDeadLock.lambda$0(TestDeadLock.java:17)
        at com.thread.lock.TestDeadLock$$Lambda$1/303563356.run(Unknown Source)
        at java.lang.Thread.run(Thread.java:748)

Found 1 deadlock.

3.5 Dump Content Analysis

Take Thread-2 as an example:

"Thread-2" #11 prio=5 os_prio=0 tid=0x000000001af21000 nid=0xbd4 waiting on condition [0x000000001b8ef000]
   java.lang.Thread.State: WAITING (parking)
        at sun.misc.Unsafe.park(Native Method)
        - parking to wait for  <0x0000000783e18550> (a java.util.concurrent.locks.ReentrantLock$FairSync)
        at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:836)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:870)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1199)
        at java.util.concurrent.locks.ReentrantLock$FairSync.lock(ReentrantLock.java:224)
        at java.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:285)
        at com.thread.lock.TestDeadLock.lambda$1(TestDeadLock.java:30)
        at com.thread.lock.TestDeadLock$$Lambda$2/1044036744.run(Unknown Source)
        at java.lang.Thread.run(Thread.java:748)

   Locked ownable synchronizers:
        - <0x0000000783e09718> (a java.util.concurrent.locks.ReentrantLock$FairSync)

"Thread-2" stands for the name of the thread. If there is a daemon, it means that the thread is a daemon thread. Thread-2 is not a daemon thread, and all of them have no daemon.

prio=5, representing thread priority of 5 [default value].

Tid = 0x000000001 e69b800, representing Java thread Id (the unique identity of threads in the current virtual machine).

nid=0x2340, which represents the thread's local identity, that is, the thread's identity in the operating system.

waiting on condition: The state of the thread DUMP. Generally, there are several states as follows:

  • Runnable: This state indicates that the thread has all the runnable conditions, waits for the scheduling of the operating system in the running queue, or is running.
  • Wait on condition: This state indicates that the thread is waiting for a condition to occur. For example: waiting for network reads and writes, threads in sleep, threads parking. This is the condition.await() of the ReentrantLock to get the lock wait.
  • Waiting for monitor entry: Threads are waiting to acquire locks without acquiring them. The synchronized acquisition locks wait in this state.
  • in Object.wait(): The thread has acquired the lock and is running, but it executes the Object.wait() method to release the lock and still waits for the lock.

[0x000000001 f18e000]: Represents the address range of currently running threads in the heap;

java.lang.Thread.State: WAITING (parking): Represents the thread state is WAITING, which is suspended by parking.

parking to wait for <0x000000076b734700> (a java.util.concurrent.locks.ReentrantLock$FairSync): It is suspended by parking, waiting to obtain a fair lock 0x000076b734700 for ReentrantLock

Locked ownable synchronizers: - <0x000076b734730> (a java.util.concurrent.locks.ReentrantLock$FairSync): A fair lock 0x000076b734730 representing a ReentrantLock

Similarly, thread-1 already has a ReentrantLock fair lock 0x000076b734700, while waiting for thread-2 to have a ReentrantLock fair lock 0x000076b734730.

Found one Java-level deadlock:

Found one Java-level deadlock:
=============================
"Thread-2":
  waiting for ownable synchronizer 0x0000000783e18550, (a java.util.concurrent.locks.ReentrantLock$FairSync),
  which is held by "Thread-1"
"Thread-1":
  waiting for ownable synchronizer 0x0000000783e09718, (a java.util.concurrent.locks.ReentrantLock$FairSync),
  which is held by "Thread-2"

Thread 1 has locks in thread 2, and thread 2 has locks in thread 1.

Topics: Java Lambda JDK Eclipse