记一次线上tomcat worker线程在一个流量高峰后居高不下的问题及排查解决过程

一天晚上有一个跑批任务要执行，这个任务可能会引发一个较大的流量并发到我们的一个应用服务。
果然不出意外，当天晚上9点半，这个应用服务的某个接口每秒请求量到达了150左右。这时调用方出现
大量等待超时，我们的这个应用服务则报出了大量获取数据库连接超时的异常。翻开日志一看原来是数据
库连接池Hikari从连接池获取空闲连接超时了。至于为什么Hikari会获取连接超时，后面分析。
    好在这种高并发的访问只是顺时的，5分钟后恢复了平静报警也消失了，但问题并没有就此结束。不
一会正常的业务访问该接口也频繁出现超时，但这时的并发却不超过10啊，怎么会出现这么奇怪的现象呢，
通过skywalking链路监控工具查看调用链发现是上游rpc调用等待超时时间是15秒，而我们服务处理时间
超过了20秒，再配合在Kibana上查询相关访问日志，发现是上游请求发出后将近20秒，请求才进入处理流
程。我的第一反应就是tomcat的处理请求的worker线程不够用了，使请求进入了等待队列，但现在并发又
不高为什么会worker线程不够用了。赶紧去Grafana面板查看我们应用的当前运行状况，不看不知道一看
吓一跳，当前处于busy状态的tomcat worker线程已经高达192了，而我们设置的tomcat maxThreads
为200。事情不简单啊，基本上确认是刚才瞬间高并发导致的，因为之前时间线busy线程都不超过10。
    为什么会导致这样的情况呢，先来不及思考这些问题了，先让服务恢复正常才首要任务。赶紧联系运维
帮忙重启应用，并在重启前做好dump。重启后tomcat busy线程数恢复了正常，接口超时现象也没有了。
接下来就该分析为什会经过一个流量高峰后，tomcat 线程池中的线程为什么得不到回收并且处于非空闲
状态。拿到dump文件后，分析了下当时的线程状态，发现tomcat worker线程都阻塞在了future.get()
这个方法上，看到这基本明白咋回事了。我们的项目使用axon异步框架，类似于事件驱动，在有实体需要
创建时会发出一个command然后axon进行异步处理。这里的问题出在使用了axon的分发事件的方法
sendAndWait(command) 却没设置超时时间（前人写代码的时候估计任务这个方法会有默认超时时间了），
然后axon的异步线程在获取数据库连接时超时抛出了异常，却没给future设置result,即没调用
completeValue()方法以通知被阻塞的线程（我觉得这是axon框架的一个坑），导致tomcat worker
线程一直被阻塞，最终造成192个线程被阻塞。
    就算并发过两百也不至于数据库连接池被被撑爆吧，一查原来是Hikari没给配置连接池最大连接数，
然后Hikari默认的最大的连接池数目是10，然后我们这个应用只部署了两个实例，也就是说整个服务最
多可用20个数据库连接，所以最后导致大量拿去连接池连接超时。
    最后将代码中用到sendAndWait(command)的地方改为sendAndWait(command,30,TimeUnit.SECONDS)，
并将Hikari的maximumPoolSize调大。
    总结，在调用阻塞方法的时候一定要格外注意，特别注意是否可能被永久阻塞，再就是使用新框架时，
一定要对其有比较深入的了解。