【转】java线上程序排错经验2 - 线程堆栈分析

前言

在线上的程序中，我们可能经常会碰到程序卡死或者执行很慢的情况，这时候我们希望知道是代码哪里的问题，我们或许迫切希望得到代码运行到哪里了，是哪一步很慢，是否是进入了死循环，或者是否哪一段代码有问题导致程序很慢，或者出现了线程不安全的情况，或者是某些连接数或者打开文件数太多等问题，总之我们想知道程序卡在哪里了，哪块占用了大量的资源。

此时，或许通过线程堆栈的分析就能定位出问题。

如果能深入掌握堆栈分析的技术，很多问题都能迎刃而解，但是线程堆栈分析并不简单，设计到线上的排错问题，需要有一定的知识的广度，对某些知识也要有一定的深度，本人不才，无论是广度还是深度，都感觉略有欠缺，工作两年多来，碰到了很多问题，在解决问题时，并不是一帆风顺的，其中可没少折腾，但我相信，正确的理论可以指导实践，本文也算是现学现卖。

注：本文主要针对于Linux的，不过大多数在windows上也适用

什么是线程堆栈

线程栈：
Java线程堆栈是某个时间对所有线程的一个快照，其中主要记录了如下信息
– 线程的名称

线程的ID
原生线程ID
线程的运行状态
锁的状态
调用堆栈,也就是每个线程在各个方法调用的栈

上面描述的信息，接下来我们会具体的介绍与分析

如何分析

首先我们得知道如何去得到线程堆栈。工具有很多，我这里只介绍最原始的。先得到当前运行 java 程序的PID，这时候就要用到jps命令

jps 常用的几个命令

jps #显示所有java程序和线程ID  
jps -m #输出main method的参数 
jps -l #输出完全的包名，应用主类名，jar的完全路径名 
jps -v #输出jvm参数

一般直接使用 jps 即可，如果分不清哪个 pid 是哪个程序，可以直接

jps -mlv

下面举个简单的线程堆栈分析的例子

package me.zks.jvm.troubleshoot.threadhump;
public class FirstSample {
    public static void main(String[] args) {
        FirstSample firstSample = new FirstSample();
        firstSample.fun1();
    }
    public void fun1(){
        //执行某些不耗时操作，然后直接进入fun2方法
        fun2();
    }
    public void fun2(){
        //执行某些不耗时的操作，然后直接进入fun3方法
        fun3();
    }
    public void fun3(){
        //一个死循环，或者耗时特别大的操作
        while (true){
            System.out.println("");
        }
    }
}

上面程序打成 jar 包，名为 jvm-troubleshoot-1.0-SNAPSHOT.jar，在 linux 上运行

java -cp jvm-troubleshoot-1.0-SNAPSHOT.jar me.zks.jvm.troubleshoot.threadhump.FirstSample

另外开一个 session，输入 jps 显示如下

ubuntu@VM-0-12-ubuntu:~$ jps
27831 Jps
27819 FirstSample
ubuntu@VM-0-12-ubuntu:~$

输入 jps -mlv显示如下

ubuntu@VM-0-12-ubuntu:~$ jps -mlv
27874 sun.tools.jps.Jps -mlv -Dapplication.home=/usr/lib/jvm/java-8-oracle -Xms8m
27819 me.zks.jvm.troubleshoot.threadhump.FirstSample
ubuntu@VM-0-12-ubuntu:~$

jstack 27819 显示如下

ubuntu@VM-0-12-ubuntu:~$ jstack 27819
2018-09-02 13:56:14
Full thread dump Java HotSpot(TM) 64-Bit Server VM (25.171-b11 mixed mode):

“Attach Listener” #8 daemon prio=9 os_prio=0 tid=0x00007fd350001000 nid=0x6d27 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE

“Service Thread” #7 daemon prio=9 os_prio=0 tid=0x00007fd3700c6800 nid=0x6cb3 runnable [0x0000000000000000]
java.lang.Thread.State: RUNNABLE

