Press "Enter" to skip to content

记一次线上java生产事故(CallerRunsPolicy)

关键词

ThreadPoolExecutor.CallerRunsPolicy()

起因

早晨上班不久后,突然系统告警,商品服务延迟特别大。

由于其他几个后端服务和商品服务的依赖关系特别大,导致其他服务接连奔溃。由于目前各个系统没有做服务降级,在依赖服务(商品服务)出现阻塞,延迟响应缓慢之后,自身服务也出现阻塞现象。

后端服务接连奔溃,前端业务系统马上感受到影响,逐个失能。

处理

马上导出线上应用的线程栈分析,

"http-nio-8020-exec-49@23084" daemon prio=5 tid=0x2af nid=NA runnable
  java.lang.Thread.State: RUNNABLE
	  at java.net.SocketInputStream.socketRead0(Unknown Source:-1)
	  at java.net.SocketInputStream.socketRead(Unknown Source:-1)
	  at java.net.SocketInputStream.read(Unknown Source:-1)
	  at java.net.SocketInputStream.read(Unknown Source:-1)
	  at java.net.SocketInputStream.read(Unknown Source:-1)
	  at redis.clients.util.RedisInputStream.ensureFill(RedisInputStream.java:196)
	  at redis.clients.util.RedisInputStream.readByte(RedisInputStream.java:40)
	  at redis.clients.jedis.Protocol.process(Protocol.java:151)
	  at redis.clients.jedis.Protocol.read(Protocol.java:215)
	  at redis.clients.jedis.Connection.readProtocolWithCheckingBroken(Connection.java:340)
	  at redis.clients.jedis.Connection.getBinaryBulkReply(Connection.java:259)
	  at redis.clients.jedis.BinaryJedis.get(BinaryJedis.java:244)
	  at org.springframework.data.redis.connection.jedis.JedisConnection.get(JedisConnection.java:1215)
	  at org.springframework.data.redis.connection.DefaultStringRedisConnection.get(DefaultStringRedisConnection.java:296)
	  at sun.reflect.GeneratedMethodAccessor293.invoke(Unknown Source:-1)
	  at sun.reflect.DelegatingMethodAccessorImpl.invoke(Unknown Source:-1)
	  at java.lang.reflect.Method.invoke(Unknown Source:-1)
	  at org.springframework.data.redis.core.CloseSuppressingInvocationHandler.invoke(CloseSuppressingInvocationHandler.java:57)
	  at com.sun.proxy.$Proxy503.get(Unknown Source:-1)
	  at org.springframework.data.redis.cache.RedisCache$2.doInRedis(RedisCache.java:319)
	  at org.springframework.data.redis.cache.RedisCache$2.doInRedis(RedisCache.java:315)
	  at org.springframework.data.redis.cache.RedisCache$AbstractRedisCacheCallback.doInRedis(RedisCache.java:565)
	  at org.springframework.data.redis.core.RedisTemplate.execute(RedisTemplate.java:207)
	  at org.springframework.data.redis.core.RedisTemplate.execute(RedisTemplate.java:169)
	  at org.springframework.data.redis.core.RedisTemplate.execute(RedisTemplate.java:157)
	  at org.springframework.data.redis.cache.RedisCache.lookup(RedisCache.java:314)
	  at org.springframework.data.redis.cache.RedisCache.get(RedisCache.java:184)
	  at org.springframework.data.redis.cache.RedisCache.get(RedisCache.java:133)

我们拿到的一手线程栈其中发现一堆奇怪的线程,线程名前缀http-nio-8020-exec-指示该线程是Tomcat为我们创建的一个用来处理前端http接口请求的工作线程。截图我暂时省略了栈低的业务代码,可以看到栈顶显示,我们的redis客户端正在读数据,很多线程都这样,都是runable状态,都在读redis数据或者等待度。

这里犯了一个误导我们排查的严重错误

由于我们之前在解决商品服务时,遇到过这种服务慢的情况,当时是因为springboot的缓存框架在redis里面写入了一个锁(结构类似:*~lock)结果异常退出了,没解锁。然后后续请求都尝试来加锁,失败,所以卡主整个系统了。

这里我们看到拿到的线程栈,一看,啊?!!这么多http请求线程,栈顶都在读redis啊!!我靠redis卡住了?又出现上次的锁了?为啥redis慢啊?

  • 我们去redis查了一通,发现并没有类似锁出现。
  • 我们去redis查了慢查询,发现并没有明显的慢查询现象,只要零星的一个eval函数执行的什么指令有点慢。
  • 用命令或者工具在redis查,redis发现并不慢

这时部分人员开始把查问题关注到redis里面发现的eval函数跑的lua脚本到底在干啥(事后证明,这个玩意只是管理端在清理redis缓存,量其实不大)

我们此时疯狂怀疑redis

