只是不愿随波逐流 ...|
收藏闪存小组博问

lidongdongdong~

园龄：2年7个月粉丝：14关注：8

64、JVM 问题排查

内容来自王争 Java 编程之美

上一节我们讲到：JVM 的性能优化、参数调优一般都发生在 JVM 出现问题时，比如 OOM、频繁 GC、GC 时间过长等
本节我们就来讲一下常见的 JVM 问题的解决方案，以及排查问题过程中常用的 JVM 性能监控和分析工具

1、JVM 性能监控和分析工具

用于 JVM 性能监控和分析的工具有很多，常见的有 jstat、JConsole、VisualVM、jmap、MAT 以及一些 JVM 参数
按照功能我们将它们分为 3 类：GC 统计信息监控、GC 详细日志分析、JVM 内存快照获取和分析，接下来我们就按照类别简单介绍一下这些工具

1、GC 统计信息监控：jstat、JConsole、VisualVM 等

jstat 是命令行工具，JConsole、VisualVM 是可视化工具，JConsole、VisualVM 不仅可以监控 GC 的情况，还可以监控系统资源（CPU、内存等）的使用情况、线程的执行情况等
这里我们重点介绍一下更加简单常用的 jstat

jstat 命令使用起来非常简单，我们只需要通过 jps 命令查找到要监控的 JVM 进程 ID，然后执行 jstat -gcutil [vmid] [time-interval] 即可
其中 time-interval 为每次输出 GC 统计信息的时间间隔，以毫秒为单位，以下示例为间隔 1 秒输出一条 GC 统计信息
image

在以上 jstat 输出的统计信息中，各列的含义如下所示

  • S0：表示 Survivor0 的内存使用率
  • S1：表示 Survivor1 的内存使用率
  • E：表示 Eden 区的内存使用率
  • O：表示老年代的内存使用率
  • M：表示 Metaspace 的内存使用率
  • YGC：YoungGC 的次数
  • YGCT：YoungGC 的总耗时
  • FGC：FullGC 的次数
  • FGCT：FullGC 的总耗时
  • GCT：GC 的总耗时

通过以上统计信息，我们可以获得 GC 的各项重要指标，比如
YoungGC 频率、FullGC 频率、YoungGC 耗时、FullGC 耗时、年轻代的垃圾回收率、老年代的垃圾回收率、年轻代的对象增长速率、老年代的对象增长速率等
以此来检查 JVM 是否存在问题

2、GC 详细日志分析：JVM 参数 -XX:+PrintGCDetails 等

从上述讲解，我们可以发现，jstat 只能输出 GC 的统计信息，如果我们希望获得每次 GC 的详细情况，那么我们就需要使用如下 JVM 参数

  • -XX:+PrintGCDetails 打印详细 GC 日志
  • -Xloggc:./logs/gc.log 详细 GC 日志存储的位置

在设置以上 JVM 参数之后，JVM 输出的日志格式如下示例所示
注意：不同版本的 JVM 和不同的垃圾回收器输出的 GC 日志格式也不同，这里显示的是 Java 8 和 CMS 垃圾回收器对应的 GC 日志格式
image

以上日志可以粗略的分为两类：ParNew 日志和 CMS 日志，我们先来看 ParNew 日志，我们拿上图中的第一条日志来举例讲解

[GC (Allocation Failure) 4.527: [ParNew: 48243K->6054K(55296K), 0.0101725 secs] 48243K->11277K(96256K), 0.0103798 secs] [Times: user=0.08 sys=0.01, real=0.01 secs]

我们对上述 ParNew 日志所包含的信息逐一解读，如下所示

  • GC（Allocation Failure）：表示 GC 是因为内存分配失败触发的
  • 4.527：表示 GC 发生的时间（距离 JVM 启动所经历的秒数）
  • [ParNew：48243K->6054K(55296K)，0.0101725 secs]：表示 GC 的情况
    ParNew 表示 GC 类型为 Parallel New，48243 K 和 6054 K 表示 GC 前后年轻代中对象的大小 55296 K 表示年轻代的总大小，0.0101725 表示 GC 耗时
  • 48243K->11277K(96256K)，0.0103798 secs：48243 K 和 11277 K 表示本次 GC 前后整个堆中对象的大小变化，96256 K 表示整个堆的总大小
  • [Times: user=0.08 sys=0.01, real=0.01 secs]：表示 GC 具体的耗时分析
    user=0.08 表示 GC 线程使用 CPU 的时间，sys=0.01 表示系统调用的时间，real=0.01 表示墙上时钟，也就是从 GC 开始到结束所经历的时间，即 STW 停顿时间
    注意：在多核多线程情况下，user 时间为每个线程所使用的 CPU 时间之和，因此它的大小很有可能超过 real 时间的大小

