Performance issues with Spring Boot

[johnament]

Hi Spring Boot team!

I was wondering if you could provide me some insight on some performance issues I'm seeing within Spring Boot. You can see a sample project that's been put together here: https://github.com/SpartaSystems/spring-boot-sample

The problem that we're seeing is that under load, the database connection pool seems to not be able to keep up. A similar app to this, based on Wildfly Swarm was written and does not exhibit this issue, and I was wondering if you could provide some insight on how to tweak boot to help make this work a bit better.

Here's a few schematics:

• Test runs on an M3Large instance in AWS
• The database is MySQL 5.6.30 and runs local to the box (not an RDS instance)
• The java version is 1.8.0_u51
• All bare minimum JVM settings, e.g. 512 mb

What we see is that we get back an error rate of around 10% (plus or minus 3% depending on execution) with most of the errors being problems trying to get a connection from the underlying pool. The pool size is actually larger here than we run in most cases, but that doesn't seem to help.

John

[wilkinsona]

Looking at the app's dependencies, you're using the Tomcat JDBC connection pool. You might want to try using Hikari instead. To do so, exclude tomcat-jdbc and add a dependency on Hikari instead.

[johnament]

Yes, so that definitely helped the overall performance, though I kind of question whether this should be the default CP. I do still see a bunch of these in the logs, which seem to indicate some bad database connections.

2016-05-20 19:13:08.846  INFO 1514 --- [  XNIO-2 task-2] o.h.e.j.b.internal.AbstractBatchImpl     : HHH000010: On release of batch it still contained JDBC statements
2016-05-20 19:13:08.867 ERROR 1514 --- [  XNIO-2 task-2] io.undertow.request                      : UT005023: Exception handling request to /messages/0/093f3359-82fe-4651-91df-543d539ffc4f/1463771544000

