java

关注公众号 jb51net

关闭
首页 > 软件编程 > java > JVM内存飙升线上排查

JVM内存飙升线上问题排查方式

作者：一米阳光zw

文章主要介绍了线上CMS服务内存增长问题的排查过程,通过分析GC日志和堆栈快照,定位问题为Nacos的NamingService对象无法回收和MySQL的CallableStatement对象增长迅速,最终通过将NamingService改为单例模式解决了内存增长问题

前言

最近线上环境的CMS服务出现内存增长非常快的情况，上午内存2.4G下午就到了4G以上并且内存的增长随着时间推移一直增长，直到达到内存空间限制然后pod重启。由于之前没有接触过所以这次排查完记录一下，主要是分享一下排查的思路和工具以及一些指令等。

这次问题的排查思路是先查看gc日志，通过gc日志分析内存升高的过程主要是发生在哪个区，如果是堆外内存那可能不大好排查，可以查看代码中哪些涉及到大文件、大的字符串处理等，如果是新生代gc频繁那就是临时对象较多，gc日志只是做个大概的定位；其次主要还是需要对堆栈信息作分析，使用dump命令做快照，分别在服务刚启动时和内存飙升后做快照，对比升高后哪些对象的数量和大小增加。

GC日志

GC日志开启

在启动 Java 应用程序时，通过 JVM 参数启用 GC 日志记录

JDK 8 及以下版本

-XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:/path/to/gc.log

JDK 9 及以上版本

-Xlog:gc*:file=/path/to/gc.log:time,uptime,level,tags

查看GC日志

下面是线上的部分gc日志，从GC的间隔时间60、90、115可以看出频率较高，表明应用程序内存分配压力较大，同时新生代 GC 耗时从 0.127秒 增加到 0.715秒

2024-12-18T06:44:01.909+0000: 84819.612: [GC (Allocation Failure) 2024-12-18T06:44:01.910+0000: 84819.614: [DefNew: 1151910K->52843K(1230656K), 0.1256773 secs] 3431287K->2333097K(3965440K), 0.1275887 secs] [Times: user=0.13 sys=0.00, real=0.13 secs] 
2024-12-18T06:45:01.366+0000: 84879.070: [GC (Allocation Failure) 2024-12-18T06:45:01.368+0000: 84879.071: [DefNew: 1143848K->77773K(1230656K), 0.1896575 secs] 3424102K->2362281K(3965440K), 0.1915247 secs] [Times: user=0.18 sys=0.01, real=0.20 secs] 
2024-12-18T06:46:31.906+0000: 84969.609: [GC (Allocation Failure) 2024-12-18T06:46:31.907+0000: 84969.610: [DefNew: 1171725K->67117K(1230656K), 0.1596144 secs] 3456233K->2362116K(3965440K), 0.1615306 secs] [Times: user=0.15 sys=0.01, real=0.16 secs] 
2024-12-18T06:48:27.092+0000: 85084.795: [GC (Allocation Failure) 2024-12-18T06:48:27.093+0000: 85084.797: [DefNew: 1161069K->136703K(1230656K), 0.2665425 secs] 3456068K->2466626K(3965440K), 0.2688204 secs] [Times: user=0.24 sys=0.03, real=0.27 secs] 
2024-12-18T06:48:28.749+0000: 85086.452: [GC (Allocation Failure) 2024-12-18T06:48:28.751+0000: 85086.454: [DefNew: 1230655K->136704K(1230656K), 0.7121741 secs] 3560578K->2689414K(3965440K), 0.7152341 secs] [Times: user=0.38 sys=0.33, real=0.72 secs] 

时间戳：

GC 触发原因：

GC 类型：

内存变化：

1151910K->52843K(1230656K)

3431287K->2333097K(3965440K)

耗时：

user=0.13 ser=0.13 sys=0.00, real=0.13 secs

堆栈快照

直接查看高内存时的内存快照可能无法定位导致高内存占用的对象，可以在项目刚启动时和内存占用很高时分别记录快照，再使用内存分析工具对比，可以比较直观的看到导致内存升高的对象，从而在项目里面快速定位。

