FullGC频繁，线程数持续增长排查

告警

线上应用fullgc频繁，收到告警

GC监控—堆内存不足

查看近12小时的监控，发现Survivor区一直处于 满状态、fullgc非常频繁、但没有内存溢出的现象，很明显是堆内存不足

GC日志分析—暂停时间并不长

因为fullgc相当频繁，抽取了一次fullgc日志分析，发现一次fullgc过程中，暂停时间并不长
例如下面的fullgc，暂停时长为

• 初始标记CMS-initial-mark：0.05s
• 重新标记CMS Final Remark：0.29s

2022-11-22T09:11:30.438+0800: 344102.892: [GC (Allocation Failure) 2022-11-22T09:11:30.440+0800: 344102.894: [ParNew: 1376182K->153600K(1382400K), 0.2052663 secs] 3454603K->2289
346K(4040704K), 0.2088212 secs] [Times: user=0.56 sys=0.01, real=0.21 secs]
2022-11-22T09:11:30.662+0800: 344103.116: [GC (CMS Initial Mark) [1 CMS-initial-mark: 2135746K(2658304K)] 2310318K(4040704K), 0.0489591 secs] [Times: user=0.13 sys=0.01, real=0.
05 secs]
2022-11-22T09:11:30.716+0800: 344103.170: [CMS-concurrent-mark-start]
2022-11-22T09:11:31.347+0800: 344103.801: [CMS-concurrent-mark: 0.631/0.631 secs] [Times: user=1.29 sys=0.03, real=0.64 secs]
2022-11-22T09:11:31.351+0800: 344103.805: [CMS-concurrent-preclean-start]
2022-11-22T09:11:31.366+0800: 344103.819: [CMS-concurrent-preclean: 0.014/0.015 secs] [Times: user=0.03 sys=0.00, real=0.01 secs]
2022-11-22T09:11:31.369+0800: 344103.823: [CMS-concurrent-abortable-preclean-start]
2022-11-22T09:11:31.533+0800: 344103.987: [GC (Allocation Failure) 2022-11-22T09:11:31.535+0800: 344103.989: [ParNew: 1382400K->153600K(1382400K), 0.2068298 secs] 3518146K->2345
666K(4040704K), 0.2097398 secs] [Times: user=0.58 sys=0.01, real=0.21 secs]
2022-11-22T09:11:32.654+0800: 344105.108: [CMS-concurrent-abortable-preclean: 1.058/1.285 secs] [Times: user=2.70 sys=0.04, real=1.28 secs]
2022-11-22T09:11:32.667+0800: 344105.121: [GC (CMS Final Remark) [YG occupancy: 1345792 K (1382400 K)]2022-11-22T09:11:32.668+0800: 344105.122: [Rescan (parallel) , 0.1862920 se
cs]2022-11-22T09:11:32.854+0800: 344105.308: [weak refs processing, 0.0001122 secs]2022-11-22T09:11:32.854+0800: 344105.308: [class unloading, 0.0624232 secs]2022-11-22T09:11:32
.917+0800: 344105.371: [scrub symbol table, 0.0319926 secs]2022-11-22T09:11:32.949+0800: 344105.403: [scrub string table, 0.0032403 secs][1 CMS-remark: 2192066K(2658304K)] 35378
59K(4040704K), 0.2851247 secs] [Times: user=0.65 sys=0.01, real=0.29 secs]
2022-11-22T09:11:32.958+0800: 344105.412: [CMS-concurrent-sweep-start]
2022-11-22T09:11:33.030+0800: 344105.483: [GC (Allocation Failure) 2022-11-22T09:11:33.031+0800: 344105.485: [ParNew: 1382400K->120109K(1382400K), 0.1535558 secs] 3550502K->2343
198K(4040704K), 0.1567270 secs] [Times: user=0.42 sys=0.01, real=0.15 secs]
2022-11-22T09:11:34.931+0800: 344107.384: [CMS-concurrent-sweep: 1.771/1.972 secs] [Times: user=3.94 sys=0.06, real=1.98 secs]
2022-11-22T09:11:34.933+0800: 344107.387: [CMS-concurrent-reset-start]
2022-11-22T09:11:34.942+0800: 344107.396: [CMS-concurrent-reset: 0.009/0.009 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22

Thread监控—线程数持续增长

另一个同学注意到线程监控异常，发现线程数持续增长，处于TIMED_WATING状态的线程也持续增长，
初步怀疑是线程对象较多，且状态处于长时间的TIMED_WATING，所以younggc无法回收，进入老年代，引起频繁fullgc

执行jstack—分析线程

线上执行jstack

使用工具IBM Thread and Monitor Dump Analyzer for Java (TMDA)对stack日志进行分析

线程状态分析

发现

• 线程总数多，6k+
• 91%的线程在等待，Wating on condition，看堆栈，是调用了Thread.sleep

Waiting on condition线程分析

查看状态为Waiting on condition状态的线程，发现几乎都是Druid-ConnectionPool-Destory-xxxx

线程堆栈信息

分析Druid-ConnectionPool-Destory线程

DruidDataSource.init()
->createAndStartDestroyThread()
相关代码如下

        String threadName = "Druid-ConnectionPool-Destroy-" + System.identityHashCode(this);
        destroyConnectionThread = new DestroyConnectionThread(threadName);
        destroyConnectionThread.start();
1
2
3

也就是说，一个DruidDataSource连接池，对应一个Druid-ConnectionPool-Destroy线程
上面的6k左右个Druid-ConnectionPool-Destroy线程，对应了6k左右的DruidDataSource连接池🥶

所以，究竟是哪里创建了这么多连接池？

哪里创建了这么多连接池？

这个应用是bi系统中的数据查询引擎，维护了很多库，约500个，但现在有6k左右的数据库连接池肯定是不对劲的。
后来经过排查，是有个定时检查内存中的连接池与数据库中维护的数据源信息差异的任务，在不断的创建连接池，在某个分支条件下，创建了连接池后，发生异常，但没有及时关闭连接池，导致在后续的定时任务调度中，不断的创建连接池。

结论与方案

关于连接池

对于连接池的维护，部分代码需要优化，尤其是在发生异常时，没有及时关闭连接池。这也是本次告警的主要原因

关于gc

从上面的排查来看gc频繁的问题，应该就是因为数据库连接池频繁创建，没有及时关闭造成的。
但gc日志分析来看gc暂停时间并不长，只是gc整个过程较长
●新生代的s区基本处于满状态，fullgc频繁，但没有内存泄露的现象，很明显是内存不足
●抽取一次fullgc日志分析，发现gc暂停时间不长，是运维告警的问题

若有收获，就点个赞吧