Sven
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,否则启动后会影响第一个访问应用的用户!
Npc
2
看看JVM的JIT即时编译器, JVM默认是混合模式, 可以在JVM参数中选择更改, 解释器模式 或者是 编译器模式.
解释器模式 全程由JIT即时的从字节码解释成机器码,启动的比较快,后续运行相对比来说比较慢
编译器模式 先把全部代码编译成机器码再运行, 启动的比较慢, 后续运行相对比来说比较快
混合模式 JIT会探测到热点代码 缓存机器码在JVM里面 后续再次进入就不会再由字节码转换成机器码
1 Like
ROOT
3
有道理哈。我一直在想,可能是spring初始化的问题。没想过jit这茬。
Sven
4
跟JVM没啥关系,应该与tomcat有关, 再说下,这个不是应用启动慢, 是用户第一次访问慢, http请求第一次慢!
Sven
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 流程熟悉的朋友。
ROOT
7
日志没看到时间呢?要不然打开 trace 日志级别,看看耗时的调用栈是哪里。
可以考虑换Undertow试试看,现在很多人企业项目都不咋用Tomcat了。