Location analysis of recording an online deadlock

Online deadlock location analysis

Now? IT The world is generally highly concurrent , Distributed environment , Inevitable Deadlock , Dead cycle Other questions , We can usually stop the service during normal development , then hit trace ---> compile ---> Modify the source code ---> recompile ---> ..... ---> solve the problem , Or through the integrated development environment ( Such as : IDEA, Eclipse) Provided Debug function Breaking point ---> watch variable ---> Get into / Jump out of the way ---> .....---> solve the problem , however , When encountering the production environment, they are often at a loss , because The production environment can't just let you stop serving , And the production environment will not be open debug Port of (debug Open debugging is required <<-agentlib:jdwp=transport=dt_socket,server=y,suspend=n,address=5005>>), that , How to locate online deadlocks ? Yes? ---> solve the problem ?

actually , Java It has provided us with some useful positioning analysis tools , Of course , This is nonsense , You must know , You also know which commands are JDK Under the installation directory of bin Lower and java as well as javac Lie together . Yes , That's true , You are really a clever little ghost ( However, it has never been used, has it ? Today, Shuai Shuai gives you an application scenario , ha-ha …)

( Before going to bed last night, I got a little code to jfoa I never thought it would lead to online deadlock …)

1. jps

1.1 jps Virtual machine process health tool

Location analysis java Deadlock , Dead cycle you have to know what happened first LVMID(Logical Volume Manager ID), It's like you want to see Windows Details of an application on , You have to find out which process this application is running on .
Or you can put LVMID Understood as a PID, Usually LVMID and process PID It's consistent , But it doesn't have to be the same .

therefore , Want to know LVMID, By querying PID, But for one thing, it's not safe , second , When multiple virtual machine processes are started at the same time , Cannot distinguish by name , You have to use it jps 了 ( The task manager has n individual java.exe).

JackLi:~ dreamli$ jps
1461 
1847 GradleDaemon
1210 
1851 RunnerApplication
1852 Jps
JackLi:~ dreamli$ 

Above is a simple use , The number in the first column is LVMID, Followed by the main class of startup . Shuai Shuai used gradle Building tools , So there's a GradleDaemon, then jfoa The entry point of the project is RunnerApplication

1.2 jps Parameters

jps There are several parameters

• -q Only the output LVMID

JackLi:~ dreamli$ jps -q
1875
1461
1847
1210
1851

• -m The output goes to main The parameters of the function

JackLi:~ dreamli$ jps -m
1876 Jps -m
1461 
1847 GradleDaemon 6.2.2
1210 
1851 RunnerApplication

• -l Output the full name of the main class , If the process is executing jar, Will output jar route

JackLi:~ dreamli$ jps -l
1461 
1877 sun.tools.jps.Jps
1847 org.gradle.launcher.daemon.bootstrap.GradleDaemon
1210 
1851 club.javafamily.runner.RunnerApplication

• -v When the output virtual machine process starts JVM Parameters

JackLi:~ dreamli$ jps -v
1461  -Dosgi.requiredJavaVersion=1.8 -Dosgi.instance.area.default=@user.home/eclipse-workspace -XX:+UseG1GC -XX:+UseStringDeduplication -XstartOnFirstThread -Dorg.eclipse.swt.internal.carbon.smallFonts -Dosgi.requiredJavaVersion=1.8 -Xms256m -Xmx1024m -Xdock:icon=../Resources/Eclipse.icns -XstartOnFirstThread -Dorg.eclipse.swt.internal.carbon.smallFonts -javaagent:/Applications/Eclipse.app/Contents/Eclipse/lombok.jar
1878 Jps -Dapplication.home=/Users/dreamli/Software/java/zulu-jfx-252/zulu-8.jdk/Contents/Home -Xms8m
1847 GradleDaemon -Xmx2g -Dfile.encoding=UTF-8 -Duser.country=CN -Duser.language=zh -Duser.variant
1210  -Xms128m -Xmx2048m -XX:ReservedCodeCacheSize=240m -XX:+UseCompressedOops -Dfile.encoding=UTF-8 -XX:+UseConcMarkSweepGC -XX:SoftRefLRUPolicyMSPerMB=50 -ea -Dsun.io.useCanonCaches=false -Djava.net.preferIPv4Stack=true -Djdk.http.auth.tunneling.disabledSchemes="" -XX:+HeapDumpOnOutOfMemoryError -XX:-OmitStackTraceInFastThrow -Xverify:none -XX:ErrorFile=/Users/dreamli/java_error_in_idea_%p.log -XX:HeapDumpPath=/Users/dreamli/java_error_in_idea.hprof -javaagent:/Applications/IntelliJ IDEA.app/Contents/bin/jetbrains-agent.jar -Djb.vmOptionsFile=/Users/dreamli/Library/Preferences/IntelliJIdea2019.3/idea.vmoptions -Didea.home.path=/Applications/IntelliJ IDEA.app/Contents -Didea.executable=idea -Didea.paths.selector=IntelliJIdea2019.3
1851 RunnerApplication -Djava.rmi.server.hostname=127.0.0.1 -Dspring.profiles.active=dev -agentlib:jdwp=transport=dt_socket,server=y,suspend=n,address=5005 -Dfile.encoding=UTF-8 -Djava.io.tmpdir=/Users/dreamli/Workspace/MyRepository/javafamily/jfoa/runner/build/server-temp -Duser.country=CN -Duser.language=zh -Duser.variant

