记一次 JVM 线上调优实战

约定不等于承诺〃 2023-09-30 10:44 32阅读 0赞

### 问题描述 ###

很多时候我们的系统在使用过程中经常出现卡顿的情况，或者请求变慢等等情况，然后运维人员跑来给你说写的什么垃圾代码，CPU 飙升，经常 100%，内存飙升。

如果你不知道怎么定位问题，觉得自己代码也找不出什么问题，那就说重启试试咯！！！

当然了，这种处理方式可以解决，但并不能从根本上解决问题，试想一下如果对于高并发的系统，你重启项目肯定是不行的，所以我们要找到问题的源头，因为我们程序都是跑在 JVM 里面的，所以上面的 2 种情况很可能是我们的代码出现了问题，比如常见的死循环，递归等等，当然这种就是比较明显的错误。大多数情况下我们能察觉出来，而对于比较难以察觉的代码问题，则需要我们在 JVM 的层面去解决，也就是所谓的 **JVM 调优**。

问题如下：

1.  系统 CPU 经常 100%，如何调优？
2.  系统内存飙升，如何定位问题？

当然，有人会说，加内存，加服务器等等，我们要理解调优的目的，其目的是为了利用现有的内存来获取**高吞吐量**或者**低延迟**，说白了就是花更少的钱做更多的事。

### 场景模拟 ###

之前在公司做过一个差旅系统（类似携程，但针对的是企业用户），大概意思是年终要**定时**统计年终的差旅费用，包括机票，酒店费用报销等等，把数据从 MySQL 中取出来计算汇总，如下：

![image-20220315105115488][]

大概步骤：

1.  从数据库中批量读取用户信息；
2.  利用线程池多线程执行任务计算。

模拟代码如下：

/**
     * VM参数： -XX:+PrintGC -Xms200M -Xmx200M
     * GC调优---生产服务器推荐开启(默认是关闭的)
     * -XX:+HeapDumpOnOutOfMemoryError
     */
    public class FullGCProblem {
        
        //线程池
        private static ScheduledThreadPoolExecutor executor = new ScheduledThreadPoolExecutor(50, new ThreadPoolExecutor.DiscardOldestPolicy());
    
        public static void main(String[] args) throws Exception {
        
            //50个线程
            executor.setMaximumPoolSize(50);
            while (true) {
        
                calc();
                // 休眠 100ms 模拟计算耗时
                Thread.sleep(100);
            }
        }
    
        /**
         * 模拟多线程执行任务计算
         */
        private static void calc() {
        
            List<UserInfo> taskList = getAllCardInfo();
            taskList.forEach(userInfo -> {
        
                executor.scheduleWithFixedDelay(() -> {
        
                    userInfo.other();
                }, 2, 3, TimeUnit.SECONDS);
            });
        }
    
        /**
         * 模拟从数据库读取数据，返回
         */
        private static List<UserInfo> getAllCardInfo() {
        
            List<UserInfo> taskList = new ArrayList<>();
            for (int i = 0; i < 100; i++) {
        
                UserInfo userInfo = new UserInfo();
                taskList.add(userInfo);
            }
            return taskList;
        }
    
        private static class UserInfo {
        
            String name = "ayue";
            int age = 18;
            BigDecimal money = new BigDecimal(999999.99);
    
            // 模拟计算逻辑
            public void other() {
        
                
                System.out.println(Thread.currentThread().getName() + "：计算中...");
            }
        }
    }

### 问题复现 ###

我们在虚拟机上运行上面这个 main 方法，这里的虚拟机配置如下：

![image-20220315120302703][]

然后把上面的程序打为 jar 包，在虚拟机中运行如下：

java -cp jvm.jar -XX:+PrintGC -Xms200M -Xmx200M net.javatv.gc.FullGCProblem

![image-20220315132112124][]

对于上面的程序，我们是知道具体的代码的，而一般情况下，你是不知道别人的代码是怎么写的，所以我们一般可以通过 top 命令来查看 CPU，内存等使用情况。

如下：

![image-20220315133047417][]

可以看到其中的 Java 程序 cpu 飙升，甚至超过了 100%，且内存占用也比较高，然后在去看 GC 日志，如下：

![image-20220315133826316][]

可以看到，存在非常频繁的 Full GC。

**注意**：并不是一开始就超过 100%，或者OOM，频繁 GC 等，一般程序可能会过一段时间才会出现。

### 问题定位 ###

对于上面存在的问题，我们分为两种情况来定位：

1.  CPU 占用过高
2.  内存占用过高

此外，JDK 也为我们提供了如下性能诊断工具，详细操作可参考之前写的文章：[JDK自带性能诊断工具][JDK]

![image-20220315134411702][]

#### CPU 占用过高 ####

`top` 命令是我们在 Linux 下最常用的命令之一，它可以实时显示正在执行进程的 CPU 使用率、内存使用率以及系统负载等信息。其中上半部分显示的是系统的统计信息，下半部分显示的是进程的使用率统计信息。

