【转】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 显示如下

[email protected]:~$ jps
27831 Jps
27819 FirstSample
[email protected]:~$

输入 jps -mlv显示如下

[email protected]:~$ jps -mlv
27874 sun.tools.jps.Jps -mlv -Dapplication.home=/usr/lib/jvm/java-8-oracle -Xms8m
27819 me.zks.jvm.troubleshoot.threadhump.FirstSample
[email protected]:~$

jstack 27819 显示如下

[email protected]:~$ 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 我也不知道
  • 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

!

线程锁分析

jps

[email protected]:~$ jps
21786 LockAnalysics
21804 Jps

jstack

[email protected]:~$ 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。 实际上线程状态有如下几种

  1. 新建状态（New）：新创建了一个线程对象。
  2. 就绪状态（Runnable）：线程对象创建后，其他线程调用了该对象的 start() 方法。该状态的线程位于可运行线程池中，变得可运行，等待获取 CPU 的使用权。
  3. 运行状态（Running）：就绪状态的线程获取了 CPU，执行程序代码。
  4. 阻塞状态（Blocked）：阻塞状态是线程因为某种原因放弃 CPU 使用权，暂时停止运行。直到线
    程进入就绪状态，才有机会转到运行状态。
  5. 死亡状态（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速度慢的问题

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

参考文献：

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

原文地址：https://www.cnblogs.com/michael-xiang/p/10780213.html

时间： 2024-10-22 20:33:13

【转】java线上程序排错经验2 - 线程堆栈分析的相关文章

java线上服务问题排查

1.业务日志相关 如果系统出现异常或者业务有异常,首先想到的都是查看业务日志 查看日志工具: less 或者more grep tail -f filename 查看实时的最新内容 ps:切忌vim直接打开大日志文件,因为会直接加载到内存的 2.数据库相关 java应用很多瓶颈在数据库,一条sql没写好导致慢查询,可能就会带来应用带来致命危害. 如果出现Could not get JDBC Connection .接口响应慢.线程打满等, 需要登录线上库, 查看数据库连接情况:show proc

java线上问题调试

线上出现问题,如oom等问题,可以将堆hprof文件使用java VisualVM打开堆文件 可以看到最多的对象是char数组,可以看出来 从这些对象中可以看到相应的信息,根据这些信息查看相应的问题 原文地址:https://www.cnblogs.com/zhangchiblog/p/9319921.html

复现一个典型的线上Spring Bean对象的线程安全问题（附三种解决办法）

问题复现 假设线上是一个典型的Spring Boot Web项目,某一块业务的处理逻辑为: 接受一个name字符串参数,然后将该值赋予给一个注入的bean对象,修改bean对象的name属性后再返回,期间我们用了 Thread.sleep(300) 来模拟线上的高耗时业务 代码如下: @RestController @RequestMapping("name") public class NameController { @Autowired private NameService n

java 线上问题定位工具

在JDK的bin目录下有很多命令行工具: 我们可以看到各个工具的体积基本上都稳定在27kb左右,这个不是JDK开发团队刻意为之的,而是因为这些工具大多数是jdk\lib\tools.jar类库的一层薄包装而已,他们的主要功能代码是在tools类库中实现的.命令行工具的好处是:当应用程序部署到生产环境后,无论是直接接触物理服务器还是远程telnet到服务器上都会受到限制.而借助tools.jar类库里面的接口,我们可以直接在应用程序中实现功能强大的监控分析功能. 常用命令: 这次我主要介绍如下的一

Java线上应用故障排查之一：高CPU占用

一个应用占用CPU很高,除了确实是计算密集型应用之外,通常原因都是出现了死循环. (友情提示:本博文章欢迎转载,但请注明出处:hankchen,http://www.blogjava.net/hankchen) 以我们最近出现的一个实际故障为例,介绍怎么定位和解决这类问题. 根据top命令,发现PID为28555的Java进程占用CPU高达200%,出现故障. 通过ps aux | grep PID命令,可以进一步确定是tomcat进程出现了问题.但是,怎么定位到具体线程或者代码呢? 首先显示线

Java线上应用故障之CPU占用高排查与定位

最近线上频繁报警CPU空闲不足,故紧急排查后分享给大家 1.使用top命令,获取占用CPU最高的进程号 2.查看线程号对应的进程信息 命令:ps -ef|grep 22630 3.查看进程对应的线程信息 命令:ps -mp22630-oTHREAD,tid,time | sort -nr| head -15 4.选取第一个线程号,转换成16进制 命令:printf "%x" 22657 结果:5881 5.使用jstack查询出具体的线程状态 命令:jstack 22630|grep

Redis持久化磁盘IO方式及其带来的问题 　　有Redis线上运维经验的人会发现Redis在物理内存使用比较多，但还没有超过实际物理内存总容量时就会发生不稳定甚至崩溃的问题，有人认为是基于快照方式持

转自:http://blog.csdn.net/kaosini/article/details/9176961 一.对Redis持久化的探讨与理解 redis是一个支持持久化的内存数据库,也就是说redis需要经常将内存中的数据同步到磁盘来保证持久化.redis支持两种持久化方式,一种是 Snapshot(RDB)也是默认方式,另一种是Append only file(AOF)的方式.具体的理论说明请见这里. 我们应该明确持久化的数据有什么用,答案是用于重启后的数据恢复.Redis是一个内存数据

关于Java中的程序，进程和线程的详解...

程序:一段静态的代码,一组指令的有序集合,它本身没有任何运行的含义,它只是一个静态的实体,是应用软件执行的蓝本. 进程:是程序的一次动态执行,它对应着从代码加载,执行至执行完毕的一个完整的过程,是一个动态的实体,它有自己的生命 周期.它因创建而产生,因调度而运行,因等待资源或事件而被处于等待状态,因完成任务而被撤消.反映了一个程序在 一定的数据 集上运行的全部动态过程.通过进程控制块(PCB)唯一的标识某个进程.同时进程占据着相应的资源(例如包 括cpu的使用 ,轮转时间以及一些其它设备的权限)

java线：辛格尔顿隐藏ThreadLocal实现线程数据共享

效果图分享: A和B需要共享同一线程,还有一组的相同A和B共享还有一组线程,两组相互之间不受影响. 代码: package cn.itcast.lesson6; import java.util.Random; public class ThreadLocalTest { public static void main(String[] args) { for(int i=0;i<2;i++){ new Thread(new Runnable() { public void run() { in