2 jstack

2.1 jstack: java Stack trace tool

jstack The command is used to generate a thread snapshot at the current time ( Commonly referred to as threaddump Documents or javacore file ), Thread snapshot is a collection of method stacks that are being executed by each thread in the current virtual machine , The purpose of generating a thread snapshot is to locate the reason why the thread has a long pause , Such as : thread deadlock , Dead cycle , The long waiting time of requesting external resources is a common reason for the long pause of threads .
The basic command format is as follows :
jstack [options] lvmid

JackLi:~ dreamli$ jps -m
1461 
1847 GradleDaemon 6.2.2
1210 
1851 RunnerApplication
1980 Jps -m
JackLi:~ dreamli$ jstack 1851
2020-11-26 23:59:27
Full thread dump OpenJDK 64-Bit Server VM (25.252-b14 mixed mode):

"Attach Listener" #62 daemon prio=9 os_prio=31 tid=0x00007faece823800 nid=0xac03 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"MessageBroker-2" #61 prio=5 os_prio=31 tid=0x00007faed3018800 nid=0x15403 waiting on condition [0x000070000ab6c000]
   java.lang.Thread.State: WAITING (parking)
	at sun.misc.Unsafe.park(Native Method)
	- parking to wait for  <0x0000000773124fa8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)

2.2 jstack Parameters

jstack There are a few parameters :

• -F: When a normal output request is not responded to , Force output thread stack
• -l: Display information about locks in addition to the stack
• -m: Call local methods , Can be displayed C/C++ The stack

3. Deadlock location analysis

Last night, the code ran until midnight , Submitted a lot of code , little does one think … Deadlock ------ Left tears of heartache …

3.1 jps location lvmid

The first step is needless to say , First find lvmid

3.2 jstack Get thread stack

3.1 remind Linux Little knowledge

• Write thread stack to local file

jstack -m 1851 >> .... Your path ../jfoa/jstack-2020-11-26.log

• Get remote Linux Stack file on

scp [email protected]:/root/jfoa-logs/jstack-2020-11-26.log ./jstack.txt

3.2 Thread stack file analysis

Here are some core points posted

"http-nio-80-exec-6" #58 daemon prio=5 os_prio=0 tid=0x00007efc15ccb800 nid=0x40 waiting on condition [0x00007efbdd490000]
   java.lang.Thread.State: WAITING (parking)
	at sun.misc.Unsafe.park(Native Method)
	- parking to wait for  <0x00000000e051e308> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
	at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
	at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
	at org.apache.tomcat.util.threads.TaskQueue.take(TaskQueue.java:107)
	at org.apache.tomcat.util.threads.TaskQueue.take(TaskQueue.java:33)
	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 org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
	at java.lang.Thread.run(Thread.java:745)

   Locked ownable synchronizers:
	- None