“C1 CompilerThread1” #6 daemon prio=9 os_prio=0 tid=0x00007fd3700b1800 nid=0x6cb2 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE

“C2 CompilerThread0” #5 daemon prio=9 os_prio=0 tid=0x00007fd3700af800 nid=0x6cb1 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE

“Signal Dispatcher” #4 daemon prio=9 os_prio=0 tid=0x00007fd3700ae000 nid=0x6cb0 runnable [0x0000000000000000]
java.lang.Thread.State: RUNNABLE

“Finalizer” #3 daemon prio=8 os_prio=0 tid=0x00007fd37007b000 nid=0x6caf in Object.wait() [0x00007fd35befd000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)

- waiting on <0x00000000ec6b2c98> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:143)
- locked <0x00000000ec6b2c98> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:164)
at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:212)
“Reference Handler” #2 daemon prio=10 os_prio=0 tid=0x00007fd370076800 nid=0x6cae in Object.wait() [0x00007fd35bffe000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)

- waiting on <0x00000000ec6b2e50> (a java.lang.ref.Reference$Lock)
at java.lang.Object.wait(Object.java:502)
at java.lang.ref.Reference.tryHandlePending(Reference.java:191)
- locked <0x00000000ec6b2e50> (a java.lang.ref.Reference$Lock)
at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:153)
“main” #1 prio=5 os_prio=0 tid=0x00007fd37000a800 nid=0x6cac runnable [0x00007fd377121000]
java.lang.Thread.State: RUNNABLE
at java.io.FileOutputStream.writeBytes(Native Method)
at java.io.FileOutputStream.write(FileOutputStream.java:326)
at java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:82)
at java.io.BufferedOutputStream.flush(BufferedOutputStream.java:140)

- locked <0x00000000ec6bfe58> (a java.io.BufferedOutputStream)
at java.io.PrintStream.write(PrintStream.java:482)
- locked <0x00000000ec6b6ee0> (a java.io.PrintStream)
at sun.nio.cs.StreamEncoder.writeBytes(StreamEncoder.java:221)
at sun.nio.cs.StreamEncoder.implFlushBuffer(StreamEncoder.java:291)
at sun.nio.cs.StreamEncoder.flushBuffer(StreamEncoder.java:104)
- locked <0x00000000ec6b6e98> (a java.io.OutputStreamWriter)
at java.io.OutputStreamWriter.flushBuffer(OutputStreamWriter.java:185)
at java.io.PrintStream.newLine(PrintStream.java:546)
- eliminated <0x00000000ec6b6ee0> (a java.io.PrintStream)
at java.io.PrintStream.println(PrintStream.java:807)
- locked <0x00000000ec6b6ee0> (a java.io.PrintStream)
at me.zks.jvm.troubleshoot.threadhump.FirstSample.fun3(FirstSample.java:22)
at me.zks.jvm.troubleshoot.threadhump.FirstSample.fun2(FirstSample.java:17)
at me.zks.jvm.troubleshoot.threadhump.FirstSample.fun1(FirstSample.java:13)
at me.zks.jvm.troubleshoot.threadhump.FirstSample.main(FirstSample.java:9)
“VM Thread” os_prio=0 tid=0x00007fd37006f000 nid=0x6cad runnable

“VM Periodic Task Thread” os_prio=0 tid=0x00007fd3700cc000 nid=0x6cb4 waiting on condition

JNI global references: 5

通过上面的 jstack 我们可以知道，我们的这个简单程序，竟然有这么多线程，分别是：

“Attach Listener”
”Service Thread”
”C1 CompilerThread1”
”C2 CompilerThread0”
”Signal Dispatcher”
”Finalizer”
”Reference Handler
,”main”
”VM Thread”
”VM Periodic Task Thread”