首先,我们线程栈的栈顶都是redis的读在等待,其次我们之前遇到过几次,感觉都和redis有关联。

我们尝试了多种办法,尝试将redis重新在新机器部署、尝试将商品的redis根据功能拆成多个redis和多个服务组合,降低单个redis负载、尝试将Redison(分布式锁单独配置的)移除、尝试将感觉有问题的redis缓存注解移除。

感觉是一通操作猛如虎,效果不明显,甚至更差了。

奔溃边缘,数据库负载高

怎么办呢?哪里出了问题,大家没有头绪,此时运维同事反馈,数据库的负载非常高,但是看不到数据库在跑什么语句,不知道数据库在跑什么。现象就是连接数高,是过去平时的好几倍,数据库的负载高,load 已经到40了。(这里很奇怪了,为什么看不到数据库在跑什么?那么为什么负载这么高)

重启数据库

此时某位领导表示,都这个逼样了,重启数据库,杀链接看看。一通操作,发现没效果。

断开MQ消费

尝试本地开发机器连接生产数据库和redis进行调试,发现本地应用启动后非常不正常。看到网卡流量异常,上下行跑到20M以上。和项目开发确认后得知,应用要消费MQ的数据,处理解锁库存业务。我本地尝试将消费MQ的bean注释掉,反复尝试终于把本地的应用启动好,负载正常,查询本地的接口发现还是不快,有点慢。发现本地连等待数据库返回特别慢,等待redis返回也慢,尝试将生产流量引入本地还是慢。

按道理说,应用的查询基本上都优化的走redis了,即使说目前生产环境的MySQL高的离谱虽然没法解释,那如果查询都走的redis应该不受影响啊?再者说,我们从本地的控制台发现redis也不慢,查询都正常,也没有明显慢查询。

尝试本地启动redis

本地启动redis,链接生成数据库,我发现似乎查询比之前有明显提升了,这也合乎情理,正当准备进一步调试。被告知这也可能会污染生成数据,暂停调试。

外援支持

因为事故已经持续大半天了,此时已经是下午了。大领导已经坐不住了,跑到我们办公室来”慰问“我们。此刻我们压力大的一笔,然后一通交流,要求找外援协助排查,此刻大家内心五味杂陈。

个人感觉,这种情况,除非外援能现场支持,只通过电话沟通,排查这种问题,真的是没啥希望。外援简单了解了一些redis的连接池,服务器配置,连接数状况(可能我们给的信息干扰,我们给的信息是redis查询慢,其实根结不是redis问题)。最后感谢了下外援,便挂断电话。

继续分析线程栈

此时已经差不多到下班时间了,系统依然非常不稳定,奇怪的简直离谱。按说系统其实此时的负载量是非常非常的低的了,已经没什么请求流量了。但是又害怕故障随着流量小自动解除了,那就完蛋了,就像眼看着特洛伊混进城了,不知道什么时候会爆炸,大家都在和时间赛跑。

一步步分析缓慢接口逻辑,查找哪里慢

回过头去看线程栈,很多http线程都被卡在redis读的地方(快照的时刻点,这里的理解有误区,误解到自己了),还是那个样子。开始本地启动调试模式,发现一个简单的查询就要好久,代码也很有意思,查询一个商品要去redis捞20多次,好夸张。

现在去改程序也不现实,逻辑确实复杂的很。也不能解释前几天一直都是好的,为什么今天就炸了。虽然代码看起来很蛋疼,redis交互的那么热,但是为什么之前是好的,今天突然炸了?本地调试了很久,发现其实底层和redis的速度并不慢,都是毫秒级返回。

此刻我好戏明白了我之前对redis慢的误区,我开始和同事解释为什么每次快照,都是卡在redis读的地方。我们系统的设计和redis的交互太频繁了,导致我们每次快照的点,正好都落在redis身上。

可能redis并不是慢,是我们程序慢,数据库负载高。

搭建redis集群,准备切换

不管怎样,部分同事建议拆分redis和redis集群,来解决redis慢的问题。拆分redis之后发现效果并不明显,redis集群也在准备中。。。。

系统的IO异常

此时我已经感觉到奔溃,开始怀疑是不是硬件问题,内存问题等等。。

另一个同事建议抓包分析,结果运维同事抓了1分钟包,告诉我们抓了4个多G的数据。。。。。

我表达了极大的震撼,我靠,你这个系统兼职是,是不是在用磁盘挖矿啊。我表达了自己的震惊,然后被同事取笑没做过业务系统,说这个数据量是正常的,我无法理解这种现象。因为这个时间点已经是我们系统的低负载时刻了,哪来这么大的数据量。

我表示这么大的数据,没法分析的,暂时不要把抓包dump发给我了,我想看看服务器到底在跑什么东西,这么大流量。