"jfoa-1" #78 prio=5 os_prio=0 tid=0x00000000009ef000 nid=0x52 waiting on condition [0x00007efbda87f000]
   java.lang.Thread.State: WAITING (parking)
	at sun.misc.Unsafe.park(Native Method)
	- parking to wait for  <0x00000000e0363ae0> (a java.util.concurrent.locks.ReentrantReadWriteLock$NonfairSync)
	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.ReentrantReadWriteLock$WriteLock.lock(ReentrantReadWriteLock.java:943)
	at club.javafamily.runner.web.portal.service.SubjectVoteService.getVoteCurrentCount(SubjectVoteService.java:159)
	at club.javafamily.runner.web.portal.service.SubjectVoteService.changeVote(SubjectVoteService.java:93)
	at club.javafamily.runner.web.portal.service.SubjectVoteService$$FastClassBySpringCGLIB$$c43301b2.invoke(<generated>)
	at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:218)
	at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:749)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163)
	at org.springframework.aop.interceptor.AsyncExecutionInterceptor.lambda$invoke$0(AsyncExecutionInterceptor.java:115)
	at org.springframework.aop.interceptor.AsyncExecutionInterceptor$$Lambda$848/1976926828.call(Unknown Source)
	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
	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:745)

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



"https-jsse-nio-443-exec-5" #45 daemon prio=5 os_prio=0 tid=0x00007efc15a17800 nid=0x33 waiting on condition [0x00007efbde19a000]
   java.lang.Thread.State: WAITING (parking)
	at sun.misc.Unsafe.park(Native Method)
	- parking to wait for  <0x00000000e0363ae0> (a java.util.concurrent.locks.ReentrantReadWriteLock$NonfairSync)
	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.ReentrantReadWriteLock$WriteLock.lock(ReentrantReadWriteLock.java:943)
	at club.javafamily.runner.web.portal.service.SubjectVoteService.getVoteCurrentCount(SubjectVoteService.java:159)
	at club.javafamily.runner.web.portal.service.SubjectVoteService$$FastClassBySpringCGLIB$$c43301b2.invoke(<generated>)
	at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:218)
	...
	   Locked ownable synchronizers:
	- <0x00000000e0520d38> (a java.util.concurrent.ThreadPoolExecutor$Worker)

"https-jsse-nio-443-exec-10" #50 daemon prio=5 os_prio=0 tid=0x00007efc15c2d800 nid=0x38 waiting on condition [0x00007efbddc94000]
   java.lang.Thread.State: WAITING (parking)
	at sun.misc.Unsafe.park(Native Method)
	- parking to wait for  <0x00000000e0363ae0> (a java.util.concurrent.locks.ReentrantReadWriteLock$NonfairSync)
	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.doAcquireShared(AbstractQueuedSynchronizer.java:967)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireShared(AbstractQueuedSynchronizer.java:1283)
	at java.util.concurrent.locks.ReentrantReadWriteLock$ReadLock.lock(ReentrantReadWriteLock.java:727)
	at club.javafamily.runner.web.portal.service.SubjectVoteService.getSubjectVoteDto(SubjectVoteService.java:61)
	at club.javafamily.runner.web.portal.service.SubjectVoteService$$FastClassBySpringCGLIB$$c43301b2.invoke(<generated>)
	at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:218)

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

Here is the main analysis Locked ownable synchronizers as well as "jfoa-1" #78 prio=5 os_prio=0 tid=0x00000000009ef000 nid=0x52 waiting on condition [0x00007efbda87f000]

• Locked ownable synchronizers Lock information is displayed

• "jfoa-1" #78 prio=5 os_prio=0 tid=0x00000000009ef000 nid=0x52 waiting on condition [0x00007efbda87f000] as follows

" The thread of " #78 prio=5 os_prio=0 tid=0x00000000009ef000 nid=0x52 waiting on condition [ Wait for lock status , 0(0x0000000000000000)  Means no lock ]
   java.lang.Thread.State:  Thread state 

Then analyze the deadlock in combination with the method call stack , The cause of the dead cycle .

4 Problem recurrence

The reason for Shuai Shuai's problem is ReentrantReadWriteLock Obtain the write lock in the read lock .( Obtaining a read lock in a write lock will not deadlock )

• Service

package org.jack.thread01;

import java.util.concurrent.locks.ReadWriteLock;
import java.util.concurrent.locks.ReentrantReadWriteLock;

