1. 起因

A与B云侧模块特性联调的过程中,端侧发现云侧返回有延迟的情况。

7月19日与A模块一起抓包初步判断,B业务有积压的情况。

7月18日已经转侧B业务现网版本,由于使用一套逻辑。故可能存在请求积压的问题。(严重)

2. 定位过程

2.1 复现问题

15路压测大屏发现请求有将近十多秒的时延,对于B业务实时性要求极高的业务,这无疑是灾难性的。

springboot接口请求302 springboot接口请求积压会挂掉吗?_springboot接口请求302

由于B业务最近针对业务并没有修改关键代码,只对springboot等相关第三方包做了升级。对比升级前后日志发现一个线程的名称发生了变化

升级前:

springboot接口请求302 springboot接口请求积压会挂掉吗?_阻塞队列_02

升级后:

springboot接口请求302 springboot接口请求积压会挂掉吗?_阻塞队列_03

 

因为B业务的上传接口采用的是异步回调机制。

升级之前,当springmvc内部有异步回调的时候,每次都会创建线程去处理回调逻辑,即没有线程池的概念,每次都是创建新的线程。线程命名规则是:MvcAsync[xx]

[xx]标示数值,比如MvcAsync1,MvcAsync9,MvcAsync10...

升级之后发现线程名字变成了task-[xx], xx标示数值,似乎只是名称改了,且在长期运行日志中发现task-[xx]也是大体递增趋势。

springboot接口请求302 springboot接口请求积压会挂掉吗?_spring_04

 

2.2 找异常点

后来为了复现问题,我们采用了15路压测,利用Java VisualVM观察CPU,内存,进程等。CPU和内存都ok,但是发现了很奇怪的现象:在压测的时候,为什么task-[xx]不递增,而且只维持8个线程,而我们15路并发,自然是处理不了。

难道task-[xx]是线程池里面的线程?且业务明显很“忙”,为什么不继续创建线程?难道内部真的改成线程池,并且对线程数量做了最多8个线程的限制?

springboot接口请求302 springboot接口请求积压会挂掉吗?_线程池_05

后来我做了单次调用的测试,发现,task-[xx]同一时刻最多有8个线程同时运行,如果一直运行的话,就会复用线程,与之前的每次都创建新的线程完全不同,而且只运行一次的线程的存活时间是大约60秒,这不是keepalive的特性吗?

通过分析可以基本判断异步回调已经不是每次都创建新的线程,而是可能内部有线程池?

springboot接口请求302 springboot接口请求积压会挂掉吗?_spring_06

这些都是分析和猜测,并没有直接的证据说明,而且我们是需要最终去修改问题,如果只是大体猜出问题在哪?但是却不知道如何修改,也是没有办法的。

2.3 确认问题及解决方案

没办法,只能撸代码。

对于springboot我们基本都是当黑盒使用的,代码确实看了大概,但是要完全靠走读代码很难确定问题(面向接口编程一般很难确定具体运行类),所以我们采用了单步调试。撸代码基本可以确定问题对应的代码范围,方便我们调试代码。

为了方便调试,我写了一个简单的demo(个人觉得这个很重要,最好的方式肯定直接利用业务代码调试,但是有的时候我们的业务很庞大或者调试条件比较苛刻)

@RequestMapping("/webAsyncTask")
    public WebAsyncTask<String> webAsyncTask() {
        System.out.println("外部线程:" + Thread.currentThread().getName());
        WebAsyncTask<String> result = new WebAsyncTask<>(6000000L, new Callable<String>() {
            @Override
            public String call()
                throws Exception {
                System.out.println("内部线程:" + Thread.currentThread().getName());
                return "web async task";
            }
        });

        result.onTimeout(new Callable<String>() {
            @Override
            public String call()
                throws Exception {
                return "timeout";
            }
        });

        result.onCompletion(new Runnable() {

            @Override
            public void run() {
                System.out.println("finish");
            }
        });
        return result;
    }

通过走读代码,确定在spring-web-x.x.x.RELEASE.jar包里面的类

org.springframework.web.context.request.async.WebAsyncManager

其中的AsyncTaskExecutor taskExecutort保存异步调度线程的创建方式。

private AsyncTaskExecutor taskExecutor = new SimpleAsyncTaskExecutor(this.getClass().getSimpleName());

默认赋值SimpleAsyncTaskExecutor,这个对象就是每次都创建新的线程去执行异步回调。

我们分别使用springboot-1.5.14.RELEASE和springboot-2.1.3.RELEASE调试代码,对于调试的断点也很重要,到底把断点加在什么地方呢?针对我们的这个问题,加在业务代码里面肯定是看不出问题。有个方法可以大体判断地方,通过线程调用堆栈,如下图(可放大,下同):

springboot接口请求302 springboot接口请求积压会挂掉吗?_spring_07

 

 

断点基本可以确定在WebAsyncManager.startCallProcessing()方法里面

springboot-1.5.14.RELEASE调试截图:taskExecutor就是SimpleAsyncTaskExecutor实例

springboot接口请求302 springboot接口请求积压会挂掉吗?_阻塞队列_08

springboot- 2.1.3.RELEASE调试截图:taskExecutor就是org.springframework.scheduling.concurrent.ThreadPoolTaskExecutor实例,并且是一个线程池corePoolSize=8,keepalive=60sec,maxPoolSize= 2147483647,queueCapacity=2147483647

这些默认值肯定是不合理的。

springboot接口请求302 springboot接口请求积压会挂掉吗?_阻塞队列_09

补充:

(1)corePoolSize: 线程池中的核心线程数,当提交一个任务时,线程池创建一个新线程执行任务,直到当前线程数等于corePoolSize;如果当前线程数为corePoolSize,继续提交的任务被保存到阻塞队列中,等待被执行;

(针对该问题由于队列很大,任务一直在排队,导致新的线程创建不了,而且一直是8个)

(2)maximumPoolSize: 线程池中允许的最大线程数。如果阻塞队列满了,且继续提交任务,则创建新的线程执行任务,前提是当前线程数小于maximumPoolSize

(3)keepAliveTime: 线程空闲的存活时间,即当线程没有任务执行时,继续存活的时间,默认情况下,该参数只在线程数大于corePoolSize时才有用。

(4)workQueue: 必须是BlockingQueue阻塞队列,当线程池中的线程数超过它的corePoolSize的时候,线程会进入阻塞队列进行阻塞等待。

至此才能确定问题是由于springboot升级底层改变了异步回调线程的管理方式。

解决方案,其实我在都读代码的时候已经发现了:即继承WebMvcConfigureationSupport重载方法configureAsyncSupport设置异步回调的线程池或还是采用SimpleAsyncTaskExecutor

@Override
    public void configureAsyncSupport(final AsyncSupportConfigurer configurer) {
        configurer.setTaskExecutor(threadPoolTaskExecutor());
    }

3. 总结

线程池的设置一直都是很重要的问题,而且大多数框架提供的默认线程池针对具体业务基本都是不合理的,顺便吐槽一下,springboot对task-[xx]的命名,没有体现线程池,应该起一个更具功能和意义的名字,比如async-threadpool-2-thread-[xx]