Why my Springboot with embbeded tomcat too slow when process first request?

Question

Env.

OS:macOS Mojave Version 10.14.5(centOS have same problem)

Springboot:2.1.6.RELEASE(embedded tomcat 9.0.21),war

I am a new player of Spring Boot, which I think is helpful to build my project. Now I have finish my work with it, but a strange phenomenon harass me. My project cost about 5 minutes to response to the first request, it costs 5 minutes not 5 seconds, the request after first seems normally. It was extraordinary slow, so I need some help from you.

With the help of jstack I got that most of the time was cost to doing things below, same doing unpack war.

"http-nio-15281-exec-5" #105 daemon prio=5 os_prio=31 tid=0x00007f988eaff800 nid=0x13b03 runnable [0x0000700013218000]
   java.lang.Thread.State: RUNNABLE
    at java.util.zip.Inflater.inflateBytes(Native Method)
    at java.util.zip.Inflater.inflate(Inflater.java:259)
    - locked <0x00000007bac79ab0> (a java.util.zip.ZStreamRef)
    at java.util.zip.InflaterInputStream.read(InflaterInputStream.java:152)
    at java.util.zip.ZipInputStream.read(ZipInputStream.java:194)
    at java.util.jar.JarInputStream.read(JarInputStream.java:207)
    at java.util.zip.ZipInputStream.closeEntry(ZipInputStream.java:140)
    at java.util.zip.ZipInputStream.getNextEntry(ZipInputStream.java:118)
    at java.util.jar.JarInputStream.getNextEntry(JarInputStream.java:142)
    at java.util.jar.JarInputStream.getNextJarEntry(JarInputStream.java:179)
    at org.apache.catalina.webresources.JarWarResourceSet.getArchiveEntries(JarWarResourceSet.java:117)
    - locked <0x00000007810e7770> (a java.lang.Object)
    at org.apache.catalina.webresources.AbstractArchiveResourceSet.getResource(AbstractArchiveResourceSet.java:253)
    at org.apache.catalina.webresources.StandardRoot.getResourceInternal(StandardRoot.java:282)
    at org.apache.catalina.webresources.Cache.getResource(Cache.java:62)
    at org.apache.catalina.webresources.StandardRoot.getResource(StandardRoot.java:217)
    at org.apache.catalina.webresources.StandardRoot.getClassLoaderResource(StandardRoot.java:226)
    at org.apache.catalina.loader.WebappClassLoaderBase.findClassInternal(WebappClassLoaderBase.java:2303)
    at org.apache.catalina.loader.WebappClassLoaderBase.findClass(WebappClassLoaderBase.java:865)
    at org.springframework.boot.web.embedded.tomcat.TomcatEmbeddedWebappClassLoader.findClassIgnoringNotFound(TomcatEmbeddedWebappClassLoader.java:119)
    at org.springframework.boot.web.embedded.tomcat.TomcatEmbeddedWebappClassLoader.doLoadClass(TomcatEmbeddedWebappClassLoader.java:84)
    at org.springframework.boot.web.embedded.tomcat.TomcatEmbeddedWebappClassLoader.loadClass(TomcatEmbeddedWebappClassLoader.java:66)
    - locked <0x00000007af22a990> (a java.lang.Object)
    at org.apache.catalina.loader.WebappClassLoaderBase.loadClass(WebappClassLoaderBase.java:1188)
    at java.lang.Class.forName0(Native Method)
    at java.lang.Class.forName(Class.java:348)
    at com.sun.beans.finder.ClassFinder.findClass(ClassFinder.java:67)
    at com.sun.beans.finder.ClassFinder.findClass(ClassFinder.java:110)
    at java.beans.Introspector.findCustomizerClass(Introspector.java:1301)
    at java.beans.Introspector.getTargetBeanDescriptor(Introspector.java:1295)
    at java.beans.Introspector.getBeanInfo(Introspector.java:425)
    at java.beans.Introspector.getBeanInfo(Introspector.java:262)
    at java.beans.Introspector.getBeanInfo(Introspector.java:204)
    at org.springframework.beans.CachedIntrospectionResults.getBeanInfo(CachedIntrospectionResults.java:248)
    at org.springframework.beans.CachedIntrospectionResults.<init>(CachedIntrospectionResults.java:273)
    at org.springframework.beans.CachedIntrospectionResults.forClass(CachedIntrospectionResults.java:177)
    at org.springframework.beans.BeanWrapperImpl.getCachedIntrospectionResults(BeanWrapperImpl.java:174)
    at org.springframework.beans.BeanWrapperImpl.getLocalPropertyHandler(BeanWrapperImpl.java:230)
    at org.springframework.beans.BeanWrapperImpl.getLocalPropertyHandler(BeanWrapperImpl.java:63)
    at org.springframework.beans.AbstractNestablePropertyAccessor.getPropertyValue(AbstractNestablePropertyAccessor.java:620)
    at org.springframework.beans.AbstractNestablePropertyAccessor.getPropertyValue(AbstractNestablePropertyAccessor.java:612)
    at org.springframework.data.util.DirectFieldAccessFallbackBeanWrapper.getPropertyValue(DirectFieldAccessFallbackBeanWrapper.java:52)
    at org.springframework.data.jpa.repository.support.JpaMetamodelEntityInformation.getId(JpaMetamodelEntityInformation.java:154)
    at org.springframework.data.repository.core.support.AbstractEntityInformation.isNew(AbstractEntityInformation.java:42)
    at org.springframework.data.jpa.repository.support.JpaMetamodelEntityInformation.isNew(JpaMetamodelEntityInformation.java:233)
    at org.springframework.data.jpa.repository.support.SimpleJpaRepository.save(SimpleJpaRepository.java:506)
    at org.springframework.data.jpa.repository.support.SimpleJpaRepository.saveAndFlush(SimpleJpaRepository.java:521)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:498)
    at org.springframework.data.repository.core.support.RepositoryComposition$RepositoryFragments.invoke(RepositoryComposition.java:359)
    at org.springframework.data.repository.core.support.RepositoryComposition.invoke(RepositoryComposition.java:200)
    at org.springframework.data.repository.core.support.RepositoryFactorySupport$ImplementationMethodExecutionInterceptor.invoke(RepositoryFactorySupport.java:644)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
    at org.springframework.data.repository.core.support.RepositoryFactorySupport$QueryExecutorMethodInterceptor.doInvoke(RepositoryFactorySupport.java:608)
    at org.springframework.data.repository.core.support.RepositoryFactorySupport$QueryExecutorMethodInterceptor.lambda$invoke$3(RepositoryFactorySupport.java:595)
    at org.springframework.data.repository.core.support.RepositoryFactorySupport$QueryExecutorMethodInterceptor$$Lambda$641/1539038539.get(Unknown Source)
    at org.springframework.data.repository.util.QueryExecutionConverters$$Lambda$640/28145535.apply(Unknown Source)
    at org.springframework.data.repository.core.support.RepositoryFactorySupport$QueryExecutorMethodInterceptor.invoke(RepositoryFactorySupport.java:595)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
    at org.springframework.data.projection.DefaultMethodInvokingMethodInterceptor.invoke(DefaultMethodInvokingMethodInterceptor.java:59)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
    at org.springframework.transaction.interceptor.TransactionInterceptor$$Lambda$636/1377160602.proceedWithInvocation(Unknown Source)
    at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:295)
    at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:98)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
    at org.springframework.dao.support.PersistenceExceptionTranslationInterceptor.invoke(PersistenceExceptionTranslationInterceptor.java:139)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
    at org.springframework.data.jpa.repository.support.CrudMethodMetadataPostProcessor$CrudMethodMetadataPopulatingMethodInterceptor.invoke(CrudMethodMetadataPostProcessor.java:138)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
    at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:93)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
    at org.springframework.data.repository.core.support.SurroundingTransactionDetectorMethodInterceptor.invoke(SurroundingTransactionDetectorMethodInterceptor.java:61)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
    at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:212)
    at com.sun.proxy.$Proxy125.saveAndFlush(Unknown Source)

