阅读 629

线上服务一直很稳定,最近突然cpu使用率百分百,诡异问题排查

线上某服务一直运行很稳定,最近突然就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连接。这下只能将限流组件sentinelbug的猜测去掉了,因为昨天去掉配置后,也并没有看到sentinel线程占用cpu过高的现象了,只能排除。继续统计redissocket打开数量。

确实对上了,文件句柄数达上限的问题确实是与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的,出异常也会移除缓存,只是清理时间间隔比较长,一个小时才清理一次。

到此,我就不再往下分析了。去掉内存缓存是不可能的,只能计算业务所需要的内存,提升实例的内存。通过数据库查询,估算需要缓存的记录数是四百多万,本地写了个测试用例,计算四百多万记录大概消耗700m的内存,因此,只需要将机器的内存稍微提高一点就没有问题了。

但是我想不通的是,redis连接文件句柄数为什么会如此高呢,不是用了连接池,是fgc影响了什么吗?STW也不至于导致redis文件句柄打开这么多吧?如果您知道,非常希望您能留言帮我解答下疑惑,感激不尽!

文章分类
阅读
文章标签