tomcat线程数快速增长问题排查

vlambda
2020-07-14

tomcat线程数快速增长问题排查

时间线

2020-07-11 17:40:00 hotfix修复版本上线

2020-07-11 17:50:00 用户反馈页面无法访问，所有的请求全部爆502 bad gateway , 显示连接不上后端服务了

2020-07-11 17:54:00 运维第一反应给予系统重启

2020-07-11 17:57:00 系统再次宕机，版本回滚

排查过程

查看grafana应用监控，可以很明显的看到，tomcat线程数在短时间内快速上升，很快到了500 ，到了500之后

系统不在接受请求，整体的QPS瞬间下降，CPU利用率也不高（图中CPU飙升的地方是系统发版本导致的，由于这是一个很大的项目，启动时编译类会导致CPU升高）。

查看JVM线程情况，后台守护线程也是瞬间增长

tomcat线程数快速增长问题排查

查看系统GC情况

tomcat线程数快速增长问题排查

GC次数也非常平稳

后面查看系统的数据库CPU，慢查询，网络流量，都很正常。

由于服务器被瞬间重启了，当时的堆栈信息没有保存下来。只能新开一个节点，由于是修改BUG的版本，可以和线上的旧版本同时跑，新节点加入负载，继续观察

新节点启动后一直运行正常，直到下午3点多，tomcat线程开始飙升了，通知运维这台机器的负载下掉

tomcat线程数快速增长问题排查

导出线程栈信息

jstack -l 13454 >> 123.txt

这里介绍一个堆栈分析工具

https://gceasy.io/

tomcat线程数快速增长问题排查

可以看到http的线程数有212个，点进去查看线程栈的具体信息, 可以看到线程是等待状态，阻塞在了获取redis连接，程序入口是HealthEndpoint , 由这里可以猜测出是springboot的健康检查接口，去检查redis是否可用，但是没有获取到redis的资源，导致一直阻塞

tomcat线程数快速增长问题排查

通过阅读源码发现，这里使用的还是老的Jedis连接池，没有设置最大等待时间。

默认borrowMaxWaitMillis=-1 , 因此走的是阻塞队列的take方法，而不是走的poll， take会阻塞当前线程。

/actuator/health 这个接口我们运维拿来做阿里云SLB负载检查的接口了，这个从SLB那边过来的请求，有7-8个QPS（PS：运维说不可以改，改不动，也是好无奈）, 请求非常频繁，猜测是由于jedisPoll资源紧张，加上这个检测接口调用过于频繁。导致竞争不到连接池资源，因此发生请求线程一直阻塞，最终导致tomcat请求无法响应。

修改方案

设置JedisPoll的maxWaitMillis = 3000。

关闭actuator对redis的检查 , 没办法，为了避免再出现，这个接口调用这么频繁，目前先禁用掉

management:
  health:
    redis:
      enabled: false

配置加上，上线观察，一个小时后，上线后发现系统报错，但是错误信息为

显示获取不到连接，这个是因为设置了maxWaitMillis，所以系统不再是阻塞，而是报错了，拿不到连接了。

既然是连接池的资源不够用，那么问题就好解决了，修改配置，排查代码不规范的地方

@Component
@Slf4j
public class OrderSynEvent implements ApplicationListener<ContextRefreshedEvent> {

    @SneakyThrows
    @Override
    public void onApplicationEvent(ContextRefreshedEvent contextRefreshedEvent) {
        executor.execute(() -> {
            while (true) {
                log.info("");
                try {
                    // 此处使用了阻塞方式获取list里面的元素
                    Object o = operation.rightPop(RedisConst.ORDER_ZERO_LOAD_SYN_STATE_LIST, 0, TimeUnit.SECONDS);
                } catch (Exception e) {
                    log.error("",3);
                }
            }
        });
    }
}

上面线程里面的代码没有什么问题，但是在onApplicationEvent里面去new线程，会new出来很多个的，经过测试，这个线程在spring启动之后会new出来5次（因为当前类可能会被多个上下文加载），因此系统里面会有5个线程阻塞的去获取list的元素，根本原因应该不是这个，但是这个不规范的使用，会导致redis里面的线程池资源被占用，直接修复。

同时修改redis的配置，最终配置如下

<bean id="jedisPoolConfig" class="redis.clients.jedis.JedisPoolConfig">
        <property name="maxIdle" value="300"/>
        <property name="maxWaitMillis" value="3000"/>
        <property name="testOnBorrow" value="true"/>
        <property name="testOnReturn" value="true"/>
        <property name="minIdle" value="10"/>
        <property name="testWhileIdle" value="true"/>
        <property name="timeBetweenEvictionRunsMillis" value="3000"/>
        <property name="numTestsPerEvictionRun" value="10"/>
        <property name="minEvictableIdleTimeMillis" value="60000"/>
 </bean>