具体步骤如下：

**1、通过 `top`命令来找到消耗 CPU 很高的进程 id**

为什么要使用 `top`而不使用 jdk 自带的诊断工具，是因为我们要先确定是不是 Java 程序导致的，如下：

![image-20220315140615028][]

**2、单独监控该进程**

利用如下命令单独监控，如下：

top -p 4337

![image-20220315141124412][]

然后在该界面输入 `H`，则展示该进程下所有的线程信息，如下：

![image-20220315141229768][]

**3、找到消耗 cpu 特别高的线程编号**

![image-20220315141518338][]

**4、执行 jstack 对当前的进程做 dump，输出所有的线程信息**

注意是进程，即上面的 4337，如下：

jstack 4337

![image-20220315142432876][]

可以看到它会输出所有线程的堆栈信息，并且存在一些 16 进制的 nid。

**5、线程进制转换**

然后我们把第 4 步得到的线程 id 4340，4339进行 16 进制转换：

4340---10F4
     4339---10F3

把转换的进制在第 4 步的线程信息中查找，如下：

![image-20220315143227877][]

从图中可以看出，造成 **CPU100%** 的原因是在由于**垃圾回收线程**导致的，而可能不是我们**业务线程**导致的。

PS：jdk1.8 默认垃圾收集器Parallel Scavenge（新生代）+Parallel Old（老年代）

可通过以下命令查看默认垃圾回收器：

java -XX:+PrintCommandLineFlags -version

由于一般情况下我们的项目在运行过程中是不会开启 GC 日志的，我们可以`jstat –gc pid` 来统计，达到类似的效果，如下：

//每间隔 2s 总共查询 10 次 GC 情况
    jstat -gc 4337 2000 10

查询结果如下：

![image-20220315144857979][]

说明：

S0C：第一个幸存区（From 区）的大小
    S1C：第二个幸存区（To 区）的大小
    S0U：第一个幸存区的使用大小
    S1U：第二个幸存区的使用大小
    EC：伊甸园（Eden）区的大小
    EU：伊甸园（Eden）区的使用大小
    OC：老年代大小
    OU：老年代使用大小
    MC：方法区大小
    MU：方法区使用大小
    CCSC:压缩类空间大小 
    CCSU:压缩类空间使用大小 
    YGC：年轻代垃圾回收次数
    YGCT：年轻代垃圾回收消耗时间
    FGC：老年代垃圾回收次数
    FGCT：老年代垃圾回收消耗时间
    GCT：垃圾回收消耗总时间

当然了，其实我们只需要展示需要的列：

// 每间隔 2s 总共查询 10 次 GC 情况，且只显示13~17列的数据。
    jstat -gc 4337 2000 10 | awk '{print $13,$14,$15,$16,$17}'

![image-20220315145501769][]

从上图可以看出，`YoungGC` 只进行了 19 次，而进行了大量的 `Full GC`（7000多次且继续递增），同时`PrintGC`还显示抛出了 `OutOfMemory`。

![image-20220315145740235][]

**结论**

这里的 CPU 占用过高不是业务线程导致，而是 GC 线程占用过高导致的，JVM 在疯狂的进行垃圾回收，**JVM 中默认的垃圾回收器是多线程的**，所以多线程在疯狂回收，导致 CPU 占用过高。

#### 内存占用过高 ####

那么，它为什么会进行疯狂的垃圾回收？很显然，**内存不够**，我们通过`jmap`看一下堆的内存情况，如下：

jmap –heap 4337

![image-20220315151108800][]

很明显的可以看到，老年代已经被塞得满满的了，也就是说 GC 好像没有作用了，有人说为什么没有自动扩容（代码中有注释，设置了 -Xmx=200M，目的是快速测试），就算没有设置，随着时间最后也会塞满。

因此，问题的根本很可能发生了内存泄漏。

我们可以通过 `jmap`导出堆的快照（即 dump 文件），但是导出 dump 文件过大会对程序造成影响，因此我们可以先`jmap -histo pid`，它可以打印每个 class 的实例数目，内存占用，类全名信息。如下：

//把JVM中的对象全部打印出来， 但是这样太多了，那么我们选择前 20 的对象展示出来
    jmap –histo 4337 | head -20

![image-20220315200145967][]

可以看到，存在很多个对象，大约 60 万个（其实这个时候程序已经死掉了，但是还是占用 CPU）。

一般来说，前面这几行，就可以看出，到底是哪些对象占用了内存。我们知道对象都是朝生夕死的，那么为什么这些对象不死呢？回收不掉呢？其结果导致了 `FullGC` 和 `OutOfMemory`。

我们再回顾上面的代码，我们把线程池的最大线程数设置为 50，而我们的任务数为 100，任务数多于线程数，那么任务会进入阻塞队列，由于任务数一直多于线程数，所以每 0.1s 就会有 50 个任务进入阻塞队列，没有执行，但同时这些对象又被线程池对象 Executor 引用，且Executor 是一个 `GCroots`，所以堆中有 60 万个对象（UserInfo），阻塞队列中有 60 万个任务（ScheduledFutureTask），并且这些对象还无法回收。

