Java线上故障排查手段

发表于2019-03-08更新于2022-04-27阅读次数

高CPU负载

1、找出最消耗CPU的进程号，执行以下命令

1
top -c #显示进程运行信息列表

键入大写的P，让进程按照CPU使用率排序
top-c

在这里可以通过工具*show-busy-java-threads*，直接定位到问题代码，不需要执行后面的步骤2-4。
使用方式如下：

1
./show-busy-java-threads -p 3303

2、找出最消耗CPU的线程，执行以下命令

1
top -H -p 3303  #显示一个进程的线程运行信息列表

这时也可以键入大写的P，让进程按照CPU使用率排序
top-h-p.png

3、将线程转化为16进制。之所以要转化为16进制，是因为堆栈里，线程id是用16进制表示的

1
printf "%x\n" 3313

printf3303.png
4、定位问题代码
(1)、在线查看

1
jstack -l 3303 | grep -C 20 nid=0xcf1 --color=auto  #-l 输出锁的附加信息

(2)、导出文件查看

1
jstack -l 3303 | more > threadStack20190308.log

jstack3003

参数介绍
prio：线程的优先级
tid：线程id
nid:操作系统映射的线程id

5、 分析线程状态
jstack日志中的线程状态有：

  • RUNNABLE: 线程正在执行中，占用了资源，比如处理某个请求/进行计算/文件操作等

  • BLOCKED:线程处于阻塞状态，等待某种资源(可理解为等待资源超时的线程)；
    具体状态有：

          1、 "waiting to lock <xxx>"：即等待给xxx上锁，<b>grep stack文件找locked <xxx></b> 查找获得锁的线程；

      2、 "waiting for monitor entry"：线程通过synchronized(obj){……}申请进入了临界区，但该obj对应的monitor被其他线程拥有，从而处于等待。

  • WAITING(parking)/TIMED_WAITING:等待状态，若指定了时间，到达指定的时间后自动退出等待状态，parking指线程处于挂起中；具体状态有：

          - "waiting on condition"需与堆栈中的"parking to wait for  <xxx> (at java.util.concurrent.SynchronousQueue$TransferStack)"结合来看。（1）、此线程是在等待某个条件的发生，来把自己唤醒；（2）、SynchronousQueue不是一个队列，其是线程之间移交信息的机制，当我们把一个元素放入到 SynchronousQueue 中时必须有另一个线程正在等待接受移交的任务，因此这就是本线程在等待的条件。

  • Deadlock:死锁，资源相互占用。

对上述各种状态的具体描述如下：

  • 线程状态为“waiting for monitor entry” 意味着它在等待进入一个临界区 ，所以它在”Entry Set“队列中等待。 此时线程状态一般都是Blocked：java.lang.Thread.State: BLOCKED (on object monitor)。

如果大量线程在“waiting for monitor entry”可能是一个全局锁阻塞住了大量线程。如果短时间内打印的 thread dump 文件反映，随着时间流逝，”waiting for monitor entry”的线程越来越多，没有减少的趋势，可能意味着某些线程在临界区里呆的时间太长了，以至于越来越多新线程迟迟无法进入临界区。

  • 线程状态为“waiting on condition”说明它在等待另一个条件的发生，来把自己唤醒，或者干脆它是调用了 sleep(N)。
    此时线程状态大致为以下几种：(1)、java.lang.Thread.State: WAITING (parking)：一直等那个条件发生；（2）、 java.lang.Thread.State: TIMED_WAITING (parking或sleeping)：定时的，那个条件不到来，也将定时唤醒自己。

如果大量线程在“waiting on condition” 可能是它们又跑去获取第三方资源，尤其是第三方网络资源，迟迟获取不到Response，导致大量线程进入等待状态。
所以如果你发现有大量的线程都处在”Wait on condition”，从线程堆栈看，正等待网络读写，这可能是一个网络瓶颈的征兆，因为网络阻塞导致线程无法执行。

  • 线程状态为“in Object.wait()” 说明它获得了监视器之后，又调用了 java.lang.Object.wait() 方法。每个 Monitor在某个时刻，只能被一个线程拥有，该线程就是 “Active Thread”。而其它线程都是 “Waiting Thread”，分别在两个队列 “ Entry Set”和 “Wait Set”里面等候。在 “Entry Set”中等待的线程状态是 “Waiting for monitor entry”，而在 “Wait Set”中等待的线程状态是 “in Object.wait()”。当线程获得了 Monitor，如果发现线程继续运行的条件没有满足，它则调用对象（一般就是被 synchronized 的对象）的 wait() 方法，放弃了 Monitor，进入 “Wait Set”队列。此时线程状态大致为以下几种：（1）、java.lang.Thread.State: TIMED_WAITING (on object monitor)；（2）、java.lang.Thread.State: WAITING (on object monitor)；一般都是RMI相关线程（RMI RenewClean、 GC Daemon、RMI Reaper），GC线程（Finalizer），引用对象垃圾回收线程（Reference Handler）等系统线程处于这种状态。

