排查Java程序

备注

虽然我不懂Java开发，但是运维工作中还是会遇到一些Java程序运行异常问题需要排查，例如CPU过高，负载过高等。对于Java程序简单排查可以方便我们定位问题。

Java程序和线程

Java程序有时候会出现挂起和运行缓慢的问题，通过线程dump可以提供一个当前运行的java集成的状态快照，方便进行分析诊断。这种方式简单有效，经常能够发现一些线索以及简单的错误。

Java使用线程来执行每个内部和外部操作。Java的垃圾搜集进程有自己的线程，Java应用程序内部的任务也会创建自己的线程。

在Java程序的生命周期中，线程会经历多种状态。每个线程都有一个跟踪当前操作的执行堆栈。此外，JVM还存储了之前调用成功的所有方法。因此，分析完整的堆栈可以帮助我们研究出现问题时应用程序发生了什么。

../_images/Life_cycle_of_a_Thread_in_Java.jpg

Java线程生命周期

Java线程生命周期

状态

说明

NEW

一个新创建的线程，还没有开始执行

RUNNABLE

正在运行或准备执行但正在等待资源分配

BLOCKED

待获取监视器锁(monitor lock)以进入或重新进入 同步块(synchronized block)/方法(method)

WAITING

等待其他线程执行特定操作，没有任何时间限制

TIMED_WAITING

等待其他线程在指定时间段内执行特定操作

TERMINATED

已完成执行

获取Java程序线程dump

一旦Java程序开始运行，有多种方式来生成Java线程dump用于分析诊断:

  • JVM Process Status(jps)

  • jstack

  • 首先使用 top 命令检查系统中运行的Java程序，找出进程 PID ; 也可以使用 jps 命令找出Java进程PID:

使用 jps 命令输出运行的java进程PID
jps

输出类似:

使用 jps 命令输出运行的java进程PID
1856 CELauncher   <= 这个1856就是java程序的PID，也可以使用top命令看到
279040 Jps

  • 记录下Java进程的所有LWP线程:

使用 ps 命令输出运行的java进程线程
ps -eLo pid,lwp<Plug>PeepOpencpu,vsz,comm | grep 1856 > OS_LWP

执行 cat OS_LWP | sort -k3 可以看到按线程CPU繁忙程度排序的结果:

按CPU繁忙程度排序java线程
...
  1856 399987  0.9 7088060 java
  1856   2479  1.0 7088060 java
  1856 523238  1.1 7088060 java
  1856 523239  1.1 7088060 java
  1856 523240  1.1 7088060 java
  1856 523242  1.1 7088060 java
  1856 523243  1.1 7088060 java
  1856 399963  1.2 7088060 java
  1856 399964  1.2 7088060 java
  1856 399973  1.2 7088060 java
  1856 399974  1.2 7088060 java
  1856 399975  1.2 7088060 java
  1856 399976  1.2 7088060 java
  1856 399977  1.2 7088060 java
  1856 399986  1.2 7088060 java
  1856 399989  1.2 7088060 java
  1856 399993  1.2 7088060 java
  1856 399994  1.2 7088060 java
  1856 399997  1.2 7088060 java
  1856 400000  1.2 7088060 java
  1856 400001  1.2 7088060 java
  1856 400003  1.2 7088060 java
  1856   2223  1.6 7088060 java

备注

在 jstack 中记录的线程 nid 是十六进制，所以这里 OS_LWP 的PID需要从十进制转换成十六进制来对应

  • 执行 jstack 命令获取Java线程堆栈:

jstack命令输出java进程PID的堆栈
jstack -l 1856 > jstack.txt

获得 jstack.txt 进行下一步分析

分析java线程dump

  • 在 jstack.txt 的前面部分可能有类似如下内容，显示了JVM版本以及 Safe Memory Reclamation (SMR) 和 non-JVM internal threads:

    2021-01-04 12:59:29
Full thread dump OpenJDK 64-Bit Server VM (15.0.1+9-18 mixed mode, sharing):

Threads class SMR info:
_java_thread_list=0x00007fd7a7a12cd0, length=13, elements={
0x00007fd7aa808200, 0x00007fd7a7012c00, 0x00007fd7aa809800, 0x00007fd7a6009200,
0x00007fd7ac008200, 0x00007fd7a6830c00, 0x00007fd7ab00a400, 0x00007fd7aa847800,
0x00007fd7a6896200, 0x00007fd7a60c6800, 0x00007fd7a8858c00, 0x00007fd7ad054c00,
0x00007fd7a7018800

}

  • 然后是完整的线程列表dump，包含了以下信息:

Java线程dump ( jstack )输出内容字段说明

字段

说明

Name

如果开发者对线程起了有意义的名字，可能提供一些有用信息

Priority 优先级 ( prio )

线程的优先级

Java ID ( tid )

JVM的标识ID

Native ID 原生ID ( nid )

操作系统的标识ID，也就是PID，十六进制

State 状态

线程的 实际状态 (actual state)

Stack trace

描述应用程序的重要信息

分析关注点

  • 在 jstack.txt 最后显示 Java 本机接口(JNI)引用。当发生内存泄漏时，需要特别关注，因为它们不会被自动垃圾回收:

    JNI global refs: 15, weak refs: 0

  • 重点关注 RUNNABLE 和 BLOCKED 线程，以及 TIMED_WAITING 线程:

    • 这些状态会提示我们两个或多个线程之间发生冲突的方向

    • 在死锁情况下，多个线程运行在共享对象上持有一个同步块 ( In a deadlock situation in which several threads running hold a synchronized block on a shared object )

    • 在线程争用时，一个线程会阻塞等待其他线程完成 ( In thread contention, when a thread is blocked waiting for others to finish )

  • 对于异常高的CPU使用率，通常我们只需要查看 RUNNABLE 线程

    • 除了 jstack 获取线程dump，还有一个常用命令是 top -H -p PID ，可以显示哪些线程正在消耗特定进程中的操作系统资源

    • 此外建议查看 jstack 输出中内部JVM线程，例如 GC

  • 当Java程序处理性能 异常低 时，应该检查 BLOCKED 线程

  • 一些间歇性的性能问题，需要间隔很近的多次 jstack 获取线程堆栈，以便进行对比

    • 推荐的最佳做法是 至少进行3次 jstack dump ，每 10秒 一次

  • 建议在Java代码中对创建新线程使用命名以便在排查时能够定位源代码

  • 忽略内部JVM处理(例如GC)

  • 当出现异常的CPU或内存使用情况，应该关注长时间运行或阻塞的线程

  • 使用 top -H -p PID 来检查线程堆栈和CPU处理的关系

在线分析工具

分析工具

参考