/** * @Description:  Obtain the write lock in the read lock  * @Warning:  Deadlock  * @Author: Jack Li * @Package: thread-01 - ThreadService * @Date: Nov 26, 2020 10:57:49 PM * @Version: 1.0.0 * @TimeComplexity: Required[O(n)] ---- Current[O(n^2)] * @ExecuteResult: Success! * @Status: Accepted */
public class ThreadService {
    

	public void method1() {
    
		
		System.out.println("Method 1  Ready to acquire read lock ");
		lock.readLock().lock();
		
		System.out.println("Method 1  Get read lock ");

		try {
    
			Thread.sleep(2000);
			
			System.out.println("Method 1  Ready to get the write lock ");
			
			method3();
			
			System.out.println("Method 1  Obtain the write lock and release ");
			
			
		} 
		catch(Exception e) {
    
			e.printStackTrace();
		}
		finally {
    
			lock.readLock().unlock();
			
			System.out.println("Method 1  Release read lock ");
			
		}
	}

	public void method2() {
    
		System.out.println("Method 2  Ready to get the write lock ");
		lock.writeLock().lock();
		
		System.out.println("Method 2  Get write lock ");

		try {
    
			Thread.sleep(1000);
		} 
		catch(Exception e) {
    
			e.printStackTrace();
		}
		finally {
    
			lock.writeLock().unlock();
			
			System.out.println("Method 2  Release the write lock ");
		}
	}
	
	public void method3() {
    
		lock.writeLock().lock();

		try {
    
			Thread.sleep(500);
		} 
		catch(Exception e) {
    
			e.printStackTrace();
		}
		finally {
    
			lock.writeLock().unlock();
		}
	}

	private final ReadWriteLock lock = new ReentrantReadWriteLock();
}

• Program entrance

public class DealLockTest {
    
	public static void main(String[] args) {
    
		
		new Thread(() -> {
    
			threadService.method1();
		}) .start();
		
		new Thread(() -> {
    
			threadService.method2();
		}) .start();
		
	}
	
	private static ThreadService threadService = new ThreadService();
// private static ThreadService2 threadService = new ThreadService2();
}

• Thread stack

"Thread-1" #11 prio=5 os_prio=31 tid=0x00007fbda01c2000 nid=0xa903 waiting on condition [0x0000700003e8c000]
   java.lang.Thread.State: WAITING (parking)
	at sun.misc.Unsafe.park(Native Method)
	- parking to wait for  <0x000000076abbc1b8> (a java.util.concurrent.locks.ReentrantReadWriteLock$NonfairSync)
	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.ReentrantReadWriteLock$WriteLock.lock(ReentrantReadWriteLock.java:943)
	at org.jack.thread01.ThreadService.method2(ThreadService.java:50)
	at org.jack.thread01.DealLockTest.lambda$1(DealLockTest.java:11)
	at org.jack.thread01.DealLockTest$$Lambda$2/295530567.run(Unknown Source)
	at java.lang.Thread.run(Thread.java:748)

   Locked ownable synchronizers:
	- None

"Thread-0" #10 prio=5 os_prio=31 tid=0x00007fbda01be800 nid=0x5503 waiting on condition [0x0000700003d89000]
   java.lang.Thread.State: WAITING (parking)
	at sun.misc.Unsafe.park(Native Method)
	- parking to wait for  <0x000000076abbc1b8> (a java.util.concurrent.locks.ReentrantReadWriteLock$NonfairSync)
	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.ReentrantReadWriteLock$WriteLock.lock(ReentrantReadWriteLock.java:943)
	at org.jack.thread01.ThreadService.method3(ThreadService.java:68)
	at org.jack.thread01.ThreadService.method1(ThreadService.java:31)
	at org.jack.thread01.DealLockTest.lambda$0(DealLockTest.java:7)
	at org.jack.thread01.DealLockTest$$Lambda$1/250421012.run(Unknown Source)
	at java.lang.Thread.run(Thread.java:748)

   Locked ownable synchronizers:
	- None

Thread-0 First get the read lock , Then get the write lock before the read lock is released , When acquiring the write lock, you have to wait for all the read locks to be released . This leads to a deadlock .