进程还在，JSF接口不干活了，这你敢信？

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）做好监控，能第一时间发现问题并处理问题。

审核编辑 黄宇