Answer 1

We were facing the exact same issue and I spent quite a good few days on it but managed to solve it with this configuration piece:

@Configuration
public class EmbeddedTomcatConfiguration {

  @Bean
  TomcatServletWebServerFactory tomcatFactory() {
    return new TomcatServletWebServerFactory() {

      @Override
      protected void postProcessContext(Context context) {
        context.setResources(new ExtractingRoot());
      }
    };
  }

  @Bean
  public WebServerFactoryCustomizer<TomcatServletWebServerFactory> servletContainerCustomizer() {
    return new WebServerFactoryCustomizer<TomcatServletWebServerFactory>() {

      @Override
      public void customize(TomcatServletWebServerFactory container) {
        container.addContextCustomizers(
            new TomcatContextCustomizer() {
              @Override
              public void customize(Context cntxt) {
                cntxt.setReloadable(false);
              }
            });
      }
    };
  }
}

This basically does 2 things...

1. It asks Tomcat not to throw away the loaded classes and do a refresh.
2. It tells Tomcat to extract packages on startup (which requires a bit more disk space) instead of scanning through un-extracted packages.

Answer 2

Turns out there are a few things going on here, I've made a gist and a repo on github to share the solution to speed up Spring (and JPA repository specifically) boot time.

TLDR:

Solution 1: Add a configuration to turn off embedded Tomcat class reload https://gist.github.com/SimoneGianni/74b3b7e5f5986a72a95e705cc6abe6dc . This will prevent the problem from happening every 15 minutes and speedup boot a bit.

