Java线上性能问题-排查方法汇总

引言

作为一名从事Java开发的程序员，在线上经常碰到某个模块的Pod发出CPU与内存告警的问题，而这些问题会导致系统响应缓慢甚至是服务不可用。一般情况下可以通过 重启 或者 调高Pod的资源量或者增加Pod数量暂时解决问题，但这是治标不治本的，只有找到问题发生的原因才能从根本上解决问题。那么在该如何快速定位到导致告警的原因呢？下面将汇总一下大致的处理思路。

一般来说导致Java程序CPU与内存冲高的原因主要有以下几种场景：

• 代码中某个位置读取数据量较大，导致系统内存耗尽，从而导致Full GC次数过多，系统缓慢。
• 代码中某个功能，存在死循环或循环产生过多重复的对象实体(因外界数据错误引起的)，集合类中有对对象的引用，使用完后未清空，使得JVM不能回收。导致系统内存耗尽，从而导致Full GC次数过多，系统缓慢。
• 代码中有比较耗CPU的操作(如：算法)，导致CPU过高，系统运行缓慢。
• 代码中某个位置 有阻塞性的操作，导致该功能调用整体比较耗时，但出现是比较随机的。
• 某个线程由于某种原因而 进入WAITING状态 ，此时该功能整体不可用，但是无法复现。
• 由于锁使用不当 ，导致多个线程进入死锁状态，从而导致系统整体比较缓慢。

前三种情况出现的频率较高，可能会导致系统不可用。

后三种只会导致某个功能运行缓慢，但是不至于导致系统不可用。

一、分析工具

会特别写明，window环境和linux环境的区别。

公司项目是有的是部署在window环境，有的是部署在linux环境

说明：进程ID 简称为PID，命令中的统一使用PID来表示进程ID

1.1、top命令查看CPU占用情况

此命令只用于linux环境，没有可视化，只能通过命令查看。

而window环境，直接启动任务管理器，点击[进程]，就非常直观的看出哪个进程占用cpu最高了。因此，若是window环境，此步可以省略。

说明：先讲命令的使用，具体操作截图在下面的案例中。

• top 查看系统进程CPU与内存占用情况，找到占用最多的进程ID
• top -n num 查看CPU占用最高的num个进程
• top -Hp PID 或 top -H -p PID查看该进程号的所有线程CPU与内存占用情况，找到占用最多的线程ID

1.2、jstack命令查看Java线程信息

window环境，可以使用jps查看java对应的进程ID。但是，不能查看线程ID。因此，无法在线查看堆栈信息，只能将堆栈信息输出到文件中。

jstack 表示生成 Java 虚拟机当前时刻的线程快照
-l 表示长列表（long）
-C10 表示显示关键字所在行前后10行
--color 表示带颜色显示关键字pid

• jps -l 显示当前所有 Java 进程ID 的命令 （window环境和linux环境）

• printf '%x\n' PID 或 printf %x PID表示将线程ID 转换为十六进制，用于搜索线程堆栈中的关键信息 （linux环境）

• jstack PID | grep 线程ID 查看线程堆栈信息 （linux环境）

• jstack PID | grep -C10 线程ID --color 查看线程堆栈信息 （linux环境）

• jstack -l PID 查看线程堆栈信息

• jstack PID >> stack.txt 将当前所有堆栈信息输出到stack.txt文件中

如果是 VM Thread这就是虚拟机GC回收线程
如果是 main则是其他线程，后面的runnable是线程状态。

1.3、jstat命令查看GC信息

如果发现返回中FGC很大且一直增大，确认为Full GC! 也可以使用 jmap -heap PID查看一下进程的堆内存是不是要溢出了，特别是老年代内存使用情况一般是达到阈值(具体看垃圾回收器和启动时配置的阈值)就会进程Full GC。

如果发现老年代都占用100%了，是频繁的full gc 导致的。而且full gc 都无法降低老年代的内存。

• jstat -gcutil PID 1000 2 或 jstat -gc PID 1000 2 表示进程ID每间隔1000毫秒统计2次（缺省代表一直统计），查看某进程GC持续变化情况

参数解释：

gcutil 的意思是[已使用空间]占[总空间]的百分比。

查询结果表明：

新生代Eden区（E，表示Eden）使用了65.33%（最后）的空间