其中，只有 main 线程是我们写的，其他的线程是 jvm 启动的时候，自己会创建一些辅助的线程，我们一般分析我们所写的线程（也不一定，有时候也是需要分析其他线程的），我们来仔细分析一下我们得这个 main 线程,我给每一行标了个号

01 “main” #1 prio=5 os_prio=0 tid=0x00007fd37000a800 nid=0x6cac runnable [0x00007fd377121000]
02 java.lang.Thread.State: RUNNABLE
03 at java.io.FileOutputStream.writeBytes(Native Method)
04 at java.io.FileOutputStream.write(FileOutputStream.java:326)
05 at java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:82)
06 at java.io.BufferedOutputStream.flush(BufferedOutputStream.java:140)
07 - locked <0x00000000ec6bfe58> (a java.io.BufferedOutputStream)
08 at java.io.PrintStream.write(PrintStream.java:482)
09 - locked <0x00000000ec6b6ee0> (a java.io.PrintStream)
10 at sun.nio.cs.StreamEncoder.writeBytes(StreamEncoder.java:221)
11 at sun.nio.cs.StreamEncoder.implFlushBuffer(StreamEncoder.java:291)
12 at sun.nio.cs.StreamEncoder.flushBuffer(StreamEncoder.java:104)
13 - locked <0x00000000ec6b6e98> (a java.io.OutputStreamWriter)
14 at java.io.OutputStreamWriter.flushBuffer(OutputStreamWriter.java:185)
15 at java.io.PrintStream.newLine(PrintStream.java:546)
16 - eliminated <0x00000000ec6b6ee0> (a java.io.PrintStream)
17 at java.io.PrintStream.println(PrintStream.java:807)
18 - locked <0x00000000ec6b6ee0> (a java.io.PrintStream)
19 at me.zks.jvm.troubleshoot.threadhump.FirstSample.fun3(FirstSample.java:22)
20 at me.zks.jvm.troubleshoot.threadhump.FirstSample.fun2(FirstSample.java:17)
21 at me.zks.jvm.troubleshoot.threadhump.FirstSample.fun1(FirstSample.java:13)
22 at me.zks.jvm.troubleshoot.threadhump.FirstSample.main(FirstSample.java:9)

先分析第一行

“main” #1 prio=5 os_prio=0 tid=0x00007fd37000a800 nid=0x6cac runnable [0x00007fd377121000]

"main" 即为线程的名称，所以给线程去个好的名字很重要，方便于我们得分析
#1 我也不知道（应该是线程ID，Thread.currentThread().getId() 可以获取）
prio=5 线程优先级，java 有1--10个优先级，当有多个线程处于可运行状态时，运行系统总是挑选一个优先级最高的线程执行，两个优先级相同的线程同时等待执行时，那么运行系统会以 round-robin 的方式选择一个线程执行，Java 的优先级策略是抢占式调度。
tid=0x00007fd37000a800 这个是 java虚拟机内部的ID，与什么操作系统没关系，我们可以通过 java.lang.Thread.getId() 或者 java.lang.management.ThreadMXBean.getAllThreadIds()获取到,在 Oracle / Sun的 JDK 实现中，此 ID只是一个自动递增的 long 类型的变量。
nid=0x6cac linux 或者 windows 等操作系统的线程ID，jvm 作为一个虚拟机，里面的所有线程ID，其实都是映射到linux上面，这个 ID 就是 linux 机器实际运行的线程 ID，这个很有用，我们可以通过这个来 linux上查一些比较重要的信息，这个以后会有详细说明。
runnable 线程的状态，线程的状态，这是从 java 虚拟机的角度来看的，表示线程正在运行，但是处于 Runnable 状态的线程不一定真地消耗 CPU，这个以后会说，线程状态以后也会详细说明。

分析第二行

java.lang.Thread.State: RUNNABLE， 描述了线程的状态

分析第3-22行

方法的调用栈的关系，我们一般从下往上看。例如先看第22行

at me.zks.jvm.troubleshoot.threadhump.FirstSample.main(FirstSample.java:9)