Solution 2: Implement a BeanInfo for each of your entities, or use this https://github.com/SimoneGianni/auto-bean-info to have them generated automatically.

FULL EXPLANATION:

When Spring starts, and/or at the first time your JPA repositories are used, and/or the first time a specific repository is used (depends on caches, order in which components are loeaded etc..), Spring and Hibernate will inspect your entities.

To do this, they will use java Introspector. Nothing bad in this, it's a standard library class used by anybody who has to deal with java beans.

Back in time when Swing was hot and shiny, Java beans was the way to compose modular UIs 20 years before Angular, and to do that a bean could be accompanied by a number of other classes, like BeanInfo and Descriptor, to specify how it should be used and configured by IDEs.

These accompanying classes were used to better describe properties, events etc.. annotations were not a thing back then.

Now, suppose you have a bean named SomethingCool.java, you could provide a SomethingCoolBeanInfo.java and/or a SomethingCoolDescriptor.java. The pattern is <bean class name>+(BeanInfo|Descriptor).

Introspector takes a bean, and first thing first .. searches for a corresponding BeanInfo and eventually Descriptor. So, these are Class.forName lookups.

At least in java 1.8 (haven't inspected more recent versions), this lookup is done in rather complex ways, tried multiple times on different classloaders.

Again, up to this, nothing bad, just searching for two classes.

Then, it arrives the Tomcat Embedded Classloader. It has two problems.

1. It is slow, cause it has to search jars inside jars, which is itself slow.
2. It throws away its cache by default every 15 minutes, so the problem is not only on startup but presents itself again later in case the search is performed again.

And, moreover, almost in 2020 Java has evolved, and BeanInfos and Descriptors are useful mostly in IDEs building UIs, not when dealing with entities that also happen to have setters and getters.

Spring tries to mitigate this invoking Introspector with a flag to ignore BeanInfos (and also exposes a property for that), but at least in 1.8 it apparently does nothing, for sure does not skip the search for a Descriptor, and as reported in the JDK ticket https://bugs.openjdk.java.net/browse/JDK-8172961 looks like it's a known problem on 1.8.

So, it loads the entity class, calls Introspector, it will search for BeanInfo, will not find it bust still scan all the jars, then search for Descriptor, again scanning all the jars, and that makes it slow.

In my case, an HTTP request usually taking milliseconds turned into 15/20 seconds the first time it was invoked, which was killing our E2E tests.

The first solution is to at least turn off Embedded Tomcat cache evictor, done with the gist https://gist.github.com/SimoneGianni/74b3b7e5f5986a72a95e705cc6abe6dc . It's a bean that intercepts the Spring Tomcat configuration and turns the correct flag. It's updated for Spring 2.0, there is a version for 1.X around on the net.

It will prevent the thing to happen again every 15 minutes, and somehow it also speeds up the boot up/first request to some extent, probably cause Tomcat is caching more aggressively.

However, it will still search for the BeanInfo and Descriptor, and give up only after it scanned all of your jars.

The second solution is to provide a BeanInfo class for each of your @Entity (and @MappedSuperclass, and ideally any interface or other superclass). By placing this BeanInfo it will find it (hopefully rather soon, in the same classloader) and avoid scanning all jars, and in BeanInfo you can also specify that there is no Descriptor and skip that other search altogether.

Since writing empty BeanInfos for each entity is tedious and pollutes your code, I've written an annotation processor that does exactly that, and I'm using it on my project.

For the time being you'll have to clone it, mvn build install it, and the use it as a dependency. I'll eventually setup a maven repo on github cause also for my purpose it's not healthy to have it as a local dependency only.

Note that in 1.9 they introduced some specific annotations to generate BeanInfos from annotations, but that is again Swing-oriented, so looks like no "avoid searching this stuff for entities" is available also in later versions.

Hope this helps, at least for me it helped, now initial boot is slightly faster, and the first request takes couple of seconds instead of 15/20, without further delays later on while executing E2E tests.