生成快照

如果命令成功运行，会在 /tmp 目录下生成名为 heapdump.hprof 的文件，大小跟实际占用的内存差不多，在做导出前可以使用压缩指令压缩提高传输效率

# 查看pid
ps -ef | grep java
# 生成内存快照到指定目录下
jmap -dump:format=b,file=/tmp/heapdump.hprof <pid>
# 压缩
tar -czvf /tmp/heapdump.tar.gz /tmp/heapdump.hprof
# 解压
tar -xzvf /tmp/heapdump.tar.gz

jmap：Java 内存映射工具，用于生成堆转储或打印内存统计信息。

得到的文件转出到本地后解压

IDEA中打开

2024.IntelliJ IDEA 2024.1.3 jprofiler

Run > Open Profiler Snapshot > Open再选择文件即可打开快照文件

jprofiler的使用

下面是打开的效果图，图片下面是解释分析内存界面中的栏目字段含义。

1. Count

2. Shallow

3. Retained

4. Biggest Objects

5. GC Roots

6. Merged Paths

7. Summary

8. Packages

​ 内容太多总结一下分析时比较重要的：

分析Shollow栏下切到 Merged Paths

先选中最大的对象，找到数量最多的类打开，查看Object[]的来源，最终指向的都是nacos下PoolThreadCache对象，并且有一个很反常的现象就是对象的回收java.lang.ref.Finalizer层级非常深根本点不完一直点一直有，并且对比启动时的该对象内存情况升高十分明显，并且右侧这个类的数量也是十分的高；

除此之外在对比时发现com.mysql.cj.jdbc.CallableStatement对象增长也十分明显，它是在sql查询时创建的查询对象，理论上来说它也应该在查询完之后进行销毁，但实际上却没有被回收，不过这个对象被回收的数量也比较多又100多M，jdbc涉及到的配置也有限制，但限制外的预编译对象没有被回收，这个可能也有问题不过这次优化中没有处理内存持续升高是其他问题造成，它的影响不是很大

# 是否开启预编译语句（PreparedStatement）的池化
db.master.poolPreparedStatements=true
# 每个数据库连接可以缓存的 PreparedStatement 对象的最大数量
db.master.maxPoolPreparedStatementPerConnectionSize=10

Retained栏下切到 Merged Paths

切换过去之后问题就很明显，回收对象大小排在前面的都是nacos相关的类，并且内部都是java.lang.ref.Finalizer对象，层级非常深。

java.lang.ref.Finalizer实际是一个对象在创建时都会被一个特殊的 Finalizer 对象所追踪，当一个对象即将被垃圾回收器（GC）回收时，Finalizer 会将该对象标记为可终结的对象，并调用其 finalize() 方法，主要作用就是清理资源和对象回收前的通知机制，finalize() 方法可以用于清理非 Java 堆中的资源，例如关闭文件流、Socket、释放内存等，不过但现代开发中，不建议依赖 finalize() 来做资源清理，因为它的执行时间和顺序不可控，它只是通知或者是建议GC来干活需要进行垃圾回收，但实际上是否进行垃圾回收由JVM 和垃圾回收器控制，同时它也可以让对象在完全销毁之前执行一些逻辑，例如记录日志或释放资源。

到这里初步定位于nacos的使用相关，网上查了一下对于java.lang.ref.Finalizer嵌套较深的原因是：Finalizer线程会和主线程进行竞争，不过由于它的优先级较低，获取到的CPU时间较少，因此它永远也赶不上主线程的步伐。可以参考这篇文章Java的Finalizer引发的内存溢出，仔细一想其实是句废话说白了就是回收垃圾的速度赶不上制造垃圾的速度，实际结果肯定是这样不然也不会有内存持续升高最终溢出的结果，除此之外github上也有帖子nacos客户端2.0.1 PoolThreadCache 内存溢出，说是nacos某些版本的bug并且该问题没有给出解决方案就被关闭了。

