Springboot第一次访问慢，自身缺陷问题？

技术交流
1

一、现象：

1、访问controller，第一次速度在300-400ms，第二次访问就很快了大概在20ms，相差几十倍，是哪里出了问题，尝试了网上很多教程都没有作用 如启动参数设置 -Djava.security.egd=file:/dev/./urandom 等等 ， 这个是自身有BUG还是怎么回事，为什么会影响第一次访问， 后续哪个时间点还会不会出现这个影响。 有没有版本解决？ 使用的内置Tomcat，版本：9.0.52， springboot版本 2.5.4

2、这个controller里面没有任何逻辑，只是一个输出字符串

@RestController
@RequestMapping("/Test")
public class MyTest {

    @GetMapping("/index")
    public String index(){
        return "ssddd";
    }
}

3、项目依赖仅仅只是springboot自己的

<?xml version="1.0" encoding="UTF-8"?>
<project xmlns="http://maven.apache.org/POM/4.0.0"
         xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
         xsi:schemaLocation="http://maven.apache.org/POM/4.0.0 http://maven.apache.org/xsd/maven-4.0.0.xsd">
    <modelVersion>4.0.0</modelVersion>

    <groupId>org.example</groupId>
    <artifactId>springTest</artifactId>
    <version>1.0-SNAPSHOT</version>

    <description>test</description>
    <packaging>jar</packaging>
    <properties>
        <maven.compiler.source>1.8</maven.compiler.source>
        <maven.compiler.target>1.8</maven.compiler.target>
        <project.build.sourceEncoding>UTF-8</project.build.sourceEncoding>
        <java.version>8</java.version>

        <spring-boot-dependencies.version>2.5.4</spring-boot-dependencies.version>

    </properties>
    <dependencies>
        <dependency>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-starter-web</artifactId>
            <version>2.5.4</version>
        </dependency>
    </dependencies>

    <build>
        <plugins>
            <plugin>
                <groupId>org.springframework.boot</groupId>
                <artifactId>spring-boot-maven-plugin</artifactId>
                <executions>
                    <execution>
                        <goals>
                            <goal>repackage</goal>
                            <goal>build-info</goal>
                        </goals>
                    </execution>
                </executions>
            </plugin>
        </plugins>
    </build>
</project>

二、项目设置：

spring:
  mvc:
    servlet:
      load-on-startup: 1

三、该问题带来的影响：

1、每次更新启动后，必须人为去访问，或者额外去写一个脚本，去访问应用里面的一个controller，也需要在应用里面写一个测试的controller，否则启动后会影响第一个访问应用的用户！

2

看看JVM的JIT即时编译器, JVM默认是混合模式, 可以在JVM参数中选择更改, 解释器模式 或者是 编译器模式.
解释器模式 全程由JIT即时的从字节码解释成机器码,启动的比较快,后续运行相对比来说比较慢
编译器模式 先把全部代码编译成机器码再运行, 启动的比较慢, 后续运行相对比来说比较快
混合模式 JIT会探测到热点代码 缓存机器码在JVM里面 后续再次进入就不会再由字节码转换成机器码

1 Like
3

有道理哈。我一直在想，可能是spring初始化的问题。没想过jit这茬。

4

跟JVM没啥关系，应该与tomcat有关， 再说下，这个不是应用启动慢， 是用户第一次访问慢， http请求第一次慢！

5

访问慢不就行运行慢吗?

6

第二次就很快，而且打开debug模式后，可以看到第一次访问 确实与第二次访问有一些不同：

