Why Your Spring Boot API Adds 100ms Latency: Uncovering a Tomcat Embed Bug with Arthas

Background

A company has a channel system that simply forwards requests to third‑party services, performing only message conversion and parameter validation. After optimizing the code, the response time still fell short of the target, showing an extra ~100 ms delay between the recorded processing time (e.g., 150 ms) and the caller's observed latency (≈250 ms).

Investigation Process

Analyze Code

The channel system is a typical Spring Boot web application using the embedded Tomcat. No special filters or interceptors were found, so the problem was not in the business code.

Analyze Call Flow

Network latency was checked with ping from the client to the Nginx host and from Nginx to the channel server; both were negligible. Directly calling the service via curl on the loopback address still took ~73 ms on the first request and ~3 ms on the second, indicating a caching effect.

curl -w "@curl-time.txt" http://127.0.0.1:7744/send

Repeated requests became fast, suggesting that some cache was involved. The suspicion fell on either Tomcat or Spring MVC.

Arthas Analysis

Arthas, an open‑source Java diagnostic tool, was used to trace method execution times.

trace the entry point of Spring MVC: org.springframework.web.servlet.DispatcherServlet trace the Tomcat HTTP processor: org.apache.coyote.http11.Http11Processor.service trace the adapter: org.apache.coyote.Adapter.service The trace of Http11Processor.service revealed a 129 ms hotspot, longer than the original latency because Arthas adds overhead.

org.apache.coyote.http11.Http11Processor:service()
    ...
    +---[129.868916ms] org.apache.coyote.Adapter:service()

Further tracing of

org.apache.catalina.webresources.JarWarResourceSet.getArchiveEntries

showed a 74 ms cost spent in TomcatJarInputStream.getNextJarEntry, which loads META‑INF resources from JAR files.

+---[min=0.004452ms,max=34.479307ms,total=74.206249ms,count=31] org.apache.catalina.webresources.TomcatJarInputStream:getNextJarEntry()

Using watch on TomcatJarInputStream.createZipEntry displayed the actual resource names being loaded, all belonging to Swagger UI:

{params[0]}
    META-INF/
    META-INF/MANIFEST.MF
    META-INF/resources/
    META-INF/resources/swagger-ui.html
    ...

Removing the Swagger‑related JARs ( springfox-swagger2 and springfox-swagger-ui) eliminated the extra latency.

Tomcat Embed Bug Analysis & Fix

The root cause is a bug in Tomcat 8.5.31 (used by Spring Boot 2.0.2.RELEASE) where org.apache.catalina.mapper.Mapper.internalMapWrapper re‑checks static resources on every request, causing repeated JAR scanning. The result is cached for 5 seconds, so consecutive requests are fast.

Upgrading the embedded Tomcat to 8.5.40 or newer (or upgrading Spring Boot to 2.1.0+ which bundles a newer Tomcat) resolves the issue.

How to Upgrade

For Maven projects inheriting spring-boot-starter-parent, override the tomcat.version property:

<properties>
    <tomcat.version>8.5.40</tomcat.version>
</properties>

Or upgrade the Spring Boot version to 2.1.0.RELEASE or later.