两个Survivor区（S0、S1，表示Survivor0、Survivor1）分别是0和94.27%

老年代（O，表示Old）使用了63.80%

程序运行以来共发生Minor GC（YGC，表示Young GC）53次，总耗时1.189秒（YGCT 表示耗时）,

发生Full GC（FGC，表示Full GC）4次，总耗时0.739秒（FGCT 表示耗时）

总的耗时（GCT，表示GC Time）为1.929秒。

1.4、jmap命令分析内存

jmap 是JDK中提供的一个用来监视进程运行中的jvm物理内存的占用情况的工具。
该进程内存中所有对象的情况，例如产生了哪些对象，对象数量。
当系统崩溃时，jmap 可以从core文件或进程中获得内存的具体匹配情况，包括Heap size, Perm size等。

注意：使用jmap dump堆信息时，会触发Full GC, 触发Full GC 可能导致线上服务不可用，因此，要慎重使用，所以尽量不要在线上执行此命令。如果想dump堆信息，可以使用gcore命令，比jmap -dump快。

• jmap -heap PID 查看进程的JVM占用内存情况

  重点关注以下两个：
  Parallel GC with 4 thread(s) #垃圾回收的方式。
  Heap Configuration: #堆配置信息。

• jmap -histo:live PID 显示堆中当前活动的所有对象的统计信息，按实例对象数量从高到低显示。重点关注实例对象数量过多的类。并找到对应程序。

  参数解释：num #instances #bytes class name
  ​ 序号 #实例对象数量 #字节大小 完整类名

• jmap -histo PID | head -n 10 查看前10的对象统计信息（仅用于linux, window执行不了）

  

• jmap -dump:format=b,file=heap.dump PID 生成堆转储快照dump文件(即：导出堆信息)

• jmap -dump:format=b,file=heap.hprof PID 生成堆转储快照dump文件(即：导出堆信息)

  format=b 表示输出为二进制;
  heap.dump 表示输出的文件名为heap.dump(可指定相对路径或绝对路径);
  pid 表示进程ID
  本地工具：mat, jvisualvm。
  在线工具 fasthread.io

dump文件可视化分析工具，如下：

• 本地工具 IBM HeapAnalyzer， mat , jvisualvm

• 在线工具 https://fastthread.io/, https://heaphero.io/

1.5、arthas工具

Arthas 是一款线上监控诊断产品，通过全局视角实时查看应用 load、内存、GC、线程的状态信息，并且能在不修改应用代码的情况下，对业务问题进行诊断，包括查看方法调用的出入参、异常，监测方法执行耗时，类加载信息等，大大提升线上问题排查效率。

注意：使用jmap dump堆信息时，会触发Full GC, 触发Full GC 可能导致线上服务不可用，因此，要慎重使用，所以尽量不要在线上执行此命令。如果想dump堆信息，可以使用gcore命令，比jmap -dump快。

1.5.1 工具使用

• 下载arthas 是绿色工具，只要解压，就能直接使用（window 和 linux使用方式相同）
• linux环境 ， 进入 arthas 目录下，输入java -jar arthas-boot.jar
• window 环境，在 arthas 目录下，按住shift + 右击，打开命令窗口，输入上面的命令。
• 输入 java 项目前面的序号（即：数字）

1.5.2 常用命令

• dashboard 查看总体概况，发现有CPU占用高的进程

• thread PID 可以查看指定线程信息，能迅速定位到问题代码

二、原因分析

2.1、Full GC次数过多(重点)

相对来说，这种情况是最容易出现的，尤其是新功能上线时。对于Full GC较多的情况，其主要有如下两个特征：

• 线上多个线程的CPU都超过了100%，通过 jstack 命令可以看到这些线程主要是垃圾回收线程。
• 通过 jstat 命令监控 GC 情况，可以看到 Full GC 次数非常多，并且次数在不断增加。

2.1.1 初步排查

使用 top 与 top -Hp 命令找到CPU占用最高的Java线程，将其转为16进制后，使用 jstack 命令抓取该线程信息，发现线程名称是"VM Thread" 表示垃圾回收线程。

2.2.2 进一步确认

使用 jstat -gcutil 命令查看 GC 次数与增长情况。

2.2.3 进一步分析

使用 jmap -dump 命令dump内存，然后使用离线分析，可能是以下两个原因