这行显示了正在调用的包名，类名，方法名称，以及代码中的第几行。

从上可知，main 法调用了 fun1, fun1 调用了 fun2, fun2 调用了 fun3, fun3 调用了java.io.PrintStream.println .....

使用 top 命令，看看是哪个线程占用的 cpu 最多,一般使用top -Hp 27819

top -Hp 27819

top-hp pid !

线程锁分析

jps

ubuntu@VM-0-12-ubuntu:~$ jps
21786 LockAnalysics
21804 Jps

jstack

ubuntu@VM-0-12-ubuntu:~$ jstack 21786
2018-09-02 22:06:31
Full thread dump Java HotSpot(TM) 64-Bit Server VM (25.171-b11 mixed mode):

“Attach Listener” #12 daemon prio=9 os_prio=0 tid=0x00007f0bac001000 nid=0x5563 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE

“DestroyJavaVM” #11 prio=5 os_prio=0 tid=0x00007f0bd000a800 nid=0x551b waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE

“ThreadWaitTo” #10 prio=5 os_prio=0 tid=0x00007f0bd00ef800 nid=0x5526 waiting for monitor entry [0x00007f0bd4d17000]
java.lang.Thread.State: BLOCKED (on object monitor)
at me.zks.jvm.troubleshoot.threadhump.LockAnalysics$ThreadWaitTo.funWaitTo(LockAnalysics.java:76)

- waiting to lock <0x00000000e2a78dc0> (a java.lang.Object)
at me.zks.jvm.troubleshoot.threadhump.LockAnalysics$ThreadWaitTo.run(LockAnalysics.java:70)
at java.lang.Thread.run(Thread.java:748)
“ThreadWaitOn” #9 prio=5 os_prio=0 tid=0x00007f0bd00ee000 nid=0x5525 in Object.wait() [0x00007f0bd4e18000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)

- waiting on <0x00000000e2a7eda8> (a java.lang.Object)
at java.lang.Object.wait(Object.java:502)
at me.zks.jvm.troubleshoot.threadhump.LockAnalysics$ThreadWaitOn.funWaitOn(LockAnalysics.java:59)
- locked <0x00000000e2a7eda8> (a java.lang.Object)
at me.zks.jvm.troubleshoot.threadhump.LockAnalysics$ThreadWaitOn.run(LockAnalysics.java:52)
at java.lang.Thread.run(Thread.java:748)
“ThreadLocked” #8 prio=5 os_prio=0 tid=0x00007f0bd00e5800 nid=0x5524 waiting on condition [0x00007f0bd4f19000]
java.lang.Thread.State: TIMED_WAITING (sleeping)
at java.lang.Thread.sleep(Native Method)
at me.zks.jvm.troubleshoot.threadhump.LockAnalysics$ThreadLocked.fun1(LockAnalysics.java:40)
at me.zks.jvm.troubleshoot.threadhump.LockAnalysics$ThreadLocked.run(LockAnalysics.java:34)

- locked <0x00000000e2a78dc0> (a java.lang.Object)
at java.lang.Thread.run(Thread.java:748)
“Service Thread” #7 daemon prio=9 os_prio=0 tid=0x00007f0bd00be800 nid=0x5522 runnable [0x0000000000000000]
java.lang.Thread.State: RUNNABLE

“C1 CompilerThread1” #6 daemon prio=9 os_prio=0 tid=0x00007f0bd00b1800 nid=0x5521 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE

“C2 CompilerThread0” #5 daemon prio=9 os_prio=0 tid=0x00007f0bd00af800 nid=0x5520 waiting on condition [0x0000000000000000]
java.lang.Thread.State: RUNNABLE

“Signal Dispatcher” #4 daemon prio=9 os_prio=0 tid=0x00007f0bd00ae000 nid=0x551f runnable [0x0000000000000000]
java.lang.Thread.State: RUNNABLE

