We have been using microservices architecture for a long time. The services have been developed using spring-boot. The services were developed long back using Spring Boot 1.3.5.RELEASE, which is internally using the following tomcat dependencies:
<dependency>
<groupId>org.apache.tomcat.embed</groupId>
<artifactId>tomcat-embed-core</artifactId>
<version>8.0.33</version>
</dependency>
<dependency>
<groupId>org.apache.tomcat.embed</groupId>
<artifactId>tomcat-embed-el</artifactId>
<version>8.0.33</version>
</dependency>
<dependency>
<groupId>org.apache.tomcat.embed</groupId>
<artifactId>tomcat-embed-jasper</artifactId>
<version>8.0.33</version>
</dependency>
<dependency>
<groupId>org.apache.tomcat.embed</groupId>
<artifactId>tomcat-embed-logging-juli</artifactId>
<version>8.0.33</version>
</dependency>
<dependency>
<groupId>org.apache.tomcat.embed</groupId>
<artifactId>tomcat-embed-websocket</artifactId>
<version>8.0.33</version>
</dependency>
In order to figure out the slow response of an API we enabled log level to debug on Test env, and found that it is the tomcat that is delaying the response by almost 6-7 Sec, please find the logs below:
2021-05-28 13:04:37 [http-nio-9112-exec-1] DEBUG o.apache.tomcat.util.http.Parameters-[DirectJDKLog.java:180]-Set query string encoding to UTF-8
2021-05-28 13:04:37 [http-nio-9112-exec-1] DEBUG o.a.catalina.connector.CoyoteAdapter-[DirectJDKLog.java:180]-The variable [uriBC] has value [<Path_Param>]
2021-05-28 13:04:37 [http-nio-9112-exec-1] DEBUG o.a.catalina.connector.CoyoteAdapter-[DirectJDKLog.java:180]-The variable [semicolon] has value [-1]
2021-05-28 13:04:37 [http-nio-9112-exec-1] DEBUG o.a.catalina.connector.CoyoteAdapter-[DirectJDKLog.java:180]-The variable [enc] has value [utf-8]
2021-05-28 13:04:45 [http-nio-9112-exec-1] DEBUG o.a.c.a.AuthenticatorBase-[DirectJDKLog.java:180]-Security checking request GET <Path_Param>
2021-05-28 13:04:45 [http-nio-9112-exec-1] DEBUG org.apache.catalina.realm.RealmBase-[DirectJDKLog.java:180]- No applicable constraints defined
2021-05-28 13:04:45 [http-nio-9112-exec-1] DEBUG o.a.c.a.AuthenticatorBase-[DirectJDKLog.java:180]- Not subject to any constraint
2021-05-28 13:04:45 [http-nio-9112-exec-1] INFO o.a.c.c.C.[Tomcat].[localhost].[/]-[DirectJDKLog.java:180]-Initializing Spring FrameworkServlet 'dispatcherServlet'
If you look at the above logs when the call is made to AuthenticatorBase from CoyoteAdapter, it gets stuck for 6-7 sec ( Look at the difference in log timings ), and this is happening for every API call.
Strangely, the other services that are using the same version of Tomcat are not having this issue. Could someone please help us out to find out the root cause of this issue?
PS: I know that probably upgrading to the latest Spring version might solve this, but that option is off the table for now.
Adding thread dump taken at the time when the thread is waiting:
`"http-nio-9112-exec-1" #64 daemon prio=5 os_prio=0 tid=0x00007fe2c800d800 nid=0x519c runnable [0x00007fe3156e6000]
java.lang.Thread.State: RUNNABLE
at java.util.zip.Inflater.inflateBytes(Native Method)
at java.util.zip.Inflater.inflate(Inflater.java:259)
- locked <0x00000000f814e928> (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:112)
- locked <0x00000000e35168e0> (a java.lang.Object)
at org.apache.catalina.webresources.AbstractArchiveResourceSet.getResource(AbstractArchiveResourceSet.java:256)
at org.apache.catalina.webresources.StandardRoot.getResourceInternal(StandardRoot.java:281)
at org.apache.catalina.webresources.CachedResource.validateResource(CachedResource.java:95)
at org.apache.catalina.webresources.Cache.getResource(Cache.java:70)
at org.apache.catalina.webresources.StandardRoot.getResource(StandardRoot.java:216)
at org.apache.catalina.webresources.StandardRoot.getResource(StandardRoot.java:206)
at org.apache.catalina.mapper.Mapper.internalMapWrapper(Mapper.java:1006)
at org.apache.catalina.mapper.Mapper.internalMap(Mapper.java:822)
at org.apache.catalina.mapper.Mapper.map(Mapper.java:687)
at org.apache.catalina.connector.CoyoteAdapter.postParseRequest(CoyoteAdapter.java:886)
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:517)
at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1095)
at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:672)
at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1502)
at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1458)
- locked <0x00000000e80faeb8> (a org.apache.tomcat.util.net.NioChannel)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
at java.lang.Thread.run(Thread.java:748)`