尝试在服务器装iftop,也搞了半天,服务器是centos6版本,各个厂商的epel6都已经不维护了,想从源码编译,发现gcc版本太低,生产机器又不敢瞎升级,最后找了半天发现腾讯云的epel6(https://mirrors.cloud.tencent.com/help/epel.html)居然还能用,腾讯牛逼。装好了iftop之后发现,我靠简直了,应用在疯狂的从MySQL和Redis倒数据,在两个库之间疯狂的倒数据。峰值带宽已经跑到600多兆了,这已经超过我的理解了。

线程栈异常,准备关闭写ES行为,写ES前拼装dto耗时

衔接前面发现很多异常线程都是在执行写入ES操作。

领导让项目组立马在代码里面关闭这块逻辑,暂时不要写入ES了,观察系统状况。做了这个操作后,系统负责瞬间掉下来了,系统恢复了!

分析发现,商品服务在锁定库存后需要将更新过的库存信息写入到ES服务,写入前需要拼装一堆逻辑非常的耗时。这里使用了spring的异步事件机制,使用了定大小线程池,阻塞策略为:

ThreadPoolExecutor.CallerRunsPolicy()

该策略会导致,如果线程池的线程用完之后,会在同步的请求线程里面完成这次的异步耗时操作,倒是请求线程池阻塞,响应慢,或者是请求处理失败。

我们又梳理了一圈线程栈异常,发现好多线程栈里面都有这个写入es的代码。

这也就解释了,为什么这个锁定库存的接口有的非常快(线程池还有线程,异步处理),还有的非常慢(线程池用完,同步线程处理)。

转机,关闭写ES功能,速度提升

这样一关,瞬间系统恢复了往日的流畅。大家脸上都挂满了笑容,开始互相唏嘘,早就发现了哪哪不对劲,如果再细心下就早就解决了问题。哎。。。难受

定位问题、解决方案

问题定位,解决方案就简单了,将这个异步操作彻底异步化,将需要处理的数据丢给MQ,处理单独消费线程来处理MQ数据,将这个异步任务做到可配置是否启动,单独启动节点来消费这个MQ数据。

问题回归

  • 看起来,大家都赞同的意见是,同步线程太少了,耗时的异步处理也跑到同步线程来处理了,导致系统处理速度慢,系统拖死。

这里其实可以说几句。

为什么之前系统好好的?今天突然不行了?炸的这么彻底?

其实同样的问题在两天前发生过,系统非常卡,当时我们线程栈分析,也都是很多线程都在等待MySQL数据库连接。当时发现有个异步线程池居然有100个线程都在处理东西,每个线程都在redis读,也持有MySQL连接。当时就断言,这什么叼线程池,怎么搞这么多线程来处理异步任务。全部都持有数据库连接,当然正常的请求就拿不到数据库连接了。

然后当时就让业务系统将这个池改小(改为20),然后昨天发布了这个改动。这个看似合理的改动也是压死系统的最后一根稻草。

处理这个异步任务的线程少了,因为系统本身的Tomcat处理线程也就默认200个,这种锁定数量多了之后,这个锁定工作又非常的慢,异步线程用完之后,由于线程池的策略是用完之后,使用创建线程来进行异步任务。导致主线程非常慢,系统可用性降低。

这里警醒下,上次发现问题之后的处理方案定的太草率了,单纯的看了线程池大小,进行线程池的线程数量调整,没有评估到带来的后续影响。

  • 一点疑问,即使这个线程数量调小了,为什么系统负载在外部请求明显降低之后还这么高?这个异步任务到底在干什么,为什么有这么大的io?

这真的很奇怪,太多问题需要被去刨根问底。

  • 反思为什么这个问题排查了一天了,所有信息我们都能拿到了,远程debug,本地debug,各种数据都有。

这里警醒下,什么是线程栈,该如何去看。

使用jstack打印的线程栈只是jvm在某一个时刻点的状态,某一个时刻的状态。我们在分析问题的时候要切记这一点,我们要知道什么是时间点,什么是时间线,我们不能盯着某一个时刻点的状态,就断定什么。

比如我们的线程栈大部分线程都在某一个时间点的状态是在redis读,我们作为事后诸葛来分析,这是合理的。我们的系统真的是redis的io密集型系统。系统大部分时间都在做redis的io操作,所以你随便拍个照片,看到线程在redis读,你就解读为”啊!是redis卡住了!“这样的分析是极不合理的。

那应该怎样做? 我们应该在捕捉线程栈快照时,捕捉到每个线程是什么时间创建的,看看到底哪个线程创建了多久,在跑什么玩意。

还是要自己的看线程栈,其实作为时候诸葛,线程栈都已经把问题的本质写的很清楚的在线程栈里面了。http-nio-线程居然里面还在跑抛出的异步工作线程的代码。

但是怎么说呢,还是经验不足吧,无他

发表评论

邮箱地址不会被公开。 必填项已用*标注