可以使用类似如下命令，查看对应状态的线程情况

1
2
jstack -l pid |grep "BLOCKED"|wc -l
jstack -l pid |grep "Waiting on condition"|wc -l

Monitor
在多线程的 JAVA程序中，实现线程之间的同步，就要说说 Monitor。 Monitor是Java中用以实现线程之间的互斥与协作的主要手段，它可以看成是对象或者Class的锁。每一个对象都有，也仅有一个 monitor。下 面这个图，描述了线程和 Monitor之间关系，以 及线程的状态转换图：
thread

  • 进入区(Entry Set)：表示线程通过synchronized要求获取对象的锁。如果对象未被锁住，则进入拥有者;否则在进入区等待。一旦对象锁被其他线程释放，立即参与竞争。
  • 拥有者(The Owner)：表示某一线程成功竞争到对象锁。
  • 等待区(Wait Set)：表示线程通过对象的wait方法，释放对象的锁，并在等待区等待被唤醒。

从图中可以看出，一个 Monitor在某个时刻，只能被一个线程拥有，该线程就是 “Active Thread”，而其它线程都是 “Waiting Thread”，分别在两个队列 “ Entry Set”和 “Wait Set”里面等候。在 “Entry Set”中等待的线程状态是 “Waiting for monitor entry”，而在“Wait Set”中等待的线程状态是 “in Object.wait()”。 先看 “Entry Set”里面的线程。我们称被 synchronized保护起来的代码段为临界区。当一个线程申请进入临界区时，它就进入了 “Entry Set”队列。

locked <地址> 目标：使用synchronized申请对象锁成功，监视器的拥有者。
waiting to lock <地址> 目标：使用synchronized申请对象锁未成功，在进入区等待。
waiting on <地址> 目标：使用synchronized申请对象锁成功后，释放锁在等待区等待。

高CPU IO Wait

1、找到高IO Wait的进程

1
iotop -P    #该工具需要安装

iotop

2、找到写入量大的线程信息

1
iotop

iotop

从command 已经可以看到进程信息了，部分情况下可以直接看到进程名称，将24841和24854对应起来。
3、将线程24854转化为16进制。之所以要转化为16进制，是因为堆栈里，线程id是用16进制表示的

1
printf "%x\n" 24854

iotopprintf
4、定位问题代码
(1)、在线查看

1
jstack -l 24841 | grep -C 20 nid=0x6116 --color=auto  #-l 输出锁的附加信息

(2)、导出文件查看

1
jstack -l 24841 | more > threadStack20190308.log

iotop-jstack

频繁GC和堆内存out of memory

第一种方式：
1、利用jps或ps查看程序的进程ID，如25585
2、结合GC情况，确认本身的内存分配是不是过小。如果是old区增长的过快，就可能是内存泄露。这个时候，你需要看看到底是什么对象占用了你的内存。

1
2
jstat -gcutil 25585 5000 10# 查看垃圾回收情况，每5秒打印1次，一共打印10次
jmap -heap 25585 #查看当前堆内存情况

3、可以通过以下参数调大堆内存

1
-Xms5000m –Xmx5000m

第二种方式：

1、对Java进行如下的配置，可打印出发生out of memory时的堆内存清况

1
2
- XX:+PrintGC -XX:+PrintGCDateStamps -Xloggc:/home/gc20190318.log -XX:+UseGCLogFileRotation 
- XX:NumberOfGCLogFiles=10 -XX:GCLogFileSize=50m -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/home/dump20190318.hprof

2、利用jps或ps查看程序的进程ID，如25585
3、利用下面命令，生成堆内存转储文件dump20190318.hprof，结合MAT工具进行分析，找出最消耗内存的对象

1
kill -3 25585

第三种方式：
1、用jps或ps查看程序的进程ID，如25585
2、利用下面命令，找出最消耗内存的对象

1
jmap -histo:live 25585 | more

第四种方式：
1、用jps或ps查看程序的进程ID，如25585
2、利用下面命令，生成堆内存转储文件dump20190318.hprof，结合MAT工具，找出最消耗内存的对象

1
jmap -dump:live，format=b，file=/home/dump20190318.hprof 25585

参考资料