How a Hidden Tomcat Bug Added 70 ms Latency in Spring Boot – Debugging with Arthas

Locating the Issue

The company has a channel system built with Spring Boot and embedded Tomcat that simply converts messages and validates parameters. After code optimizations the response time was still about 100 ms longer than expected; the server logged ~150 ms while the client observed ~250 ms.

Analyzing the Code

The project is a standard Spring Boot web application without custom filters or interceptors, so the problem was not in business code.

Analyzing the Call Flow

Requests flow through Nginx reverse proxy to the channel system. Network latency was verified with ping:

ping 10.0.0.139
PING 10.0.0.139 (10.0.0.139) 56(84) bytes of data.
64 bytes from 10.0.0.139: icmp_seq=1 ttl=64 time=0.029 ms
...

Ping results showed no network delay. Directly calling the service via localhost eliminated Nginx and network factors:

curl -w "@curl-time.txt" http://127.0.0.1:7744/send
success
http: 200
dns: 0.001s
redirect: 0.000s
time_connect: 0.001s
time_starttransfer: 0.073s
time_total: 0.073s

The first request still took ~73 ms, while a second immediate request completed in 3 ms, suggesting a caching effect.

Using Arthas for Deep Diagnosis

Arthas, Alibaba’s Java diagnostic tool, was employed. The trace command on org.springframework.web.servlet.DispatcherServlet showed that Spring MVC consumed only about 18 ms of the total time, leaving ~97 ms unaccounted for.

[arthas@24851]$ trace org.springframework.web.servlet.DispatcherServlet *
... cost in 508 ms ...
[2.952142ms] DispatcherServlet:buildLocaleContext()
[18.08903ms] DispatcherServlet:doService()
[15.050124ms] DispatcherServlet:doDispatch()

Further tracing of org.apache.coyote.http11.Http11Processor.service revealed a 129 ms hotspot:

[arthas@24851]$ trace org.apache.coyote.http11.Http11Processor service
... cost in 269 ms ...
[131.650285ms] Http11Processor:service()
[0.14319ms] Http11InputBuffer:parseRequestLine()
[0.14319ms] Http11InputBuffer:parseHeaders()
[129.868916ms] Adapter:service()

Tracing

org.apache.catalina.webresources.JarWarResourceSet.getArchiveEntries

showed repeated loading of JAR entries, especially META‑INF resources, taking 74 ms total over 31 calls.

[arthas@24851]$ trace org.apache.catalina.webresources.JarWarResourceSet getArchiveEntries
... cost in 150 ms ...
[75.743681ms] JarWarResourceSet:getArchiveEntries()
... loading META‑INF/, META‑INF/MANIFEST.MF, swagger‑ui resources ...

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

[arthas@24851]$ watch org.apache.catalina.webresources.TomcatJarInputStream createZipEntry "{params[0]}"
... result=[META-INF/]
... result=[META-INF/MANIFEST.MF]
... result=[META-INF/resources/swagger-ui.html]
... result=[META-INF/resources/webjars/springfox-swagger-ui/...]

Removing the Swagger dependencies ( springfox-swagger2 and springfox-swagger-ui) eliminated the latency.

Root Cause and Solution

The latency was caused by a bug in Tomcat‑embed 8.5.31 (used by Spring Boot 2.0.2.RELEASE) that re‑examined static resources on each request. Upgrading Tomcat‑embed to 8.5.40 or newer (or upgrading Spring Boot to 2.1.0+ which bundles a fixed Tomcat version) resolves the issue.

Typical fix in Maven:

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

After the upgrade the mysterious 70 ms delay disappears, confirming that the issue was a Tomcat‑embed bug triggered by Swagger static resource handling.