Why a Spring Boot API Took 100ms Extra: Tracing Tomcat’s Hidden Jar Loading Bug

Background

The company runs a channel system that merely forwards requests, performs message conversion and parameter validation, and sits between upstream services and third‑party channels. After code optimisation the response time still fell short of the target, with about 100 ms extra time observed between the service’s internal timing and the client‑side latency.

Investigation Process

Code analysis

The system is a typical Spring Boot web application using the embedded Tomcat server. No custom filters or interceptors were found, so business code was initially ruled out.

Call‑flow analysis

The request flow is Nginx → Channel System. Ping tests from the host to the Nginx server and from Nginx to the channel server showed sub‑millisecond latency, confirming the network is not the cause.

By bypassing Nginx and calling the service directly via curl http://127.0.0.1:7744/send, the first request took about 73 ms while the second request (made immediately after) took only 3 ms, suggesting a caching effect.

Further testing revealed that if a pause is introduced between requests, the latency jumps back to >70 ms, indicating that some resource is being re‑loaded after its cache expires.

Using Arthas for Deep Tracing

Arthas, Alibaba’s open‑source Java diagnostic tool, was employed. The trace command was first run on Spring MVC entry points, showing that Spring MVC itself consumed only ~18 ms of the total 115 ms observed by the client.

Since the remaining time could not be accounted for, the investigation shifted to Tomcat. Using stack org.springframework.web.servlet.DispatcherServlet identified the call chain leading to org.apache.coyote.http11.Http11Processor.service. Tracing this class highlighted a 129 ms hotspot.

Further tracing of org.apache.catalina.webresources.TomcatJarInputStream revealed repeated calls to createZipEntry:

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

The method loads JAR entries for META-INF/ and META-INF/MANIFEST.MF . The logs showed 31 such calls consuming a total of ~74 ms. Using watch on TomcatJarInputStream.createZipEntry exposed the actual resource name being loaded: swagger-ui , a Swagger UI library packaged as a JAR. Removing the Swagger JAR from the project eliminated the mysterious 70 ms delay.

Root Cause Analysis

The issue stems from a bug in Tomcat‑embed version 8.5.31 (used by Spring Boot 2.0.2.RELEASE). The method org.apache.catalina.mapper.Mapper#internalMapWrapper re‑validates static resources on every request, causing the JAR’s static files to be re‑read. Tomcat caches these resources in org.apache.catalina.webresources.Cache with a default TTL of 5000 ms, so consecutive requests hit the cache and are fast, while a pause forces a cache miss and the costly JAR loading. The bug does not appear in local IDE runs because the Spring Boot packaging plugin creates a different class loading path, avoiding the problematic code path.

Solution

Upgrade the embedded Tomcat version to 8.5.40 or later, which contains the fix. This can be done by:

Setting <tomcat.version>8.5.40</tomcat.version> in the Maven <properties> section of the Spring Boot parent POM.

Or upgrading Spring Boot itself to 2.1.0.RELEASE or newer, which bundles a newer Tomcat version.

After the upgrade, the extra 70 ms latency disappears and the service meets the required response time.

Key Takeaways

Network latency may be negligible; hidden framework overhead can dominate response time.

Arthas trace and watch commands are powerful for pinpointing slow paths in production.

Embedded server bugs can surface only in packaged deployments, not in local IDE runs.

Upgrading the embedded container often resolves obscure performance regressions.