DEBUG 6512 [] [http-nio-8300-Acceptor] o.apache.tomcat.util.threads.LimitLatch  Counting up[http-nio-8300-Acceptor] latch=1
DEBUG 6512 [] [http-nio-8300-Acceptor] o.apache.tomcat.util.threads.LimitLatch  Counting up[http-nio-8300-Acceptor] latch=2
DEBUG 6512 [] [http-nio-8300-exec-1] o.a.coyote.http11.Http11NioProtocol      Processing socket [org.apache.tomcat.util.net.NioChannel@deccd30:java.nio.channels.SocketChannel[connected local=/192.168.0.165:8300 remote=/192.168.0.165:31251]] with status [OPEN_READ]
DEBUG 6512 [] [http-nio-8300-exec-1] o.a.coyote.http11.Http11NioProtocol      Found processor [null] for socket [org.apache.tomcat.util.net.NioChannel@deccd30:java.nio.channels.SocketChannel[connected local=/192.168.0.165:8300 remote=/192.168.0.165:31251]]
DEBUG 6512 [] [http-nio-8300-exec-1] o.a.coyote.http11.Http11NioProtocol      Popped processor [null] from cache
DEBUG 6512 [] [http-nio-8300-exec-1] o.a.coyote.http11.Http11NioProtocol      Register [org.apache.coyote.http11.Http11Processor@1f0dbc23] as [Tomcat:type=RequestProcessor,worker="http-nio-8300",name=HttpRequest1]
DEBUG 6512 [] [http-nio-8300-exec-1] org.apache.tomcat.util.modeler.Registry  Managed= Tomcat:type=RequestProcessor,worker="http-nio-8300",name=HttpRequest1
DEBUG 6512 [] [http-nio-8300-exec-1] org.apache.tomcat.util.modeler.Registry  Looking for descriptor 
DEBUG 6512 [] [http-nio-8300-exec-1] org.apache.tomcat.util.modeler.Registry  Introspecting

第二次访问日志：

DEBUG 6512 [] [http-nio-8300-Acceptor] o.apache.tomcat.util.threads.LimitLatch  Counting up[http-nio-8300-Acceptor] latch=1
DEBUG 6512 [] [http-nio-8300-Acceptor] o.apache.tomcat.util.threads.LimitLatch  Counting up[http-nio-8300-Acceptor] latch=2
DEBUG 6512 [] [http-nio-8300-exec-5] o.a.coyote.http11.Http11NioProtocol      Processing socket [org.apache.tomcat.util.net.NioChannel@deccd30:java.nio.channels.SocketChannel[connected local=/192.168.0.165:8300 remote=/192.168.0.165:65142]] with status [OPEN_READ]
DEBUG 6512 [] [http-nio-8300-exec-5] o.a.coyote.http11.Http11NioProtocol      Found processor [null] for socket [org.apache.tomcat.util.net.NioChannel@deccd30:java.nio.channels.SocketChannel[connected local=/192.168.0.165:8300 remote=/192.168.0.165:65142]]
DEBUG 6512 [] [http-nio-8300-exec-5] o.a.coyote.http11.Http11NioProtocol      Popped processor [org.apache.coyote.http11.Http11Processor@1f0dbc23] from cache
DEBUG 6512 [] [http-nio-8300-exec-5] o.a.coyote.http11.Http11InputBuffer      Before fill(): parsingHeader: [true], parsingRequestLine: [true], parsingRequestLinePhase: [0], parsingRequestLineStart: [0], byteBuffer.position(): [0], byteBuffer.limit(): [0], end: [395]
DEBUG 6512 [] [http-nio-8300-exec-5] o.a.tomcat.util.net.SocketWrapperBase    Socket: [org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper@6ab40d83:org.apache.tomcat.util.net.NioChannel@deccd30:java.nio.channels.SocketChannel[connected local=/192.168.0.165:8300 remote=/192.168.0.165:65142]], Read from buffer: [0]
DEBUG 6512 [] [http-nio-8300-exec-5] org.apache.tomcat.util.net.NioEndpoint   Socket: [org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper@6ab40d83:org.apache.tomcat.util.net.NioChannel@deccd30:java.nio.channels.SocketChannel[connected local=/192.168.0.165:8300 remote=/192.168.0.165:65142]], Read direct from socket: [474]

能看到第一次 明显多了一个 注册 processor行为。

有没有对 tomcat 流程熟悉的朋友。

7

日志没看到时间呢？要不然打开 trace 日志级别，看看耗时的调用栈是哪里。

可以考虑换Undertow试试看，现在很多人企业项目都不咋用Tomcat了。