“Finalizer” #3 daemon prio=8 os_prio=0 tid=0x00007f0bd007b000 nid=0x551e in Object.wait() [0x00007f0bd56ff000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)

- waiting on <0x00000000e2a08ed0> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:143)
- locked <0x00000000e2a08ed0> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:164)
at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:212)
“Reference Handler” #2 daemon prio=10 os_prio=0 tid=0x00007f0bd0076800 nid=0x551d in Object.wait() [0x00007f0bd5800000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)

- waiting on <0x00000000e2a06bf8> (a java.lang.ref.Reference$Lock)
at java.lang.Object.wait(Object.java:502)
at java.lang.ref.Reference.tryHandlePending(Reference.java:191)
- locked <0x00000000e2a06bf8> (a java.lang.ref.Reference$Lock)
at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:153)
“VM Thread” os_prio=0 tid=0x00007f0bd006f000 nid=0x551c runnable

“VM Periodic Task Thread” os_prio=0 tid=0x00007f0bd00c4000 nid=0x5523 waiting on condition

JNI global references: 5

先看一下 ThreadLocked 线程, 线程状态处于 TIMED_WAITING(sleep)，锁特征为waiting on condition。由这个堆栈可知该线程抢占了锁0x00000000e2a78dc0

“ThreadLocked” #8 prio=5 os_prio=0 tid=0x00007f0bd00e5800 nid=0x5524 waiting on condition [0x00007f0bd4f19000] //!! 锁特征为waiting on condition的
java.lang.Thread.State: TIMED_WAITING (sleeping) //线程状态是TIMED_WAITING(sleeping)
at java.lang.Thread.sleep(Native Method)
at me.zks.jvm.troubleshoot.threadhump.LockAnalysics$ThreadLocked.fun1(LockAnalysics.java:40)
at me.zks.jvm.troubleshoot.threadhump.LockAnalysics$ThreadLocked.run(LockAnalysics.java:34)

- locked <0x00000000e2a78dc0> (a java.lang.Object)  // 该线程占有了锁0x00000000e2a78dc0, 进入了同步代码块的方法
at java.lang.Thread.run(Thread.java:748)

再看一下 ThreadWaitTo 线程,可以发现线程状态为 BLOCKED，锁特征为 waiting for monitor entry, waiting to lock <0x00000000e2a78dc0> 说明锁 0x00000000e2a78dc0 被其他线程占用了，本线程正在等待抢占这把锁。

“ThreadWaitTo” #10 prio=5 os_prio=0 tid=0x00007f0bd00ef800 nid=0x5526 waiting for monitor entry [0x00007f0bd4d17000]
java.lang.Thread.State: BLOCKED (on object monitor)
at me.zks.jvm.troubleshoot.threadhump.LockAnalysics$ThreadWaitTo.funWaitTo(LockAnalysics.java:76)

- waiting to lock <0x00000000e2a78dc0> (a java.lang.Object)
at me.zks.jvm.troubleshoot.threadhump.LockAnalysics$ThreadWaitTo.run(LockAnalysics.java:70)
at java.lang.Thread.run(Thread.java:748)

看一下 ThreadWaitOn 线程, 线程处于 WAITING 状态，锁特征为 Object.wait()，其中 waiting on <0x00000000e2a7eda8> 会释放自己锁定的锁 0x00000000e2a7eda8，其他线程可以占有这把锁，并且自己处于等待唤醒的状态

“ThreadWaitOn” #9 prio=5 os_prio=0 tid=0x00007f0bd00ee000 nid=0x5525 in Object.wait() [0x00007f0bd4e18000]
java.lang.Thread.State: WAITING (on object monitor)
at java.lang.Object.wait(Native Method)

