1、问题背景:
应用在配合R2m升级redis版本的过程中,上游反馈调用接口报错,RpcException:[Biz thread pool of provider has been exhausted],通过监控系统和日志系统定位到现象只出现在一两个节点,并持续出现。第一时间通过JSF将有问题的节点下线,保留现场,业务恢复。
报错日志如下:
24-03-13 02:21:20.188 [JSF-SEV-WORKER-57-T-5] ERROR BaseServerHandler - handlerRequest error msg:[JSF-23003]Biz thread pool of provider has been exhausted, the server port is 22003
24-03-13 02:21:20.658 [JSF-SEV-WORKER-57-T-5] WARN BusinessPool - [JSF-23002]Task:com.alibaba.ttl.TtlRunnable - com.jd.jsf.gd.server.JSFTask@0 has been reject for ThreadPool exhausted! pool:80, active:80, queue:300, taskcnt: 1067777
2、排查步骤:
从现象开始推测原因,系统启动时,会给JSF线程池分配固定的大小,当线程都在工作的时,外部流量又打进来,那么会没有线程去处理请求,此时会有上述的异常。那么JSF线程在干什么呢?
1)借助SGM打印栈信息
2)分析栈信息
可以用在线分析工具:http://spotify.github.io/threaddump-analyzer/
2.1)分析线程状态
通过工具可以定位到JSF线程大部分卡在JedisClusterInfoCache#getSlaveOfSlotFromDc方法,如图:
2.2)分析线程夯住的方法
getSlaveOfSlotFromDc在方法入口就需要获取读锁,同时在全局变量声明了读锁和写锁:
此时对问题有一个大体的了解,大概推测:getSlaveOfSlotFromDc是获取redis连接池,该方法入口处需要获取读锁,由于读锁之间不会互斥,所以猜测有业务获取到写锁后没有释放。同时读锁没有设置超时时间,所以导致杰夫线程处理业务时卡在获取读锁处,无法释放。
2.3)从业务的角度分析持有写锁的逻辑
向中间件研发寻求帮助,经过排查,定位到有个更新拓扑的定时任务,执行时会先获取写锁,根据该消息,定位到任务的栈信息:
代码截图:
图1
图2
图3
从日志验证:日志只打印更新拓扑的日志,没有打印更新成功的日志,且02:20分以后r2m-topo-updater就不在打印日志
2.4)深入挖掘原因
虽然现象已经可以推测出来,但是对问题的原因还是百思不得其解,难道parallelStream().forEach存在bug?难道有远程请求,没有设置超时时间?...
经过查找资料确认,如果没有指定,那么parallelStream().forEach会使用ForkJoinPool.commonPool这个默认的线程池去处理任务,该线程池默认设置(容器核心数-1)个活跃线程。同时caffeine数据过期后会异步刷新数据,如果没有指定线程池,它默认也会使用ForkJoinPool.commonPool()来执行异步线程。那么就有概率出现获取到写锁的线程无法获取执行权,获取执行权的线程无法获取到读锁。
2.5)验证
3个ForkJoinPool.commonPool-worker的确都夯在获取redis连接处,线程池的活跃线程都在等待读锁。
本地caffeine缓存没有设置自定义线程池
topo-updater夯在foreach业务处理逻辑中
3.复盘
1)此问题在特定的使用场景下才会小概率出现,非常感谢中间件团队一起协助定位问题,后续也将异步更新拓扑改为同步处理。
2)Java提供了很多异步处理的能力,但是异常处理也代表需要开启线程或者使用共用的线程池,也需要注意。
3)做好监控,能第一时间发现问题并处理问题。