接下来我们再来看下 CMS 日志，我们拿其中一条 CMS 日志举例讲解，如下所示

25.933: [GC (CMS Initial Mark) [1 CMS-initial-mark: 22706K(40960K)] 29330K(96256K), 0.0002184 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
 
25.934: [CMS-concurrent-mark-start]
25.935: [CMS-concurrent-mark: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
 
25.935: [CMS-concurrent-preclean-start]
25.935: [CMS-concurrent-preclean: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
 
25.935: [GC (CMS Final Remark) [YG occupancy: 6624 K (55296 K)]25.935: [Rescan (parallel) , 0.0004028 secs]25.935: [weak refs processing, 0.0000226 secs]25.935: [class unloading, 0.0002652 secs]25.936: [scrub symbol table, 0.0003544 secs]25.936: [scrub string table, 0.0001626 secs][1 CMS-remark: 22706K(40960K)] 29330K(96256K), 0.0013012 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]
 
25.936: [CMS-concurrent-sweep-start]
25.936: [CMS-concurrent-sweep: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
 
25.936: [CMS-concurrent-reset-start]
25.937: [CMS-concurrent-reset: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]

CMS 日志包含的信息比 ParNew 日志要多很多
其中 CMS Initial Mark、CMS-concurrent-mark、CMS Final Remark、CMS-concurrent-sweep 分别对应并发垃圾回收的四个阶段：初始标记、并发标记、重新标记、并发清理
除此之外，CMS 日志中的 CMS-concurrent-preclean 和 CMS-concurrent-reset 为更加细化的并发垃圾回收阶段，负责 CMS 内部数据结构的调整工作，这里就不展开详细讲解了

3、JVM 内存快照获取和分析：JVM 参数 -XX:+HeapDumpBeforeFullGC、-XX:+HeapDumpOnOutOfMemoryError、jmap、MAT、jhat 等

以上我们讲到都是监控 GC 情况的工具，但是当 JVM 出现问题时，比如 OOM、频繁 GC
如果我们希望得知当前堆中存储的对象情况，比如哪些对象占据了大量堆内存，我们就需要将当下的内存快照 dump 出来，然后利用工具来查看和分析

常用的 dump 堆内存快照的方法有两种，一种是使用 JVM 参数，另一种是使用 jmap 命令行工具，具体如下所示
dump 出来的堆内存快照为二进制文件，我们需要通过工具来查看，常用的查看工具有 MAT、jhat 等

# 方法一: 使用 JVM 参数
-XX:+HeapDumpBeforeFullGC
-XX:HeapDumpOnOutOfMemoryError
-XX:HeapDumpPath=目录
# 方法二: 使用 jmap 命令行工具
jmap -dump:format=b,file=文件名 [pid]

对 JVM 性能监控和分析工具有了一定了解之后，我们来看下 OOM、频繁 GC、GC 时间过长这几个常见的 JVM 问题

2、JVM 常见问题一：OOM

当应用程序申请不到足够的内存空间
并且即便 JVM 通过 GC 也无法释放出足够的内存空间时，JVM 便会抛出 java.lang.OutOfMemoryError，这种情况就称为 OOM（Out Of Memory），即内存溢出
内存溢出一般有两种：永久代（元空间）的内存溢出和堆的内存溢出，分别对应以下两种错误信息

java.lang.OutOfMemoryError: PermGen space(或 MetaSpace)
java.lang.OutOfMemoryError: Java heap space

导致内存溢出的常见的原因有如下几种

  • 设置的堆或永久代（元空间）的大小太小
  • 一次性创建过多的对象，比如通过 SQL 查询全表数据
  • 应用程序使用完成的对象没有被及时释放，导致对应的内存无法被回收，长期积累，便会导致内存耗尽，我们把这种情况叫做内存泄露

关于内存泄露我们通过一个例子来解释一下，在下述代码中，Stack 在使用的过程中会出现内存泄露问题，请你思考下这是为什么呢？

public class Stack {
 
    private Object[] array;
    private int capacity;
    private int top;
 
    public Stack(int capacity) {
        this.capacity = capacity;
        this.top = 0;
        this.array = new Object[capacity];
    }
 
    public void push(Object obj) {
        array[top++] = obj;
    }
 
    public Object pop() {
        return array[--top];
    }
}

当执行 pop() 函数时，pop() 函数只是将 top 值减一并返回对应的对象，并没有删除 array 数组对对象的引用关系
因此对象即便已经使用完成，也无法被回收，为了解决内存泄露问题，我们只需要对 pop() 函数稍作修改，将引用关系删除即可，具体如下所示

public Object pop() {
    Object obj = array[top - 1];
    array[top - 1] = null; // 删除引用关系
    top--;
    return obj;
}

了解了 OOM 问题产生的原因，我们再来看下如何排查 OOM 问题

当 JVM 出现 OOM 问题时，应用程序的对应表现一般是无法继续执行，如果应用程序是接口系统，那么接口将出现大量 503 错误
这时我们通过查看日志，便会发现大量 java.lang.OutOfMemoryError 错误信息
为了排查出到底哪些对象长期存在并大量占用内存，我们需要通过 jmap 或 JVM 参数获取堆内存快照，并通过 MAT 等工具来查看和分析

我们通过一个例子来解释一下上述排查过程，示例代码如下所示
我们将堆大小设置为 100 MB
在 OOMDemo 类中，代码循环执行 api() 函数，api() 函数创建大小约 1 MB 大小的 Student 对象并放入 list 中长期持有，这样就会导致堆内存很快被耗尽，随之发生 OOM

java-Xms100m-Xmx100m-Xmn60m-XX:SurvivorRatio=8-XX:+UseConcMarkSweepGC-XX:+HeapDumpOnOutOfMemoryError-XX:HeapDumpPath=./OOMDemo
 
public class OOMDemo {
    private static final List<Student> list = new ArrayList<>();
 
    public static void main(String[] args) {
        for (; ; ) {
            api();
        }
    }
 
    public static void api() {
        Student stu = new Student();
        list.add(stu);
    }
 
    private static class Student {
        private byte[] data = new byte[1024 * 1024];
    }
}

当发生 OOM 时，JVM 会自动 dump 内存快照文件（在作者的机器上会产生 java_pid31969.hprof 这样一个文件），我们将快照文件导入 MAT 工具，如下所示
经过 MAT 工具分析，91 MB 内存存在内存泄露的嫌疑
image

我们点击上图中的 "Details"，查看内存占用的详细情况，如下图所示
图中的 Shallow Heap 指对象本身所占用的内存空间，Retained Heap 指对象及其所引用的对象所占用的总的内存空间
从图中我们可以发现，怀疑内存泄露的数据主要集中在 OOMDemo 的 list 成员变量中
以此我们再去分析 OOMDemo 的代码，看是否真正存在内存泄露，又或者创建了太多长期存在的对象
如果两者都不是，也就是并非代码问题，那么我们尝试调大堆内存的大小来看是否能解决此问题
image

3、JVM 常见问题二：频繁 GC

一般来讲，在 OOM 出现之前，JVM 会先出现频繁 GC 的现象，频繁 GC 包括频繁 YoungGC 和频繁 FullGC
单纯的频繁 YoungGC 往往是由年轻代空间太小导致的，我们只需要适当增大年轻代的大小即可解决这个问题

你可能会说，增大年轻代大小会不会导致 YoungGC 时间增长呢？实际上并不会

  • 首先：年轻代采用的是标记-复制垃圾回收算法，标记也就是可达性分析，只对存活对象进行遍历，而复制也只会对存活对象进行复制
    因此 YoungGC 时间只与存活对象的数量有关，与年轻代大小无关
  • 其次：大部分对象都是朝生夕死，年轻代空间增大，YoungGC 时间间隔增长，这会导致更多的对象在 GC 前就死亡，年轻代中的存活对象并不会增多
    综合以上两点，YoungGC 时间并不会随着年轻代的增大而增长

相对于频繁 YoungGC，频繁 FullGC 会引发更加严重的问题，且解决起来更加复杂，因为 FullGC 更加消耗 CPU 资源并且 STW 停顿时间较长
所以在发生频繁 FullGC 时，CPU 利用率一般会飙升，并且会出现应用程序变慢的情况（比如接口请求处理速度变慢甚至大量超时）

触发 FullGC 的主要原因是老年代空间不足，前面我们已经总结过，老年代的对象一般来源于长期存活的对象、大对象、空间分配担保
接下来我们从这 3 个对象来源来分析频繁 GC 发生的原因

3.1、长期存活的对象

如果应用程序创建的长期存活的对象比较多，那么我们可以适当调大老年代的大小，以减少 FullGC 的频率
不过这种情况并不常见，大部分应用程序并不会创建太多的长期存活的对象
实际上，内存泄露往往才是导致对象长期存活无法回收的主要原因
如果每次 FullGC 回收率很低，释放出来的空间很少，那么就说明是存在内存泄露了，频繁 FullGC 一段时间之后，JVM 便会出现 OOM

3.2、大对象

前面讲到，大对象会直接进入老年代，过多的大对象是引起频繁 FullGC 的最常见的原因之一
比如：在某个接口中执行了未分页 SQL，一次性加载过多数据到内存中，当高并发下，接口大量被调用，就会导致大量大对象被创建，从而导致老年代空间不足，引发频繁 FullGC
定位此种频繁 FullGC 发生的原因，我们需要在 FullGC 前（设置 JVM 参数 -XX:+HeapDumpBeforeFullGC）dump 内存快照，分析占用堆内存比较多的是哪个对象，以此来定位问题代码

3.3、空间分配担保

前面讲到，在执行 YoungGC 时，如果 To Survivor 空间不足，JVM 会触发空间分配担保，将对象存储到老年代
因此如果每次 YoungGC，To Survivor 都被占满，那么我们就要考虑增大 To Survivor 区，避免空间分配担保，减少进入老年代的对象数量

4、JVM 常见问题三：GC 时间过长

导致 GC 时间过长的常见原因有：堆内存过大、Concurrent Mode Failure、操作系统 swap

4.1、堆内存过大

前面讲到，年轻代使用标记-复制垃圾回收算法，并且年轻代空间增大并不会导致存活对象增多，因此 YoungGC 时间跟年轻代的大小无关
但是老年代使用标记 - 整理或标记 - 清除垃圾回收算法，并且老年代空间增大会导致存活对象增多，因此 FullGC 时间跟老年代的大小有关，老年代过大会导致 FullGC 时间过长
针对比较大的堆内存，我们应该选择 GC 时间可控的 G1 垃圾回收器，或者在一台大物理内存的机器上部署多个 JVM，以减小单个堆内存的大小

4.2、Concurrent Mode Failure

前面讲到，CMS 垃圾回收器采用并发垃圾回收算法，在垃圾回收的某些阶段，应用程序可以与之并发执行
应用程序的执行需要堆内存，因此 JVM 在执行垃圾回收前，会预留一定的堆内存空间
但是在执行垃圾回收的的过程中，如果预留空间不足，应用程序无法继续执行
那么 JVM 便会抛出 Concurrent Mode Failure 错误，并且暂停 CMS 垃圾回收器的执行，改为 STW 停顿时间更长的 Serial Old 垃圾回收器
垃圾回收器的中止和切换势必会增长 FullGC 时间
如果我们在 GC 详细日志中（通过设置 JVM 参数 -XX:+PrintGCDetails 得到）发现大量 Concurrent Mode Failre 字样
那么我们就需要通过减小 JVM 参数 -XX:CMSInitialOccupancyFraction 的值来调大预留空间的大小

4.3、操作系统 swap

swap 是操作系统中的概念，当物理内存不足时，操作系统会将物理内存中的部分不活跃的数据放入磁盘，当这部分数据重新被使用时，再从磁盘加载到物理内存中
这种数据在物理内存和磁盘之间换入换出的机制，就叫作 swap，swap 涉及磁盘 I / O 操作，非常影响进程的性能
如果设置的 JVM 堆内存大小超过物理内存大小，或者多个应用程序争用有限的物理内存，那么就有可能触发 swap 而导致 GC 时间增长
解决这个问题的方法也很简单，尽量保证 JVM 堆大小不要超过物理内存的大小，并且为操作系统或者其他软件预留充足的物理内存
比如物理内存有 8 GB，我们设置 JVM 堆大小为 6 GB，预留 2 GB给操作系统和其他并发运行的软件

5、课后思考题

除了频繁 FullGC，还有哪些引起应用程序变慢或 CPU 飙升的原因?
执行 CPU 密集型代码，比如因为 bug 而导致的递归代码死循环

posted @   lidongdongdong~  阅读(163)  评论(0)  编辑  收藏  举报
点击右上角即可分享
微信分享提示
AI FOR CODE 大赛
评论
收藏
关注
推荐
深色
回顶
展开