**因此，我们可以定位到代码，要么加大线程池的线程数，要么减少批量任务数**。

### 总结 ###

在 JVM 出现性能问题的时候，表现上是 CPU100%，实际是内存一直占用导致。

1.  如果 CPU 的 100%，要从两个角度出发，一个有可能是业务线程疯狂运行，比如说很多死循环。还有一种可能性，就是 GC 线程在疯狂的回收，因为 JVM 中垃圾回收器主流也是多线程的，所以很容易导致 CPU 的 100%。
2.  在遇到内存泄漏的问题的时候，一般情况下我们要查看系统中哪些对象占用得比较多，在实际的业务代码中，通过分析找到对应的对象，分析对应的类，找到为什么这些对象不能回收的原因（可达性分析算法）。

另外，如果观察一个系统，每次进行 FullGC 发现堆空间回收的比例比较小，尤其是老年代，同时对象越来越多，这个时候可以判断是有可能发生内存泄漏，而内存泄漏就和代码有很大的关系，因此需要我们去检查代码。

上面的例子只是一次相对简单的调优经历，可以使用 `jmap –histo` 这种命令去分析哪些对象占据着我们的堆空间，如果遇到更加复杂的情况，命令的方式是看不出来的，这个时候我们必须要借助一下工具（如 MAT，它也是最主要的分析工具，后续再讲），当然前提是通过 `jmap` 命令把整个堆内存的数据 dump 下来。

**内存泄漏和内存溢出**

1.  内存溢出
    
    实实在在的内存空间不足导致，即程序运行所需要的内存大于所提供的内存。
2.  内存泄漏
    
    该释放的对象没有释放，常见于使用容器保存元素的情况下，程序执行完成后对象没有被回收，处于一直存活的状态，但这个对象又没有用了，JVM又回收不了。
3.  两者关系
    
    内存泄漏过多之后就会造成内存溢出。怎么理解？多线程执行同一个内存泄漏的程序，也就是占用过多的内存之后，超出了规定的内存大小，自然就溢出了。
    
    因此，往往很多情况下，内存溢出往往是内存泄漏造成的。

所谓优化，经常有句玩笑话就是加钱加内存，因此，我们一般优化的思路有以下几点：

1.  程序优化，效果通常非常大；
2.  扩容，如果金钱的成本比较小，不要和自己过不去；
3.  参数调优，在成本、吞吐量、延迟之间找一个平衡点。

[image-20220315105115488]: https://img-blog.csdnimg.cn/img_convert/dedb91a7ab729c266af1fd36bd216432.png
[image-20220315120302703]: https://img-blog.csdnimg.cn/img_convert/3b8fb819c64bb691bf2f117a3106e295.png
[image-20220315132112124]: https://img-blog.csdnimg.cn/img_convert/bb01c926a822bc4d52af87d8a059d06d.png
[image-20220315133047417]: https://img-blog.csdnimg.cn/img_convert/18e97c1f9fa5406a666da551993bc6ce.png
[image-20220315133826316]: https://img-blog.csdnimg.cn/img_convert/a7580ef1d9e07397ff1fdf411a83310f.png
[JDK]: https://javatv.blog.csdn.net/article/details/120145571
[image-20220315134411702]: https://img-blog.csdnimg.cn/img_convert/77a1a7b8995149b4f8e30e664d67bc32.png
[image-20220315140615028]: https://img-blog.csdnimg.cn/img_convert/ea296e4a6795595c0a2305246caeac89.png
[image-20220315141124412]: https://img-blog.csdnimg.cn/img_convert/ae41d87830f3e679d5a4b7526aa68fc3.png
[image-20220315141229768]: https://img-blog.csdnimg.cn/img_convert/99a5191d85828881ae5664705727c98b.png
[image-20220315141518338]: https://img-blog.csdnimg.cn/img_convert/5ad50b9fd37bdefc041a7c66947496ce.png
[image-20220315142432876]: https://img-blog.csdnimg.cn/img_convert/6bdc37a9e4f016dcb5672f5a9ea2be9a.png
[image-20220315143227877]: https://img-blog.csdnimg.cn/img_convert/78e430150bc2571683f4044ad38ee123.png
[image-20220315144857979]: https://img-blog.csdnimg.cn/img_convert/a84c9bf0e7d848d4e6c7d75f9d16680e.png
[image-20220315145501769]: https://img-blog.csdnimg.cn/img_convert/6c615d139a0da62fd8aee1fc78afe286.png
[image-20220315145740235]: https://img-blog.csdnimg.cn/img_convert/269ca1b4968b01a5c91931d434bd62d2.png
[image-20220315151108800]: https://img-blog.csdnimg.cn/img_convert/336f433f351865b0535238096000ec0a.png
[image-20220315200145967]: https://img-blog.csdnimg.cn/img_convert/8b3932f4d43ef7893819e8be3f84130c.png