search

OpenLiberty / open-liberty

Open Liberty is a highly composable, fast to start, dynamic application server runtime environment
https://openliberty.io
Eclipse Public License 2.0
1.15k stars 590 forks source link

InstantOn Performance: SpringBoot First Request Time with Pet Clinic. #28832

Open jdmcclur opened 3 months ago

jdmcclur commented 3 months ago

Overall Springboot performance is looking really good with InstantOn, but always working to make things better. Running with Pet Clinic there seems to be a decent amount of overhead with initializing ThymeLeaf.

Most of the time is spent in org/thymeleaf/engine/TemplateManager.parseAndProcess, eventually initializing org/unbescape/html/HtmlEscapeSymbols

Exit <org/unbescape/html/HtmlEscapeSymbols.<clinit>()V bytecode static method Diff = 123.21 ms

Before that, a lot of time is spent in getConfiguration where a lot gets initialized on the first request.

Entry >org/thymeleaf/TemplateEngine.getConfiguration()Lorg/thymeleaf/IEngineConfiguration; bytecode method, this = 0xe2791f50
    Entry >org/thymeleaf/TemplateEngine.initialize()V bytecode method, this = 0xe2791f50
        Entry >org/thymeleaf/spring6/SpringTemplateEngine.initializeSpecific()V bytecode method, this = 0xe2791f50
            Entry >org/thymeleaf/TemplateEngine.setMessageResolver(Lorg/thymeleaf/messageresolver/IMessageResolver;)V bytecode method, this = 0xe2791f50
                Entry >org/thymeleaf/TemplateEngine.checkNotInitialized()V bytecode method, this = 0xe2791f50
                Exit <org/thymeleaf/TemplateEngine.checkNotInitialized()V bytecode method Diff = 0.00 ms
            Exit <org/thymeleaf/TemplateEngine.setMessageResolver(Lorg/thymeleaf/messageresolver/IMessageResolver;)V bytecode method Diff = 0.01 ms
            Entry >org/thymeleaf/spring6/SpringTemplateEngine.initializeSpringSpecific()V bytecode method, this = 0xe2791f50
            Exit <org/thymeleaf/spring6/SpringTemplateEngine.initializeSpringSpecific()V bytecode method Diff = 0.00 ms
        Exit <org/thymeleaf/spring6/SpringTemplateEngine.initializeSpecific()V bytecode method Diff = 0.66 ms
        Entry >org/thymeleaf/spring6/processor/SpringHrefTagProcessor.<clinit>()V bytecode static method
        Exit <org/thymeleaf/spring6/processor/SpringHrefTagProcessor.<clinit>()V bytecode static method Diff = 0.00 ms
        Entry >org/thymeleaf/spring6/processor/SpringHrefTagProcessor.<init>(Ljava/lang/String;)V bytecode method, this = 0xfeed5458
        Exit <org/thymeleaf/spring6/processor/SpringHrefTagProcessor.<init>(Ljava/lang/String;)V bytecode method Diff = 0.01 ms
        Entry >org/thymeleaf/spring6/processor/SpringHrefTagProcessor.setAttributeDefinitions(Lorg/thymeleaf/engine/AttributeDefinitions;)V bytecode method, this = 0xfeed5458
        Exit <org/thymeleaf/spring6/processor/SpringHrefTagProcessor.setAttributeDefinitions(Lorg/thymeleaf/engine/AttributeDefinitions;)V bytecode method Diff = 0.01 ms
        Entry >org/thymeleaf/engine/TemplateManager.<clinit>()V bytecode static method
        Exit <org/thymeleaf/engine/TemplateManager.<clinit>()V bytecode static method Diff = 0.01 ms
        Entry >org/thymeleaf/engine/TemplateManager.<init>(Lorg/thymeleaf/IEngineConfiguration;)V bytecode method, this = 0xff013a80
        Exit <org/thymeleaf/engine/TemplateManager.<init>(Lorg/thymeleaf/IEngineConfiguration;)V bytecode method Diff = 8.27 ms
    Exit <org/thymeleaf/TemplateEngine.initialize()V bytecode method Diff = 78.30 ms
Exit <org/thymeleaf/TemplateEngine.getConfiguration()Lorg/thymeleaf/IEngineConfiguration; bytecode method Diff = 78.31 ms

StackTrace