由于是nacos相关的问题，所以直接在项目中搜索"nacos."，看哪些类有使用nacos相关的类，结果只有健康检查类里面有相关使用，下面是用到的部分代码，主要逻辑就是获取nacos中所有可用的服务，请求服务的某个接口如果返回数据就代表服务健康状态。

public void checkServiceHealth() throws NacosException {
        SysLogger.info(this.getClass(),"健康检查进入：");
        NamingService namingService = NamingFactory.createNamingService(serverList);
        // 获取所有服务的列表
        List<String> serviceNames = namingService.getServicesOfServer(1, Integer.MAX_VALUE).getData();
        // 遍历所有服务
        for (String serviceName : serviceNames) {
            // 获取指定服务的所有实例
            List<Instance> instances = namingService.getAllInstances(serviceName);
            // 遍历服务的实例
            for (Instance instance : instances) {
              	//......
                // 模拟http请求向服务发送健康检查接口
              ResponseEntity<String> response = restTemplate.getForEntity(serverIp, String.class)
            }
        }
    }

问题就出在代码

NamingService namingService = NamingFactory.createNamingService(serverList)

下面是这个方法的内部代码，通过反射去创建NamingService对象，说明对象并不是单例的每次都会创建一个新对象，而这个方法由于是健康检查使用几分钟就执行一次，时间一长对象就会非常多。尽管这个对象会创建很多但是理论上还是会被垃圾回收器回收掉对内存的影响可能也不会很大，但是问题的关键就在于模拟http请求时的

ResponseEntity<String> response = restTemplate.getForEntity(serverIp, String.class);

RestTemplate 默认使用的是 HTTP Keep-Alive 机制，这是一种复用底层 TCP 连接的机制，可以提升 HTTP 请求的性能并减少资源消耗，但如果跟非单例对象一起可能导致NamingService形成强引用无法被回收。

public static NamingService createNamingService(String serverList) throws NacosException {
        try {
            Class<?> driverImplClass = Class.forName("com.alibaba.nacos.client.naming.NacosNamingService");
            Constructor constructor = driverImplClass.getConstructor(String.class);
            NamingService vendorImpl = (NamingService)constructor.newInstance(serverList);
            return vendorImpl;
        } catch (Throwable var4) {
            Throwable e = var4;
            throw new NacosException(-400, e);
        }
    }

解决

知道了原因修改的话就很简单了，把NamingService的获取方式变成单例就可以了

    @Autowired
    private NamingService namingService;

    // 获取所有服务的列表
    List<String> serviceNames = namingService.getServicesOfServer(1, Integer.MAX_VALUE).getData();

总结

修改之后上线观察cms的内存占用情况改善非常明显，由原来的4个多G变成现在的2G左右，并且稳定在2G左右基本不会升高。本次解决的问题只有NamingService对象较多无法回收的问题，但实际上在分析的过程中也发现了在运行的过程中com.mysql.cj.jdbc.CallableStatement对象增上也十分迅速，由2G内存时的20w增长到4.2G内存时的90w，这个问题并没有在这次优化中处理，后面这个对象肯定会随着时间的推移数量变的越来越多，并且这个对象也不会被垃圾回收器回收，所以可能后面还需要处理这个问题。

本次线上问题的定位与解决都是我同事，在此仅仅是做个记录，我在做分析时我看到了那个引用链非常长的问题，但是并没有引起我的注意，因为我一看这个是nacos的类所以不会有问题如果我们的项目有问题那类似用了nacos的是不是都会有问题，所以直接忽略了在其他地方浪费了很多时间，我想说的是在分析问题时还需要耐心的分析不忽略任何可能的点，定位问题时不能先入为主，想当然的认为某个地方肯定没有问题，因为这样很有可能会漏掉最重要的点，同时告诫自己做事多一些耐心、细心。

以上为个人经验，希望能给大家一个参考，也希望大家多多支持脚本之家。

您可能感兴趣的文章:
阅读全文