• 生成大量的对象，导致内存溢出(内存泄露)
• 内存占用不高，但是 Full GC 次数还是比较多，此时可能是代码中手动调用 System.gc 导致 GC 次数过多。

Ⅰ-内存溢出和内存泄露

一种通俗的解释：
1、内存溢出：你申请了10个字节的空间，但是你在这个空间写入11或以上字节的数据，出现溢出。
2、内存泄漏：你用new申请了一块内存，后来很长时间都不再使用了（按理应该释放），但是因为一直被某个或某些实例所持有导致 GC 不能回收，也就是该被释放的对象没有释放。

a) 内存溢出

java.lang.OutOfMemoryError，是指程序在申请内存时，没有足够的内存空间供其使用，出现OutOfMemoryError。

产生原因：

• JVM内存过小
• 程序不严谨，产生了过多的垃圾

一般情况下，在程序上的体现为：

1.内存中加载的数据量过于庞大，如一次从数据库取出过多数据。
2.集合类中有对对象的引用，使用完后未清空，使得 JVM 不能回收。
3.代码中存在死循环或循环产生过多重复的对象实体。
4.使用的第三方软件中的BUG。
5.启动参数内存值设定的过小。

解决方法：

• 增加 JVM 的内存大小
• 优化程序，释放垃圾

主要思路就是避免程序体现上出现的情况。避免死循环，防止一次载入太多的数据，提高程序健壮型及时释放。因此，从根本上解决Java内存溢出的唯一方法就是修改程序，及时地释放没用的对象，释放内存空间。

b) 内存泄露

Memory Leak，是指程序在申请内存后，无法释放已申请的内存空间，一次内存泄露危害可以忽略，但内存泄露堆积后果很严重，无论多少内存，迟早会被占光。

产生原因：

在Java中，内存泄漏就是存在一些被分配的对象，这些对象有下面两个特点：
1）首先，这些对象是可达的，即在有向图中，存在通路可以与其相连；
2）其次，这些对象是无用的，即程序以后不会再使用这些对象。
如果对象满足这两个条件，这些对象就可以判定为Java中的内存泄漏，这些对象不会被GC所回收，然而它却占用内存。

解决方法：

关于内存泄露的处理就是提高程序的健壮型，因为内存泄露是纯代码层面的问题。

总结：

内存泄漏的原因分析，总结出来只有一条：存在无效的引用，良好的编码规范以及合理使用设计模式有助于解决此类问题。

Ⅱ-内存溢出和内存泄露的联系

• 内存泄露会最终会导致内存溢出。
• 相同点：都会导致应用程序运行出现问题，性能下降或挂起。
• 不同点：
  1. 内存泄露是导致内存溢出的原因之一，内存泄露积累起来将导致内存溢出。
  2. 内存泄露可以通过完善代码来避免。内存溢出可以通过调整配置来减少发生频率，但无法彻底避免。

Ⅲ-步骤分析

Java的内存泄露多半是因为对象存在无效的引用，对象得不到释放，如果发现Java应用程序占用的内存出现了泄露的迹象，那么我们一般采用下面的步骤分析：

1. 用工具生成java应用程序的heap dump（如 jmap）

2. 使用Java heap分析工具（如MAT），找出内存占用超出预期的嫌疑对象

3. 根据情况，分析嫌疑对象和其他对象的引用关系。

4. 分析程序的源代码，找出嫌疑对象数量过多的原因。

   (实际案例：加班单导入日期区间错误，导致内存溢出，服务挂掉；加班单导入，产生大对象, 内存泄露，系统功能响应非常慢)

2.2、某个业务逻辑执行时间过长

如果是 Full GC 次数过多，那么通过 jstack 得到的线程信息会是类似于"VM Thread"之类的线程，而如果是代码中有比较耗时的计算，那么我们得到的就是一个线程的具体堆栈信息。

如下是一个代码中有比较耗时的计算，导致CPU过高的线程信息

这里可以看到，在请求 UserController 的时候，由于该 Controller 进行了一个比较耗时的调用，导致该线程的CPU一直处于100%。

我们 **可以根据堆栈信息，**直接定位到 UserController 的34行，查看代码中具体是什么原因导致计算量如此之高。

2.3、死锁

如果有死锁，会直接提示。关键字：deadlock。使用 jstack 打印线程信息会打印出业务死锁的位置。

