关键词

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-线程居然里面还在跑抛出的异步工作线程的代码。

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