Springboot第一次访问慢,自身缺陷问题?

一、现象:

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,否则启动后会影响第一个访问应用的用户!

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

1 个赞

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

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

访问慢不就行运行慢吗?

第二次就很快,而且打开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 流程熟悉的朋友。

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

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