V2EX = way to explore
V2EX 是一个关于分享和探索的地方
现在注册
已注册用户请  登录
shayang888
V2EX  ›  程序员

为啥 springboot 这么多版本了,这个问题还是没解决还是只有我遇到这情况?

  •  
  •   shayang888 · 292 天前 · 4017 次点击
    这是一个创建于 292 天前的主题,其中的信息可能已经有所发展或是发生改变。

    问题:每次启动完 springboot 后,无论代码写的多么简单,第一个接口请求总是特别耗时,后续该项目的任何接口请求就特别快。

    @SpringBootApplication
    @RestController
    public class DemoApplication {
       public static void main(String[] args) {
          SpringApplication.run(DemoApplication.class, args);
       }
       
       @GetMapping(path = "/test")
       public String testRequest() {
         return "123";
       }
       
       @PostMapping(path = "/test2")
       public String testRequest2() {
         return "456";
       }
    }
    

    就即使这么简单的代码,项目启动后,不论先请求哪一个接口,总是特别耗时,我本地测试第一次总是 150ms 左右,第二次就是 5 、6ms 。

    什么懒加载啥的都试了,没有任何效果。

    有人有遇到这个情况吗?

    32 条回复    2021-01-08 02:11:58 +08:00
    crclz
        1
    crclz   292 天前
    你看看 chrome 或者 postman 的时间开销,先确定是客户端的开销,还是服务端的开销。

    我之前就遇到过类似的,知道我发现 dns 开销 200ms 。
    wysnylc
        2
    wysnylc   292 天前
    [Spring boot 第一次请求很慢问题]( https://blog.csdn.net/wysnxzm/article/details/103306665)
    你的问题
    shayang888
        3
    shayang888   292 天前
    @crclz 我刚试了下 用 2 个客户端来访问,先用 postman 结果 160 多 ms 然后用 chrome 访问 20ms 换一遍用 chrome 160ms 然后 postman 10ms
    chendy
        4
    chendy   292 天前   ❤️ 2
    都这样,但是因为真的只影响首次请求所以可能大家并不在意
    而且这不是 spring-boot 的问题,是 spring-mvc 的问题,早年以为是 load-on-startup 的影响,后来发现并不是

    暴力解决方法是写个 ApplicationRunner 或者其他东西,应用启动之后自己请求自己一次,完成初始化
    还可以用 k8s 的 readless probe 之类的帮忙发请求
    liuzhaowei55
        5
    liuzhaowei55   292 天前 via Android   ❤️ 1
    这个问题也困扰已久,但没有找到好的解决方案,懒加载,random 设置都尝试过了,隔一段时间没有请求,重新请求就会响应很慢,估计开个定时器不断请求可破这个问题了。
    young1lin
        6
    young1lin   292 天前
    这是 Spring MVC 的问题好吗,根本不是 Spring Boot 的问题,虽然后者把前者整合进来了。这个是第一次 DispatcherServlet 初始化时,把那些 HandleMapping 加载进来所以慢。你要想不慢,自己加个 Spring Boot 初始化类,主动触发一下,它不 ok 吗?
    otakustay
        7
    otakustay   291 天前
    没事的再几年你们拥抱云原生了用 FAAS 会觉得这问题更酸爽的,提前适应适应
    shayang888
        8
    shayang888   291 天前
    @chendy
    @liuzhaowei55 明白了 谢谢了
    hantsy
        9
    hantsy   291 天前   ❤️ 1
    有几人看过官方 Spring Boot 参考文档或者博客: https://spring.io/blog/2019/03/14/lazy-initialization-in-spring-boot-2-2

    By default, when an application context is being refreshed, every bean in the context is created and its dependencies are injected. By contrast, when a bean definition is configured to be initialized lazily it will not be created and its dependencies will not be injected until it’s needed.
    。。。

    In a web application lazy initialization can lead to increased latency for HTTP requests that trigger bean initialization. This will typically just be the first request but it may have an adverse effect on load-balancing and auto-scaling.
    hantsy
        10
    hantsy   291 天前
    1, 关掉 lazy initialization

    2, 或者你可以自己写一个 java/main 去启动你的 Application,完全自己控制 Bean Registration,不需要 Spring Boot 。https://github.com/hantsy/spring-reactive-sample/blob/master/register-bean/src/main/java/com/example/demo/Application.java#L17,
    chendy
        11
    chendy   291 天前
    @hantsy 然而这个问题并不是懒加载导致的……更何况早年 spring-boot 压根没有懒加载
    340244120w
        12
    340244120w   291 天前
    @hantsy #10 懒加载默认开启是 spring2.2 才引入的,之前默认关闭的
    https://spring.io/blog/2018/12/12/how-fast-is-spring
    340244120w
        13
    340244120w   291 天前
    说错了,只是加了个全局 bean 懒加载的设置
    ztechstack
        14
    ztechstack   291 天前
    我想健康检查是不是能解决这个问题?
    IMCA1024
        15
    IMCA1024   291 天前
    @ztechstack 貌似是的
    chendy
        16
    chendy   291 天前
    @ztechstack 是的,健康检查帮忙预热接口…
    sampeng
        17
    sampeng   291 天前
    @IMCA1024
    @chendy
    @ztechstack

    健康检查是歪路子。谁健康检查去健康检查业务接口?况且有几百个接口的时候怎么搞?
    hantsy
        18
    hantsy   291 天前
    懒加载? Lazy Loading ? 不知道你们说什么东西了。
    chendy
        19
    chendy   291 天前
    @sampeng 随便什么接口,吃一个请求,接受请求这一层就预热起来了,业务的缓存啥的管不着也不是这个问题
    hantsy
        20
    hantsy   291 天前
    我实在搞不懂,你们在纠结什么?从我的角度没有一点意义的事情。

    试了一下我的现在的项目。https://github.com/hantsy/spring-r2dbc-sample/tree/master/database-client

    前面是启动后首次请求。两次请求,没看出来有多大差别。

    C:\Users\hantsy>curl http://localhost:8080/posts -v --trace-time
    18:22:06.375000 * Trying ::1...
    18:22:06.375000 * TCP_NODELAY set
    18:22:06.578000 * Trying 127.0.0.1...
    18:22:06.593000 * TCP_NODELAY set
    18:22:06.609000 * Connected to localhost (127.0.0.1) port 8080 (#0)
    18:22:06.625000 > GET /posts HTTP/1.1
    18:22:06.625000 > Host: localhost:8080
    18:22:06.625000 > User-Agent: curl/7.55.1
    18:22:06.625000 > Accept: */*
    18:22:06.625000 >
    18:22:06.875000 < HTTP/1.1 200 OK
    18:22:06.875000 < transfer-encoding: chunked
    18:22:06.890000 < Content-Type: application/json
    18:22:06.890000 <
    [{"id":"6697b8d0-2113-434a-82bb-20a6c0bb2f37","title":"R2dbc is refined","content":"R2dbc is now part of Spring framework core","metadata":{},"status":"DRAFT","createdAt":"2021-01-06T18:21:56.89318"},{"id":"a320359e-0425-425b-92a0-49bf2345e8a2","title":"my first post","content":"content of my first post","metadata":{"tags":["spring","r2dbc"]},"status":"DRAFT","createdAt":"2021-01-06T18:21:57.56585"}]18:22:06.890000 * Connection #0 to host localhost left intact


    C:\Users\hantsy>curl http://localhost:8080/posts -v --trace-time
    18:22:55.093000 * Trying ::1...
    18:22:55.093000 * TCP_NODELAY set
    18:22:55.312000 * Trying 127.0.0.1...
    18:22:55.312000 * TCP_NODELAY set
    18:22:55.328000 * Connected to localhost (127.0.0.1) port 8080 (#0)
    18:22:55.343000 > GET /posts HTTP/1.1
    18:22:55.343000 > Host: localhost:8080
    18:22:55.343000 > User-Agent: curl/7.55.1
    18:22:55.343000 > Accept: */*
    18:22:55.343000 >
    18:22:55.421000 < HTTP/1.1 200 OK
    18:22:55.421000 < transfer-encoding: chunked
    18:22:55.421000 < Content-Type: application/json
    18:22:55.437000 <
    [{"id":"6697b8d0-2113-434a-82bb-20a6c0bb2f37","title":"R2dbc is refined","content":"R2dbc is now part of Spring framework core","metadata":{},"status":"DRAFT","createdAt":"2021-01-06T18:21:56.89318"},{"id":"a320359e-0425-425b-92a0-49bf2345e8a2","title":"my first post","content":"content of my first post","metadata":{"tags":["spring","r2dbc"]},"status":"DRAFT","createdAt":"2021-01-06T18:21:57.56585"}]18:22:55.437000 * Connection #0 to host localhost left intact

    C:\Users\hantsy>
    hantsy
        21
    hantsy   291 天前
    上面这人是 Spring WebFlux 程序,没用 Spring Boot 。
    hantsy
        22
    hantsy   291 天前
    Spring MVC 程序。https://github.com/hantsy/spring-playground/tree/master/programming-models/webmvc-fn

    本地测试如下:

    C:\Users\hantsy>curl http://localhost:8080/ -v --trace-time
    19:23:51.593000 * Trying ::1...
    19:23:51.593000 * TCP_NODELAY set
    19:23:51.593000 * Connected to localhost (::1) port 8080 (#0)
    19:23:51.625000 > GET / HTTP/1.1
    19:23:51.625000 > Host: localhost:8080
    19:23:51.625000 > User-Agent: curl/7.55.1
    19:23:51.625000 > Accept: */*
    19:23:51.625000 >
    19:23:51.671000 < HTTP/1.1 200
    19:23:51.671000 < Content-Type: application/json
    19:23:51.671000 < Transfer-Encoding: chunked
    19:23:51.671000 < Date: Wed, 06 Jan 2021 11:23:51 GMT
    19:23:51.671000 <
    [{"id":7,"title":"Hello Spring","content":"This is my first post of Spring","createdAt":"2021-01-06T19:23:00.37556"},{"id":8,"title":"Hello Again","content":"The second post","createdAt":"2021-01-06T19:23:00.37556"}]19:23:51.687000 * Connection #0 to host localhost left intact

    C:\Users\hantsy>curl http://localhost:8080/ -v --trace-time
    19:23:55.656000 * Trying ::1...
    19:23:55.656000 * TCP_NODELAY set
    19:23:55.656000 * Connected to localhost (::1) port 8080 (#0)
    19:23:55.703000 > GET / HTTP/1.1
    19:23:55.703000 > Host: localhost:8080
    19:23:55.703000 > User-Agent: curl/7.55.1
    19:23:55.703000 > Accept: */*
    19:23:55.703000 >
    19:23:55.718000 < HTTP/1.1 200
    19:23:55.718000 < Content-Type: application/json
    19:23:55.734000 < Transfer-Encoding: chunked
    19:23:55.734000 < Date: Wed, 06 Jan 2021 11:23:55 GMT
    19:23:55.734000 <
    [{"id":7,"title":"Hello Spring","content":"This is my first post of Spring","createdAt":"2021-01-06T19:23:00.37556"},{"id":8,"title":"Hello Again","content":"The second post","createdAt":"2021-01-06T19:23:00.37556"}]19:23:55.734000 * Connection #0 to host localhost left intact
    hantsy
        23
    hantsy   291 天前
    上面的用 PostMan, Chrome 不知道对浏览器缓存有没有研究,是不是每次请求前都是事先删除了本地缓存。
    ztechstack
        24
    ztechstack   291 天前
    @sampeng 健康检查,检查一下各种数据库,然后同时预热。虽然有点歪门邪道,但可以考虑用 k8s 就绪健康检查做完整的健康检查。
    hantsy
        25
    hantsy   291 天前
    @ztechstack 完全看不懂这是什么骚操作?用来作什么?对你的程序有什么用?你的程序每次请求完了要重新启动吗?第一次请求延迟如果考虑一个长期运行的程序,比如程序运行了 100 天没重启,它解决了什么问题。
    hantsy
        26
    hantsy   291 天前
    @340244120w spring.main.lazy-initialization 这是全局延迟初始化,从来不知道被称为 [懒加载] (这是我第一次听说)。一般情况下,如果你是传统的三层结构,启用的话,repository, controller 等都不会事先初始化。这个在你的程序达到百个 Bean 的延迟是很明显的,我深有体会。


    但是像楼主那样两次请求可以相差一个数据量级的,我从来没见过(包含我用其它语言写过的 Restful API )。一般我的程序可能使用缓存等,加上后面请求可能受系统和网络资源限制不一样,一般有 2-3 倍差别我觉得还是比较正常。
    hantsy
        27
    hantsy   291 天前
    @chendy
    @340244120w 帮我看一下我的程序哪里出了问题,为什么重现不了 10 倍的场景。
    340244120w
        28
    340244120w   290 天前
    @hantsy
    我试了下,配置文件加上 logging.level.web=trace 后前后两次打印
    第一次请求--------------------------------------------
    2021-01-07 13:13:52.659 INFO 43592 --- [nio-8080-exec-2] o.a.c.c.C.[Tomcat].[localhost].[/] : Initializing Spring DispatcherServlet 'dispatcherServlet'
    2021-01-07 13:13:52.659 INFO 43592 --- [nio-8080-exec-2] o.s.web.servlet.DispatcherServlet : Initializing Servlet 'dispatcherServlet'
    2021-01-07 13:13:52.659 TRACE 43592 --- [nio-8080-exec-2] o.s.web.servlet.DispatcherServlet : Detected org.springf[email protected]49277b55
    2021-01-07 13:13:52.659 TRACE 43592 --- [nio-8080-exec-2] o.s.web.servlet.DispatcherServlet : Detected [email protected]18bda305
    2021-01-07 13:13:52.659 TRACE 43592 --- [nio-8080-exec-2] o.s.web.servlet.DispatcherServlet : Detected [email protected]e
    2021-01-07 13:13:52.660 TRACE 43592 --- [nio-8080-exec-2] o.s.web.servlet.DispatcherServlet : Detected DefaultRequestToViewNameTranslator
    2021-01-07 13:13:52.660 TRACE 43592 --- [nio-8080-exec-2] o.s.web.servlet.DispatcherServlet : Detected SessionFlashMapManager
    2021-01-07 13:13:52.660 DEBUG 43592 --- [nio-8080-exec-2] o.s.web.servlet.DispatcherServlet : enableLoggingRequestDetails='false': request parameters and headers will be masked to prevent unsafe logging of potentially sensitive data
    2021-01-07 13:13:52.660 INFO 43592 --- [nio-8080-exec-2] o.s.web.servlet.DispatcherServlet : Completed initialization in 1 ms
    2021-01-07 13:13:52.667 TRACE 43592 --- [nio-8080-exec-2] o.s.web.servlet.DispatcherServlet : GET "/", parameters={}, headers={masked} in DispatcherServlet 'dispatcherServlet'
    2021-01-07 13:13:52.669 TRACE 43592 --- [nio-8080-exec-2] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped to com.example.demo.DemoApplication$PostController#getAll()
    2021-01-07 13:13:52.675 TRACE 43592 --- [nio-8080-exec-2] o.s.web.method.HandlerMethod : Arguments: []
    2021-01-07 13:13:52.691 DEBUG 43592 --- [nio-8080-exec-2] m.m.a.RequestResponseBodyMethodProcessor : Using 'text/plain', given [*/*] and supported [text/plain, */*, text/plain, */*, application/json, application/*+json, application/json, application/*+json]
    2021-01-07 13:13:52.692 TRACE 43592 --- [nio-8080-exec-2] m.m.a.RequestResponseBodyMethodProcessor : Writing ["1111"]
    2021-01-07 13:13:52.699 TRACE 43592 --- [nio-8080-exec-2] s.w.s.m.m.a.RequestMappingHandlerAdapter : Applying default cacheSeconds=-1
    2021-01-07 13:13:52.699 TRACE 43592 --- [nio-8080-exec-2] o.s.web.servlet.DispatcherServlet : No view rendering, null ModelAndView returned.
    2021-01-07 13:13:52.699 DEBUG 43592 --- [nio-8080-exec-2] o.s.web.servlet.DispatcherServlet : Completed 200 OK, headers={masked}



    第二次请求---------------------------------------------------

    2021-01-07 12:58:11.230 TRACE 43278 --- [nio-8080-exec-3] o.s.web.servlet.DispatcherServlet : GET "/2", parameters={}, headers={masked} in DispatcherServlet 'dispatcherServlet'
    2021-01-07 12:58:11.230 TRACE 43278 --- [nio-8080-exec-3] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped to com.example.demo.DemoApplication$PostController#getById()
    2021-01-07 12:58:11.230 TRACE 43278 --- [nio-8080-exec-3] .w.s.m.m.a.ServletInvocableHandlerMethod : Arguments: []
    2021-01-07 12:58:11.231 DEBUG 43278 --- [nio-8080-exec-3] m.m.a.RequestResponseBodyMethodProcessor : Using 'text/plain', given [*/*] and supported [text/plain, */*, text/plain, */*, application/json, application/*+json, application/json, application/*+json]
    2021-01-07 12:58:11.231 TRACE 43278 --- [nio-8080-exec-3] m.m.a.RequestResponseBodyMethodProcessor : Writing ["2222"]
    2021-01-07 12:58:11.231 TRACE 43278 --- [nio-8080-exec-3] o.s.web.servlet.DispatcherServlet : No view rendering, null ModelAndView returned.
    2021-01-07 12:58:11.231 DEBUG 43278 --- [nio-8080-exec-3] o.s.web.servlet.DispatcherServlet : Completed 200 OK, headers={masked}

    --------------------------------------------------------------------

    我这个不带数据库的纯 springmvc 简单项目,dispatcher 初始化其实就 1ms 。
    第一次请求 spring 内部耗时是 699-667=32ms (快点的时候十多 ms ),不过算上 jvm 预热其实也正常。
    整体 100ms 以上的话,得加上 spring.main.lazy-initialization=true 才行。
    340244120w
        29
    340244120w   290 天前
    而且 springmvc 性能本来的确就不咋滴。。基本操作
    chendy
        30
    chendy   290 天前
    @hantsy 啊这,我们都不纠结 了只有你还在纠结啊
    你的例子第一次是比第二次慢,不就符合楼主的描述了么,至于 10 倍……我 ctrl f 在帖子里没搜到 10 倍 ,难道 block 了说慢十倍的人?……
    楼主说的这种情况和 spring 的 bean 初始化时机没关系,只能说和 jvm 预热有关(可能还有数据库连接池预热,程序内缓存预热吧啦吧啦
    随手做了几个测试,浏览器里访问,反复刷新,容易观察
    1. 随手找了一个应用( SpringMVC )加个空接口,首次 98ms,后续 4~8ms
    2. start.spring.io 做了个只有 webflux 依赖的空项目,加个空接口,首次 100ms,后续 4~8ms
    3. netty http server,不做任何处理只返回空内容,首次 80ms,后续 1-5ms
    4. 直接 java.net.ServerSocket 假装是个 http server,不做任何处理只返回空内容,首次和后续都是 12-18ms
    可以发现除了最最最简单的写法之外其他几个都存在首次比后续慢的情况,应该就是 jvm 预热的问题
    hantsy
        31
    hantsy   290 天前
    @chendy 翻了一下。还不止呢,原描述是 150MS->5ms 太夸张了。

    你这么大的发现,快去申请专利。谁整天写个 Hello World 玩,对于 Web 程序,数据库操作才是最大瓶颈。
    ztechstack
        32
    ztechstack   290 天前
    @hantsy k8s 健康检查分为两种:就绪检查与存活检查。
    1. 就绪的健康检查是 pod (程序)启动时,检查服务是否可以正常接受 HTTP 请求,如果检查正常之后才会将 HTTP 流量转发的这个 pod (程序),失败则重启 pod (程序);
    2. 存活的健康检查是 pod (程序)运行时,如果检查失败,则将 pod (服务) kill 掉,重新启动一个 pod (服务)。

    现在 springboot 的问题不就是第一次请求的时候慢,但这个第一次请求是在就绪的健康检查的时候(此时程序没有接受业务上的 http 请求)就给预热完毕了,那么其他的任何接口请求时间正常了。

    k8s 两种检查的好处在于:
    1. 就绪的检查可以实现一些稍稍比较重的任务,比如数据库连接状态或者数据是否成功初始化的检查,因为只是在启动时请求,不会因为检查而影响效率;
    2. 存活检查就可以很简单,一般单纯返回程序运行状态或加上数据库连接状态就可以了。

    实际在使用 k8s 之前,nginx 上一般都会在 upstream 配置一个统一的健康检查,只不过这个没有区分两种检查,同样也是进行了预热。
    关于   ·   帮助文档   ·   FAQ   ·   API   ·   我们的愿景   ·   广告投放   ·   感谢   ·   实用小工具   ·   3466 人在线   最高记录 5497   ·     Select Language
    创意工作者们的社区
    World is powered by solitude
    VERSION: 3.9.8.5 · 26ms · UTC 04:08 · PVG 12:08 · LAX 21:08 · JFK 00:08
    ♥ Do have faith in what you're doing.