- waiting on <0x00000000e2a7eda8> (a java.lang.Object) //此时wait方法会导致该锁被释放,其它线程又可以占有该锁
at java.lang.Object.wait(Object.java:502)
at me.zks.jvm.troubleshoot.threadhump.LockAnalysics$ThreadWaitOn.funWaitOn(LockAnalysics.java:59)
- locked <0x00000000e2a7eda8> (a java.lang.Object)
at me.zks.jvm.troubleshoot.threadhump.LockAnalysics$ThreadWaitOn.run(LockAnalysics.java:52)
at java.lang.Thread.run(Thread.java:748)

通过上面这个例子，我们看到了有locked,waiting to lock,waiting on 这三个锁特征

locked 表示已经占有了锁
waiting to lock 表示这把锁目前还没抢到（可能别别的线程抢占了），正在等待这把锁
waiting on 表示线程处于 Object.lock()状态，已经释放了锁，其他线程可以占用这把锁，同事本线程等待被唤醒.

线程状态的解读

从上面的例子中，我们看到了线程状态有BLOCKED,WAITING,TIMED_WAITING。实际上线程状态有如下几种

线程状态

新建状态（New）：新创建了一个线程对象。
就绪状态（Runnable）：线程对象创建后，其他线程调用了该对象的 start() 方法。该状态的线程位于可运行线程池中，变得可运行，等待获取 CPU 的使用权。
运行状态（Running）：就绪状态的线程获取了 CPU，执行程序代码。
阻塞状态（Blocked）：阻塞状态是线程因为某种原因放弃 CPU 使用权，暂时停止运行。直到线
程进入就绪状态，才有机会转到运行状态。
死亡状态（Dead）：线程执行完了或者因异常退出了run()方法，该线程结束生命周期。

阻塞的情况分三种：
（一）、WAITING (on object monitor) 等待阻塞：运行的线程执行 wait() 方法，JVM会把该线程放入等待池中。
（二）、BLOCKED (on object monitor) 同步阻塞：运行的线程在获取对象的同步锁时，若该同步锁被别的线程占用，则 JVM 会把该线程放入锁池中。区分同步阻塞和等待阻塞也可以看锁的特征，例如同步阻塞锁的特征是 waiting for monitor, 等待阻塞锁的特征是 object.wait()
（三）、TIMED_WAITING(sleeping) 其他阻塞：运行的线程执行 sleep() 或 join() 方法，或者发出了 I/O 请求时，JVM会把该线程置为阻塞状态。当 sleep() 状态超时、join() 等待线程终止或者超时、或者 I/O 处理完毕时，线程重新转入就绪状态。

实际上我们 jvm 线程栈中，几乎是不会出现 NEW,RUNNING,DEAD 这些状态，其中 Runnable 就算是正在运行了

处于WAITING, BLOCKED, TIME_WAITING 的是不消耗 CPU 的，处于 Runnable 状态的线程，是否消耗 cpu 要看具体的上下文情况

如果是纯Java运算代码，则消耗CPU.
如果是网络IO,很少消耗CPU,这点在分布式程序中经常碰到
如果是本地代码，结合本地代码的性质判断(可以通过 pstack/gstack 获取本地线程堆栈)，如果是纯运算代码，则消耗CPU, 如果被挂起，则不消耗CPU,如果是 IO,则不怎么消耗 CPU

线程死锁

死锁比较少见，而且难于调试：

所谓死锁：是指两个或两个以上的进程在执行过程中，由于竞争资源或者由于彼此通信而造成的一种阻塞的现象，若无外力作用，它们都将无法推进下去。此时称系统处于死锁状态或系统产生了死锁，这些永远在互相等待的进程称为死锁进程。

其实很久之前学习数字电路，经常会遇到一些锁，这也是自动化的一些常见的问题，在计算机中，也有类似的东西，请看下图

R1 和 R2，都只能被一个进程使用
T1 在使用 R1，同时没有使用完 R1 的情况下，想使用 R2
T2 在使用 R2，同时在没有使用完 R2 的情况下，想使用 R1

这时，T1 等待 T2 放弃使用 R2，同时 T2 等待 T1 放弃使用 R1，他们都不会放弃自己所使用的，于是产生了等待，将会一直僵持下去。

