spring-boot web 项目启动后，线程中有异步操作的话，第一次 HTTP 请求会超时很久是怎么回事？

大致上的代码结构是

@RestController
class ApiClass{

    Logger logger = LoggerFactory.getLogger("log");
    
    @Autowired
    ApiService apiService;
    
    @RequestMapping(value = "/api")
    public String doApi{
        logger.info("HTTP 请求  ");
        String result = apiService.doService();
        return ResponseUtil.jsonSuccess(result); //这里产生类似下面日志中的 json 串
    }
     
}

@Service
class ApiService{
    
    @Transactional
    String doService(){
        logger.debug("测试 1 处");
        。。。
        logger.debug("测试 2 处");
        LocalThread.FIXED_THREAD_POOL.execute(new Runnable() {
                @Override
                public void run() {
                    doAsync();  //大量数据库操作
                }
            });
        logger.debug("测试 3 处");
        。。。
        logger.debug("测试 4 处");
        return "xxxx";
        
    }

}

其中
public class LocalThread {
    public static ExecutorService FIXED_THREAD_POOL = Executors.newFixedThreadPool(5);
}

2017-10-12 16:24:22,407 INFO  - HTTP 请求  
2017-10-12 16:26:02,943 DEBUG - 测试 1 处
2017-10-12 16:26:03,022 DEBUG - 测试 2 处
2017-10-12 16:26:03,024 DEBUG - 测试 3 处
2017-10-12 16:26:03,069 DEBUG - 测试 4 处

下面是 spring-boot 日志
2017-10-12 16:26:03,565 [http-nio-8070-exec-1] DEBUG [org.springframework.web.servlet.mvc.method.annotation.RequestResponseBodyMethodProcessor] - Written [{"code":"2001","message":"成功","body":[{"data":"xxxx"}] as "text/html" using [org.springframework.http.converter.StringHttpMessageConverter@2bdd8394]

但是之后的请求：

2017-10-12 17:28:48,323 INFO  - HTTP 请求
2017-10-12 17:28:48,324 DEBUG - 测试 1 处
2017-10-12 17:28:48,330 DEBUG - 测试 2 处
2017-10-12 17:28:48,330 DEBUG - 测试 3 处
2017-10-12 17:28:48,332 DEBUG - 测试 4 处

2017-10-12 17:28:48,337 [http-nio-8070-exec-1] DEBUG [org.springframework.web.servlet.mvc.method.annotation.RequestResponseBodyMethodProcessor] - Written [{"code":"2001","message":"成功","body":[{"data":"xxxx"}] as "text/html" using [org.springframework.http.converter.StringHttpMessageConverter@2bdd8394]

其中，我注意到：

1 第一次请求从 controller 跳转到 service 都花了将近 2 分钟而之后的请求没这样

2 第一次请求，从测试 1 到日志打出返回 json，花了将近 0.6 秒，而第二个则是 0.01 秒左右

为何差别这么大？

esolve

2017-10-12 19:09:45 +08:00

用 IDE 在本地运行没这么大延时
然后发现，pom 里的版本是

<plugin>
<groupId>org.apache.maven.plugins</groupId>
<artifactId>maven-compiler-plugin</artifactId>
<configuration>
<source>1.8</source>
<target>1.8</target>
<showWarnings>true</showWarnings>
</configuration>
</plugin>

本地环境是 1.8
但是在部署环境中

java -version
java version "1.7.0_55"
Java(TM) SE Runtime Environment (build 1.7.0_55-b13)
Java HotSpot(TM) 64-Bit Server VM (build 24.55-b03, mixed mode)

这个影响这么大吗？

esolve

2017-10-13 11:19:10 +08:00

@WinterWu

开了 trace，但是这两分钟的跳跃，中间没有任何信息。。。

2017-10-13 11:12:49,017 [http-nio-8070-exec-1] DEBUG [org.springframework.jdbc.datasource.DataSourceTransactionManager] - Creating new transaction with name [com.eversec.centertool.modules.woapi.service.WoApiService.getActivityVo]: PROPAGATION_REQUIRED,ISOLATION_DEFAULT,readOnly; ''
2017-10-13 11:14:29,541 [http-nio-8070-exec-1] DEBUG [org.springframework.jdbc.datasource.DataSourceTransactionManager] - Acquired Connection [ProxyConnection[PooledConnection[com.mysql.jdbc.JDBC4Connection@3440eaa3]]] for JDBC transaction