org.springframework.web.util.NestedServletException: Request processing failed; nested exception is org.springframework.orm.ObjectOptimisticLockingFailureException: Batch update returned unexpected row count from update [0]; actual row count: 0; expected: 1; nested exception is org.hibernate.StaleStateException: Batch update returned unexpected row count from update [0]; actual row count: 0; expected: 1
    at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:979) ~[spring-webmvc-4.2.6.RELEASE.jar:4.2.6.RELEASE]
    at org.springframework.web.servlet.FrameworkServlet.doDelete(FrameworkServlet.java:891) ~[spring-webmvc-4.2.6.RELEASE.jar:4.2.6.RELEASE]
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:713) ~[javax.servlet-api-3.1.0.jar:3.1.0]
    at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:843) ~[spring-webmvc-4.2.6.RELEASE.jar:4.2.6.RELEASE]
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:790) ~[javax.servlet-api-3.1.0.jar:3.1.0]
    at io.undertow.servlet.handlers.ServletHandler.handleRequest(ServletHandler.java:85) ~[undertow-servlet-1.3.22.Final.jar:1.3.22.Final]
    at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:129) ~[undertow-servlet-1.3.22.Final.jar:1.3.22.Final]
    at org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:99) ~[spring-web-4.2.6.RELEASE.jar:4.2.6.RELEASE]
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) ~[spring-web-4.2.6.RELEASE.jar:4.2.6.RELEASE]
    at io.undertow.servlet.core.ManagedFilter.doFilter(ManagedFilter.java:61) ~[undertow-servlet-1.3.22.Final.jar:1.3.22.Final]
    at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:131) ~[undertow-servlet-1.3.22.Final.jar:1.3.22.Final]
    at org.springframework.web.filter.HttpPutFormContentFilter.doFilterInternal(HttpPutFormContentFilter.java:87) ~[spring-web-4.2.6.RELEASE.jar:4.2.6.RELEASE]
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) ~[spring-web-4.2.6.RELEASE.jar:4.2.6.RELEASE]
    at io.undertow.servlet.core.ManagedFilter.doFilter(ManagedFilter.java:61) ~[undertow-servlet-1.3.22.Final.jar:1.3.22.Final]
    at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:131) ~[undertow-servlet-1.3.22.Final.jar:1.3.22.Final]
    at org.springframework.web.filter.HiddenHttpMethodFilter.doFilterInternal(HiddenHttpMethodFilter.java:77) ~[spring-web-4.2.6.RELEASE.jar:4.2.6.RELEASE]
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) ~[spring-web-4.2.6.RELEASE.jar:4.2.6.RELEASE]
    at io.undertow.servlet.core.ManagedFilter.doFilter(ManagedFilter.java:61) ~[undertow-servlet-1.3.22.Final.jar:1.3.22.Final]
    at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:131) ~[undertow-servlet-1.3.22.Final.jar:1.3.22.Final]
    at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:121) ~[spring-web-4.2.6.RELEASE.jar:4.2.6.RELEASE]
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) ~[spring-web-4.2.6.RELEASE.jar:4.2.6.RELEASE]
    at io.undertow.servlet.core.ManagedFilter.doFilter(ManagedFilter.java:61) ~[undertow-servlet-1.3.22.Final.jar:1.3.22.Final]
    at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:131) ~[undertow-servlet-1.3.22.Final.jar:1.3.22.Final]
    at io.undertow.servlet.handlers.FilterHandler.handleRequest(FilterHandler.java:84) ~[undertow-servlet-1.3.22.Final.jar:1.3.22.Final]
    at io.undertow.servlet.handlers.security.ServletSecurityRoleHandler.handleRequest(ServletSecurityRoleHandler.java:62) ~[undertow-servlet-1.3.22.Final.jar:1.3.22.Final]
    at io.undertow.servlet.handlers.ServletDispatchingHandler.handleRequest(ServletDispatchingHandler.java:36) ~[undertow-servlet-1.3.22.Final.jar:1.3.22.Final]
    at io.undertow.servlet.handlers.security.SSLInformationAssociationHandler.handleRequest(SSLInformationAssociationHandler.java:131) ~[undertow-servlet-1.3.22.Final.jar:1.3.22.Final]
    at io.undertow.servlet.handlers.security.ServletAuthenticationCallHandler.handleRequest(ServletAuthenticationCallHandler.java:57) ~[undertow-servlet-1.3.22.Final.jar:1.3.22.Final]
    at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43) ~[undertow-core-1.3.22.Final.jar:1.3.22.Final]
    at io.undertow.security.handlers.AbstractConfidentialityHandler.handleRequest(AbstractConfidentialityHandler.java:46) ~[undertow-core-1.3.22.Final.jar:1.3.22.Final]
    at io.undertow.servlet.handlers.security.ServletConfidentialityConstraintHandler.handleRequest(ServletConfidentialityConstraintHandler.java:64) ~[undertow-servlet-1.3.22.Final.jar:1.3.22.Final]
    at io.undertow.security.handlers.AuthenticationMechanismsHandler.handleRequest(AuthenticationMechanismsHandler.java:60) ~[undertow-core-1.3.22.Final.jar:1.3.22.Final]
    at io.undertow.servlet.handlers.security.CachedAuthenticatedSessionHandler.handleRequest(CachedAuthenticatedSessionHandler.java:77) ~[undertow-servlet-1.3.22.Final.jar:1.3.22.Final]
    at io.undertow.security.handlers.AbstractSecurityContextAssociationHandler.handleRequest(AbstractSecurityContextAssociationHandler.java:43) ~[undertow-core-1.3.22.Final.jar:1.3.22.Final]
    at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43) ~[undertow-core-1.3.22.Final.jar:1.3.22.Final]
    at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43) ~[undertow-core-1.3.22.Final.jar:1.3.22.Final]
    at io.undertow.servlet.handlers.ServletInitialHandler.handleFirstRequest(ServletInitialHandler.java:285) ~[undertow-servlet-1.3.22.Final.jar:1.3.22.Final]
    at io.undertow.servlet.handlers.ServletInitialHandler.dispatchRequest(ServletInitialHandler.java:264) ~[undertow-servlet-1.3.22.Final.jar:1.3.22.Final]
    at io.undertow.servlet.handlers.ServletInitialHandler.access$000(ServletInitialHandler.java:81) ~[undertow-servlet-1.3.22.Final.jar:1.3.22.Final]
    at io.undertow.servlet.handlers.ServletInitialHandler$1.handleRequest(ServletInitialHandler.java:175) ~[undertow-servlet-1.3.22.Final.jar:1.3.22.Final]
    at io.undertow.server.Connectors.executeRootHandler(Connectors.java:202) [undertow-core-1.3.22.Final.jar:1.3.22.Final]
    at io.undertow.server.HttpServerExchange$1.run(HttpServerExchange.java:802) [undertow-core-1.3.22.Final.jar:1.3.22.Final]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [na:1.8.0_74]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [na:1.8.0_74]
    at java.lang.Thread.run(Thread.java:745) [na:1.8.0_74]

[wilkinsona]

Yes, so that definitely helped the overall performance, though I kind of question whether this should be the default CP

It would appear to be a better default for this application, but it's hard to say that it would definitely be a better default for everyone. I've opened #6013 to consider changing the default.

I've just modified your sample to use Hikari and run the performance test on my laptop (OS X, Java 1.8.0_74, MySQL 5.6.19). It completed without error:

================================================================================
---- Global Information --------------------------------------------------------
> request count                                      42784 (OK=42784  KO=0     )
> min response time                                      0 (OK=0      KO=-     )
> max response time                                    393 (OK=393    KO=-     )
> mean response time                                     1 (OK=1      KO=-     )
> std deviation                                          2 (OK=2      KO=-     )
> response time 50th percentile                          2 (OK=2      KO=-     )
> response time 75th percentile                          2 (OK=2      KO=-     )
> response time 95th percentile                          3 (OK=3      KO=-     )
> response time 99th percentile                          4 (OK=4      KO=-     )
> mean requests/sec                                186.017 (OK=186.017 KO=-     )
---- Response Time Distribution ------------------------------------------------
> t < 800 ms                                         42784 (100%)
> 800 ms < t < 1200 ms                                   0 (  0%)
> t > 1200 ms                                            0 (  0%)
> failed                                                 0 (  0%)
================================================================================

Whatever the problem is, it would appear to be environmental. I'm not sure that there's much that we can do in Spring Boot to address it so I'm going to close this issue. If you find evidence to the contrary please comment and we can reopen the issue and continue the investigation.