代码如下

package me.zks.jvm.troubleshoot.threadhump;

public class DeadLock implements Runnable{
private int flag = 1;
// 两个static的对象，静态变量
public static Object obj1=new Object();
public static Object obj2=new Object();
@Override
public void run() {
System.out.println(“flag=”+flag);
if(flag==1){
fun1();
}
if(flag==0){
fun2();
}
}

private void fun1() {
    synchronized (obj1){
        System.out.println("我已经锁定了obj1,休息0.5秒后再锁定obj2,但是估计进不了obj2，因为obj2估计也被锁定了");
        try {
            Thread.sleep(500);
        } catch (InterruptedException e) {
            e.printStackTrace();
        }
        synchronized (obj2){
            System.out.println("进入了obj2");
        }
    }
}
private void fun2() {
    synchronized (obj2){
        System.out.println("我已经锁定了obj2,休息0.5秒后再锁定obj1,但是估计进不了obj1，因为obj1估计也被锁定了");
        try {
            Thread.sleep(500);
        } catch (InterruptedException e) {
            e.printStackTrace();
        }
        synchronized (obj1){
            System.out.println("进入了obj1");
        }
    }
}

public static void main(String[] args) {
    DeadLock deadLock1 = new DeadLock();
    DeadLock deadLock2 = new DeadLock();
    deadLock1.flag=1;
    deadLock2.flag=0;
    System.out.println("线程开始了");
    new Thread(deadLock1).start();
    new Thread(deadLock2).start();

}
}

运行后显示

线程开始了
flag=1
我已经锁定了obj1,休息0.5秒后再锁定obj2,但是估计进不了obj2，因为obj2估计也被锁定了
flag=0
我已经锁定了obj2,休息0.5秒后再锁定obj1,但是估计进不了obj1，因为obj1估计也被锁定了

jstack 显示(删除了一些信息，只留了用户线程的)

Found one Java-level deadlock:
“Thread-1”:
waiting to lock monitor 0x00007f37680062c8 (object 0x00000000e2a794f8, a java.lang.Object),
which is held by “Thread-0”
“Thread-0”:
waiting to lock monitor 0x00007f3768004e28 (object 0x00000000e2a79508, a java.lang.Object),
which is held by “Thread-1”

Java stack information for the threads listed above:
“Thread-1”:
at me.zks.jvm.troubleshoot.threadhump.DeadLock.fun2(DeadLock.java:41)

- waiting to lock <0x00000000e2a794f8> (a java.lang.Object)
- locked <0x00000000e2a79508> (a java.lang.Object)
at me.zks.jvm.troubleshoot.threadhump.DeadLock.run(DeadLock.java:15)
at java.lang.Thread.run(Thread.java:748)
“Thread-0”:
at me.zks.jvm.troubleshoot.threadhump.DeadLock.fun1(DeadLock.java:28)

- waiting to lock <0x00000000e2a79508> (a java.lang.Object)
- locked <0x00000000e2a794f8> (a java.lang.Object)
at me.zks.jvm.troubleshoot.threadhump.DeadLock.run(DeadLock.java:12)
at java.lang.Thread.run(Thread.java:748)
Found 1 deadlock.

从线程中我们可以看到 Found one Java-level deadlock:

这就说明进入了死锁，分析 Thread-1 和 Thread-2
Thread-1锁定了0x00000000e2a79508, waiting to lock 0x00000000e2a794f8
Thread-0锁定了0x00000000e2a794f8, waiting to lock 0x00000000e2a79508，于是这两个线程就进入了死锁。

如果通过这种方式发现了死锁，那没办法，只有该代码了，将并发做的更安全点才是王道。

大数据中死循环或者复杂度高的方法判断