[err]   at org.unbescape.html.HtmlEscapeSymbols.<clinit>(HtmlEscapeSymbols.java:183)
[err]   at org.unbescape.html.HtmlEscapeUtil.escape(HtmlEscapeUtil.java:109)
[err]   at org.unbescape.html.HtmlEscape.escapeHtml(HtmlEscape.java:356)
[err]   at org.unbescape.html.HtmlEscape.escapeHtml4Xml(HtmlEscape.java:316)
[err]   at org.thymeleaf.spring6.processor.SpringHrefTagProcessor.doProcess(SpringHrefTagProcessor.java:84)
[err]   at org.thymeleaf.standard.processor.AbstractStandardExpressionAttributeTagProcessor.doProcess(AbstractStandardExpressionAttributeTagProcessor.java:160)
[err]   at org.thymeleaf.processor.element.AbstractAttributeTagProcessor.doProcess(AbstractAttributeTagProcessor.java:74)
[err]   at org.thymeleaf.processor.element.AbstractElementTagProcessor.process(AbstractElementTagProcessor.java:95)
[err]   at org.thymeleaf.util.ProcessorConfigurationUtils$ElementTagProcessorWrapper.process(ProcessorConfigurationUtils.java:633)
[err]   at org.thymeleaf.engine.ProcessorTemplateHandler.handleStandaloneElement(ProcessorTemplateHandler.java:918)
[err]   at org.thymeleaf.engine.StandaloneElementTag.beHandled(StandaloneElementTag.java:228)
[err]   at org.thymeleaf.engine.Model.process(Model.java:282)
[err]   at org.thymeleaf.engine.ProcessorTemplateHandler.handleOpenElement(ProcessorTemplateHandler.java:1587)
[err]   at org.thymeleaf.engine.OpenElementTag.beHandled(OpenElementTag.java:205)
[err]   at org.thymeleaf.engine.TemplateModel.process(TemplateModel.java:136)
[err]   at org.thymeleaf.engine.TemplateManager.parseAndProcess(TemplateManager.java:661)
[err]   at org.thymeleaf.TemplateEngine.process(TemplateEngine.java:1103)
[err]   at org.thymeleaf.TemplateEngine.process(TemplateEngine.java:1077)
[err]   at org.thymeleaf.spring6.view.ThymeleafView.renderFragment(ThymeleafView.java:372)
[err]   at org.thymeleaf.spring6.view.ThymeleafView.render(ThymeleafView.java:192)
[err]   at org.springframework.web.servlet.DispatcherServlet.render(DispatcherServlet.java:1431)
[err]   at org.springframework.web.servlet.DispatcherServlet.processDispatchResult(DispatcherServlet.java:1167)
[err]   at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:1106)
[err]   at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:979)
[err]   at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:1014)
[err]   at org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:903)
[err]   at jakarta.servlet.http.HttpServlet.service(HttpServlet.java:527)
[err]   at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:885)
[err]   at jakarta.servlet.http.HttpServlet.service(HttpServlet.java:614)
[err]   at [internal classes]
[err]   at org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:100)
[err]   at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:116)
[err]   at com.ibm.ws.webcontainer.filter.FilterInstanceWrapper.doFilter(FilterInstanceWrapper.java:203)
[err]   at [internal classes]
[err]   at org.springframework.web.filter.FormContentFilter.doFilterInternal(FormContentFilter.java:93)
[err]   at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:116)
[err]   at com.ibm.ws.webcontainer.filter.FilterInstanceWrapper.doFilter(FilterInstanceWrapper.java:203)
[err]   at [internal classes]
[err]   at org.springframework.web.filter.ServerHttpObservationFilter.doFilterInternal(ServerHttpObservationFilter.java:109)
[err]   at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:116)
[err]   at com.ibm.ws.webcontainer.filter.FilterInstanceWrapper.doFilter(FilterInstanceWrapper.java:203)
[err]   at [internal classes]
[err]   at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:201)
[err]   at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:116)
[err]   at com.ibm.ws.webcontainer.filter.FilterInstanceWrapper.doFilter(FilterInstanceWrapper.java:203)
[err]   at [internal classes]
[err]   at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136)
[err]   at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
[err]   at java.base/java.lang.Thread.run(Thread.java:857)

I did successfully load/initialize org/unbescape/html/HtmlEscapeSymbols here, but that seem pretty hacky. https://github.com/OpenLiberty/open-liberty/blob/3d4a37a15effdd14b118355ad5181df4c4ddaf52/dev/com.ibm.ws.app.manager.springboot/src/com/ibm/ws/app/manager/springboot/internal/SpringBootApplicationImpl.java#L898

            ClassLoader cl = createTopLevelClassLoader(containers, gwCfg, clCfg);

            try {
                Class.forName("org.unbescape.html.HtmlEscapeSymbols",true,cl);
            } catch (Exception e) {
                // ignore
            }

            return cl;
vijaysun-omr commented 3 months ago

https://github.com/unbescape/unbescape/blob/master/src/main/java/org/unbescape/html/HtmlEscapeSymbols.java does show a fair amount of initialization of static variables, including some calls inside a static code block. The problem is that we don't JIT compile <clinit> methods (or maybe even anything when a <clinit> is on the stack) since they are only expected to be invoked once, so this non-trivial logic runs interpreted, i.e. 10 times slower than it could if it were JITed

vijaysun-omr commented 3 months ago

https://github.com/unbescape/unbescape/blob/ec5435fb3508c2eed25d8165dc27ded2602cae13/src/main/java/org/unbescape/html/Html4EscapeSymbolsInitializer.java#L37

and

https://github.com/unbescape/unbescape/blob/ec5435fb3508c2eed25d8165dc27ded2602cae13/src/main/java/org/unbescape/html/Html5EscapeSymbolsInitializer.java#L37

are the calls inside the static code block in that <clinit> and are clearly quite a bit heavier than a typical <clinit> would be expected to be (many Java statements).

vijaysun-omr commented 3 months ago

I will need to think about whether something can be done in the JVM at checkpoint time for handling this better, but the problem will be to identify why this code is even of interest at all at that time, if it only runs as part of handling the first request.

Thinking also of what you could even attempt in Liberty, a couple of options (not sure how practical)

  1. Run a fudged up request before checkpoint (without even a load driver, i.e. just manufacture a request as it would look if it had come across the network) that exercises these code paths (even if it ultimately it results in failure, since the request was bogus to begin with)
  2. Get a list of "application classes" (from the directories where the application jars are) and do Class.forName on them all before checkpoint. This would increase memory footprint before checkpoint, but we may be able to work around that if it led to decent startup improvement (we need to check if this is even practical).