2.4、线程一直处于WAITTING状态

对于这种情况，这是比较罕见的一种情况，但是也是有可能出现的，而且 由于其具有一定的 “不可复现性”，因在排查的时候是非常难以发现的。

某个线程由于某种原因而进入WAITING状态，此时该功能整体不可用，但是无法复现。jstack 多查询几次，每次间隔30秒，对比一直停留在parking 导致的WAITING状态的线程。

可以通过给线程命名快速定位到是哪个业务代码。

2.2 随机出现大量线程访问接口缓慢

对于这种情况，比较典型的例子就是，我们某个接口访问经常需要2~3s才能返回。

这是比较麻烦的一种情况，因为一般来说，其消耗的CPU不多，而且占用的内存也不高，也就是说，我们通过上述两种方式进行排查是无法解决这种问题的。

而且由于这样的接口耗时比较大的问题是不定时出现的，这就导致了我们在通过 jstack 命令即使得到了线程访问的堆栈信息，我们也没法判断具体哪个线程是正在执行比较耗时操作的线程。

对于不定时出现的接口耗时比较严重的问题，我们的定位思路基本如下：

首先找到该接口， 通过压测工具不断加大访问力度，如果说该接口中有某个位置是比较耗时的，由于我们的访问的频率非常高，那么大多数的线程最终都将阻塞于该阻塞点

这样 通过多个线程具有相同的堆栈日志，我们基本上就可以定位到该接口中比较耗时的代码的位置。

如下是一个代码中有比较耗时的阻塞操作通过压测工具得到的线程堆栈日志：

从上面的日志可以看你出，这里有多个线程都阻塞在了 UserController 的第18行，说明这是一个阻塞点，也就是导致该接口比较缓慢的原因。

另一个思路是，使用 arthas 工具的命令：trace com.aibaobei.user.controller detail 监控此方法调用链路，可以看出方法中哪一行比较耗时。

三、总结

将以上场景使用过的命令进行汇总

3.1、排查命令总结

• top 查看系统进程CPU与内存占用情况，找到占用最多的进程ID

• top -n num 查看CPU占用最高的num个进程

• top -Hp PID 或 top -H -p PID查看该进程号的所有线程CPU与内存占用情况，找到占用最多的线程ID

• jps -l 显示当前所有 Java 进程ID 的命令 （window环境和linux环境）

• printf '%x\n' PID 或 printf %x PID表示将线程ID 转换为十六进制，用于搜索线程堆栈中的关键信息 （linux环境）

• jstack PID | grep 线程ID 查看线程堆栈信息 （linux环境）

• jstack PID | grep -C10 线程ID --color 查看线程堆栈信息 （linux环境）

• jstack -l PID 查看线程堆栈信息

• jstack PID >> stack.txt 将当前所有堆栈信息输出到stack.txt文件中

• jstat -gcutil PID 1000 2 或 jstat -gc PID 1000 2 表示进程ID每间隔1000毫秒统计2次（缺省代表一直统计），查看某进程GC持续变化情况

• jmap -heap PID 查看进程的JVM占用内存情况

• jmap -histo:live PID 显示堆中当前活动的所有对象的统计信息，按实例对象数量从高到低显示。重点关注实例对象数量过多的类。并找到对应程序。

• jmap -histo PID | head -n 10 查看前10的对象统计信息（仅用于linux, window执行不了）

• jmap -dump:format=b,file=heap.dump PID 生成堆转储快照dump文件(即：导出堆信息)

• jmap -dump:format=b,file=heap.hprof PID 生成堆转储快照dump文件(即：导出堆信息)

• dashboard 查看总体概况，发现有CPU占用高的进程 （使用 arthas工具）

• thread PID 可以查看指定线程信息，能迅速定位到问题代码 （使用 arthas工具）

3.2、异常情况解决总结

• GC问题： top + top -Hp + jstack 排查是"VM Thread"消耗过多资源，可以进一步使用 jmap 工具进行内存溢出排查。
• 业务执行过慢问题： top + top -Hp + jstack 排查发现是普通业务线程，可看到具体是哪个接口。
• 死锁： jstack + Java 进程打印堆栈信息中包含死锁信息deadlock
• 线程处于waiting状态： 多打印几次``jstack` 信息，对比一直停留在waiting状态的线程。