首先，如果是进入了死循环，程序肯定是在某个方法直接卡死，我们将线程堆栈分析下来，多分析几次，比如 20 秒一次（具体情况而定），如果多次都在同一个方法栈的调用，但是根据我们得预估，这个代码并不需要这么多的时间，并且这个方法的线程占用的cpu很高(前面提到的 TOP -Hp pid , 然后根据这个方法的 nid 转成 10 进制就可以找到对应的线程)，那么我们就怀疑是这个 cpu 高引起的问题了。

这时候就需要分析代码了。

需要注意的是,我们分析还是要根据代码客观的时间来分析，特别是在 spark 等大数据处理中，有的方法是需要很久的时间，合理的判断，找出死循环或者复杂度高的方法，然后再对代码进行修改。

IO或者网络问题

有时候，大数据在shuffle过程中，或者web程序在传输数据过程中，可能会由于网络等问题，导致程序会很慢，这个分析方法也同样是通过看线程堆栈，查看到是java.io.，或者java.nio等问题，那就可能就是网络问题了，网络问题可以参考使用iotop 和iostat 来进行分析

连接数瓶颈问题

有时候，linux 机器的频繁连接，同时连接数过多，或者 IO 的频繁打开而不关闭，连接数过多，又或者是 socketRead 的并发太多，就容易发生连接数瓶颈问题。

最比较常见的就是在 web 做压力测试（例如 ab test ），再并发数一多的时候，就容易发现瓶颈，像 mysql 有类似于 MYTOP 的工具，同样，我们也可以通过jstack获取方法栈来进行，例如下面这个例子

代码参考自《java 问题定位技术》

“Thread-248” prio=1 tid=0xa58f2048 nid=0x7ac2 runnable
[0xaeedb000..0xaeedc480]
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.read(SocketInputStream.java:129)
at oracle.net.ns.Packet.receive(Unknown Source)
… …
at oracle.jdbc.driver.LongRawAccessor.getBytes()
“Thread-429” prio=1 tid=0xa58f2048 nid=0x7ac2 runnable
[0xaeedb000..0xaeedc480]
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.read(SocketInputStream.java:129)
at oracle.net.ns.Packet.receive(Unknown Source)
… …
at oracle.jdbc.driver.LongRawAccessor.getBytes()
“Thread-250” prio=1 tid=0xa58f2048 nid=0x7ac2 runnable
[0xaeedb000..0xaeedc480]
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.read(SocketInputStream.java:129)
at oracle.net.ns.Packet.receive(Unknown Source)
…
at oracle.jdbc.driver.LongRawAccessor.getBytes()
…

假如有太多的这类线程，那么就可以得出是 jdbc 访问过多，这时候就要优化资源和优化程序了。

频繁GC导致的cpu速度慢的问题

下回讲解，内存堆栈分析。

参考文献：

HotSpotVM故障排除指南

注：本文转载自挡路人-java线上程序排错经验2 - 线程堆栈分析

posted @ 2019-04-27 20:37 Michael翔阅读(951) 评论(0) 编辑收藏举报

刷新页面返回顶部

Michael翔

公众号『Coder魔法院』，效率软件控，欢迎关注！因上努力，果上随缘，做好自己！

【转】java线上程序排错经验2 - 线程堆栈分析

前言

什么是线程堆栈

如何分析

线程锁分析

线程状态的解读

线程死锁

大数据中死循环或者复杂度高的方法判断

IO或者网络问题

连接数瓶颈问题

频繁GC导致的cpu速度慢的问题

参考文献：

公告

Michael翔

公众号『Coder魔法院』，效率软件控，欢迎关注！ 因上努力，果上随缘，做好自己！

【转】java线上程序排错经验2 - 线程堆栈分析

前言

什么是线程堆栈

如何分析

线程锁分析

线程状态的解读

线程死锁

大数据中死循环或者复杂度高的方法判断

IO或者网络问题

连接数瓶颈问题

频繁GC导致的cpu速度慢的问题

参考文献：

公告

公众号『Coder魔法院』，效率软件控，欢迎关注！因上努力，果上随缘，做好自己！