服务提供者假死，记一次full gc问题排查

本篇文章写于2020年01月18日，从公众号同步过来（博客搬家），本篇为原创文章。

线上某服务一直运行很稳定，最近突然就cpu百分百，rpc远程调用全部失败，并走了mock逻辑。重启后，一个小时后问题又重现。于是dump线程栈信息，但不仔细看也看不出什么问题。于是就有了一番排查历程。

前一天，我dump线程栈信息后发现占用cpu高的线程是阿里的限流组件sentinel，并根据线程栈信息知道，在sentinel控制台会拉取该服务的qps统计信息。这个接口会读取本地文件内容，因为qps信息是输出到/root/logs/csp/目录下的某个文件的，并且是用NIO方式读取文件。因此我猜测是sentinel在某种条件下会触发死循环bug，也就能解释得清楚为什么cpu会出现百分百的使用率。

带着这个猜测，我调试了一遍源码，也并未复现。于是我将限流功能暂时去掉，以为问题就能解决，但是没想到第二天早上又看到这个问题。于是我先将该服务的其它节点重启，留下一个节点，并将剩下的节点从注册中心中剔除。可没想到的是，注册中心已经没有这个节点了，应该是所有该服务的节点都与注册中心失联了，其它是因为重启之后重新注册到注册中心的。

既然没有注册到注册中心，其它服务调用直接走mock逻辑也解释得通。继续前一天的进度，我首先是查看文件句柄数是否打开很多，于是使用lsof查看，果然不出所料。

进程15567打开的文件句柄数20多万，因此我更愿意相信是sentinel读取文件出现bug的猜测，因为我想起前一天限流功能还没有完全去除，只是去除了限流配置。接着查看这个进程是否打开了/root/logs/csp目录下的文件（这个目录是从限流组件的源码中找出来的）。

遗憾的是看不到每个文件的打开数量。接着我用lsof -p 进程id命令查看下，该进程打开的文件句柄信息。

于是我发现打开最多的不是/root/logs/csp目录下的文件，而是redis连接。这下只能将限流组件sentinel有bug的猜测去掉了，因为昨天去掉配置后，也并没有看到sentinel线程占用cpu过高的现象了，只能排除。继续统计redis的socket打开数量。

确实对上了，文件句柄数达上限的问题确实是与redis-cluster有关。于是我使用redis-cli命令连接上redis服务，看下是否连接数增多了，是否与该进程持有的文件句柄数对得上。因为前一天我也发现某消息消费服务偶尔出现连接超时的情况。

然而并未发现什么异常，客户端连接数与平常一样。只能悬于此了。于是我又去分析线程栈信息，发现大量的dubbo线程处于wait状态，且都是阻塞在归还redis连接到连接池以及从连接池中申请连接这一步。

还有少数几个dubbo线程当前是runing状态，原因是这些线程走了内存缓存。代码中我是用aop实现内存缓存的，命中内存缓存的不会往下走业务逻辑，也就不会用到redis。因此这些线程处理的请求是正常的。

那么为什么cpu会百分百呢？大片的业务线程都已经被阻塞住了，都在wait状态，到底是什么线程占用如此高的cpu。于是我才想到用top命令去查看。

看到两个非业务相关的线程，占用非常高的cpu，于是又回去琢磨线程栈信息，与top命令显示的command列对得上的也就只有两个垃圾回收线程。

于是就是jstat命令查看gc垃圾回收情况。

连续使用jstat命令查看gc情况，发现每次执行命令，大概是1秒多，fgc的次数就加1了。问题的真相已经非常接近。找到这里，接着就是排查业务代码。

由于使用了内存缓存，会导致full gc的情况很正常。我首先想到两点，一是缓存数据太多，二是缓存数据清理的定时任务执行失败了。

由于之前该服务一直很稳定，猜测可能是数据格式不正确触发的bug，导致数据清理失败，越积越多。但是看了代码后，我是加了try-catch的，出异常也会移除缓存，只是清理时间间隔比较长，一个小时才清理一次。那么就是数据量暴增的原因。

到此，我就不再往下分析。去掉内存缓存？那就需要加好几台机器来扛下目前的并发数，而且还需要添加Redis节点，想想也是不可能的。所以只能计算业务所需要的内存，提升实例的内存。

通过数据库查询，估算需要缓存的记录数是四百多万，本地写了个测试用例，计算四百多万记录大概消耗700多m的内存，因此，只需要将机器的内存稍微提高一点就没有问题了。除非数据量还会暴涨，这也是某个业务功能的实现导致的。