java死锁性能分析
java故障诊断案例分析: 死锁瓶颈(性能分析)
只要是java程序, 都可以使用这种方式来分析性能的瓶颈
1. Dump信息查看
Thread dump信息对于性能诊断非常有用
-
kill 命令使用
kill : 杀死一个进程
-9: 强制杀死一个进程
-3: 打印进程的Thread dump信息
-
linux系统: kill -3 pid
-
windows: 在命令行窗口上, 按一个组合键: ctrl + break(fn+B键)
2. 死锁程序分析
java的一个死锁程序代码:
public class DeadLock {
final Object lockA = new Object();
final Object lockB = new Object();
public static void main(String[] args) {
DeadLock demo = new DeadLock();
demo.startLock();
}
private void startLock() {
ThreadA a = new ThreadA(lockA, lockB);
ThreadB b = new ThreadB(lockA, lockB);
a.start();
b.start();
}
}
class ThreadA extends Thread {
private Object lockA = null;
private Object lockB = null;
public ThreadA(Object a, Object b) {
this.lockA = a;
this.lockB = b;
}
public void run() {
synchronized (lockA) {
System.out.println("*** Thread A: ***: Lock A");
try {
sleep(3000);
} catch (InterruptedException e) {
e.printStackTrace();
}
synchronized (lockB) {
System.out.println("*** Thread B: ***: Lock B");
}
}
System.out.println("*** Thread A: ***: Finished");
}
}
class ThreadB extends Thread {
private Object lockA = null;
private Object lockB = null;
public ThreadB(Object a, Object b) {
this.lockA = a;
this.lockB = b;
}
public void run() {
synchronized (lockB) {
System.out.println("*** Thread B: ***: Lock B");
try {
sleep(3000);
} catch (InterruptedException e) {
e.printStackTrace();
}
synchronized (lockA) {
System.out.println("*** Thread A: ***: Lock A");
}
}
System.out.println("*** Thread B: ***: Finished");
}
}
- 执行程序, 结果如下:
*** Thread A: ***: Lock A
*** Thread B: ***: Lock B
- 执行如下shell命令:
192:javatest lingjing$ jps
32246 Launcher
32247 DeadLock
32055
32248 Jps
192:javatest lingjing$ kill -3 32247
- 在原来程序的终端变成如下结果:
*** Thread A: ***: Lock A
*** Thread B: ***: Lock B
2019-05-26 11:01:24
Full thread dump Java HotSpot(TM) 64-Bit Server VM (25.151-b12 mixed mode):
"DestroyJavaVM" #13 prio=5 os_prio=31 tid=0x00007fe4fa012000 nid=0x2603 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"Thread-1" #12 prio=5 os_prio=31 tid=0x00007fe4fc82a000 nid=0xa603 waiting for monitor entry [0x00007000050a8000]
java.lang.Thread.State: BLOCKED (on object monitor)
at javatest.ThreadB.run(DeadLock.java:78)
- waiting to lock <0x000000076ac6ca00> (a java.lang.Object)
- locked <0x000000076ac6ca10> (a java.lang.Object)
"Thread-0" #11 prio=5 os_prio=31 tid=0x00007fe4fc801000 nid=0xa803 waiting for monitor entry [0x0000700004fa5000]
java.lang.Thread.State: BLOCKED (on object monitor)
at javatest.ThreadA.run(DeadLock.java:50)
- waiting to lock <0x000000076ac6ca10> (a java.lang.Object)
- locked <0x000000076ac6ca00> (a java.lang.Object)
"Service Thread" #10 daemon prio=9 os_prio=31 tid=0x00007fe4fd0d0000 nid=0x4103 runnable [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"C1 CompilerThread3" #9 daemon prio=9 os_prio=31 tid=0x00007fe4fd0d3000 nid=0x4303 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"C2 CompilerThread2" #8 daemon prio=9 os_prio=31 tid=0x00007fe4fd0d2000 nid=0x3f03 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"C2 CompilerThread1" #7 daemon prio=9 os_prio=31 tid=0x00007fe4fd0d1800 nid=0x3e03 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"C2 CompilerThread0" #6 daemon prio=9 os_prio=31 tid=0x00007fe4fd0d0800 nid=0x4703 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"Monitor Ctrl-Break" #5 daemon prio=5 os_prio=31 tid=0x00007fe4fd0ce000 nid=0x4903 runnable [0x0000700004890000]
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 sun.nio.cs.StreamDecoder.readBytes(StreamDecoder.java:284)
at sun.nio.cs.StreamDecoder.implRead(StreamDecoder.java:326)
at sun.nio.cs.StreamDecoder.read(StreamDecoder.java:178)
- locked <0x000000076adcaf90> (a java.io.InputStreamReader)
at java.io.InputStreamReader.read(InputStreamReader.java:184)
at java.io.BufferedReader.fill(BufferedReader.java:161)
at java.io.BufferedReader.readLine(BufferedReader.java:324)
- locked <0x000000076adcaf90> (a java.io.InputStreamReader)
at java.io.BufferedReader.readLine(BufferedReader.java:389)
at com.intellij.rt.execution.application.AppMainV2$1.run(AppMainV2.java:64)
"Signal Dispatcher" #4 daemon prio=9 os_prio=31 tid=0x00007fe4fa003800 nid=0x3d03 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
"Finalizer" #3 daemon prio=8 os_prio=31 tid=0x00007fe4f985b800 nid=0x3603 in Object.wait() [0x000070000468a000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x000000076ab08ec8> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:143)
- locked <0x000000076ab08ec8> (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)
"Reference Handler" #2 daemon prio=10 os_prio=31 tid=0x00007fe4fc815800 nid=0x3403 in Object.wait() [0x0000700004587000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)
- waiting on <0x000000076ab06b68> (a java.lang.ref.Reference$Lock)
at java.lang.Object.wait(Object.java:502)
at java.lang.ref.Reference.tryHandlePending(Reference.java:191)
- locked <0x000000076ab06b68> (a java.lang.ref.Reference$Lock)
at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:153)
"VM Thread" os_prio=31 tid=0x00007fe4f985b000 nid=0x3203 runnable
"GC task thread#0 (ParallelGC)" os_prio=31 tid=0x00007fe4f9800800 nid=0x1f07 runnable
"GC task thread#1 (ParallelGC)" os_prio=31 tid=0x00007fe4fc80a800 nid=0x2a03 runnable
"GC task thread#2 (ParallelGC)" os_prio=31 tid=0x00007fe4fc001000 nid=0x2c03 runnable
"GC task thread#3 (ParallelGC)" os_prio=31 tid=0x00007fe4fc80b000 nid=0x5303 runnable
"GC task thread#4 (ParallelGC)" os_prio=31 tid=0x00007fe4fc80b800 nid=0x5203 runnable
"GC task thread#5 (ParallelGC)" os_prio=31 tid=0x00007fe4fc80c000 nid=0x5003 runnable
"GC task thread#6 (ParallelGC)" os_prio=31 tid=0x00007fe4fc80d000 nid=0x4f03 runnable
"GC task thread#7 (ParallelGC)" os_prio=31 tid=0x00007fe4f9813000 nid=0x3003 runnable
"VM Periodic Task Thread" os_prio=31 tid=0x00007fe4fd0d3800 nid=0x5503 waiting on condition
JNI global references: 22
Found one Java-level deadlock:
=============================
"Thread-1":
waiting to lock monitor 0x00007fe4fd005568 (object 0x000000076ac6ca00, a java.lang.Object),
which is held by "Thread-0"
"Thread-0":
waiting to lock monitor 0x00007fe4fd007d48 (object 0x000000076ac6ca10, a java.lang.Object),
which is held by "Thread-1"
Java stack information for the threads listed above:
===================================================
"Thread-1":
at javatest.ThreadB.run(DeadLock.java:78)
- waiting to lock <0x000000076ac6ca00> (a java.lang.Object)
- locked <0x000000076ac6ca10> (a java.lang.Object)
"Thread-0":
at javatest.ThreadA.run(DeadLock.java:50)
- waiting to lock <0x000000076ac6ca10> (a java.lang.Object)
- locked <0x000000076ac6ca00> (a java.lang.Object)
Found 1 deadlock.
Heap
PSYoungGen total 76288K, used 10486K [0x000000076ab00000, 0x0000000770000000, 0x00000007c0000000)
eden space 65536K, 16% used [0x000000076ab00000,0x000000076b53d968,0x000000076eb00000)
from space 10752K, 0% used [0x000000076f580000,0x000000076f580000,0x0000000770000000)
to space 10752K, 0% used [0x000000076eb00000,0x000000076eb00000,0x000000076f580000)
ParOldGen total 175104K, used 0K [0x00000006c0000000, 0x00000006cab00000, 0x000000076ab00000)
object space 175104K, 0% used [0x00000006c0000000,0x00000006c0000000,0x00000006cab00000)
Metaspace used 3297K, capacity 4500K, committed 4864K, reserved 1056768K
class space used 364K, capacity 388K, committed 512K, reserved 1048576K
在上面的程序中, 如下的一段, 我们可以发现一个死锁, 并给出一个提示, 并提示我们在代码的78行和50行有错误, 所以我们分析代码逻辑, 来帮助我们找到死锁的节点
Java stack information for the threads listed above:
===================================================
"Thread-1":
at javatest.ThreadB.run(DeadLock.java:78)
- waiting to lock <0x000000076ac6ca00> (a java.lang.Object)
- locked <0x000000076ac6ca10> (a java.lang.Object)
"Thread-0":
at javatest.ThreadA.run(DeadLock.java:50)
- waiting to lock <0x000000076ac6ca10> (a java.lang.Object)
- locked <0x000000076ac6ca00> (a java.lang.Object)
Found 1 deadlock.
3. java性能分析工具thread dump和heap dump
1. dump基本概念
在故障定位(尤其是out of memory)和性能分析的时候,经常会用到一些文件来帮助我们排除代码问题。这些文件记录了JVM运行期间的内存占用、线程执行等情况,这就是我们常说的dump文件。常用的有heap dump和thread dump(也叫javacore,或java dump)。我们可以这么理解:heap dump记录内存信息的,thread dump是记录CPU信息的。
heap dump:
heap dump文件是一个二进制文件,它保存了某一时刻JVM堆中对象使用情况。HeapDump文件是指定时刻的Java堆栈的快照,是一种镜像文件。Heap Analyzer工具通过分析HeapDump文件,哪些对象占用了太多的堆栈空间,来发现导致内存泄露或者可能引起内存泄露的对象。
thread dump:
thread dump文件主要保存的是java应用中各线程在某一时刻的运行的位置,即执行到哪一个类的哪一个方法哪一个行上。thread dump是一个文本文件,打开后可以看到每一个线程的执行栈,以stacktrace的方式显示。通过对thread dump的分析可以得到应用是否“卡”在某一点上,即在某一点运行的时间太长,如数据库查询,长期得不到响应,最终导致系统崩溃。单个的thread dump文件一般来说是没有什么用处的,因为它只是记录了某一个绝对时间点的情况。比较有用的是,线程在一个时间段内的执行情况。
两个thread dump文件在分析时特别有效,困为它可以看出在先后两个时间点上,线程执行的位置,如果发现先后两组数据中同一线程都执行在同一位置,则说明此处可能有问题,因为程序运行是极快的,如果两次均在某一点上,说明这一点的耗时是很大的。通过对这两个文件进行分析,查出原因,进而解决问题。
2. 利用JDK自动的工具获取thread dump文件和heap dump
使用的JDK工具在JDK_HOME/bin/目录下,使用到jmap和jstack这两个命令。
1.获取heap dump文件
jmap -dump:format=b,file=heap.out 32274
#执行结果如下:
Dumping heap to /Users/lingjing/IdeaProjects/javatest/heap.out ...
Heap dump file created
这样就会在当前目录下生成heap.out文件,这就是heap dump文件。
- 获取thread dump文件
jstack 32274 >thread.out
结果转储到thread.out,这就是thread dump文件。有了dump文件后,我们就能借助性能分析工具获取dump文件中的信息。
- java heap dump工具分析
因为我们抓取的heap信息是二进制文件, 如果我们需要分析heap信息, 就需要借助一下分析工具, jhat是用来分析java堆的命令,可以将堆中的对象以html的形式显示出来,包括对象的数量,大小等等,并支持对象查询语言。
jhat -port 5001 heap.out
当服务启动完成以后, 我们可以在浏览器中通过http://127.0.0.1:5001/进行访问