Diagnosing and Solving a 100 ms Delay in Spring Boot Embedded Tomcat Using Arthas

Background

The project is a simple Spring‑Boot web service that acts as a channel gateway, mainly performing message conversion and parameter validation. After code optimisation the overall response time was still 100 ms slower than expected; the service logged ~150 ms while the caller observed ~250 ms.

Location Process

First the network path was verified:

Nginx - reverse proxy -> channel system

[jboss@VM_0_139_centos ~]$ 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. Then the service was called directly via curl on the loopback address:

[jboss@VM_10_91_centos tmp]$ 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 took ~73 ms, the second request (immediately after) took only ~3 ms, indicating a caching effect.

Arthas Analysis

Arthas, Alibaba’s Java diagnostic tool, was used to trace the request path. Tracing org.springframework.web.servlet.DispatcherServlet showed that Spring MVC only consumed ~18 ms, leaving ~97 ms unaccounted for.

[arthas@24851]$ trace org.springframework.web.servlet.DispatcherServlet *
... 15.050124 ms org.springframework.web.servlet.DispatcherServlet:doDispatch()
...

Further tracing of the Tomcat HTTP processor revealed a long‑lasting call:

[arthas@24851]$ trace org.apache.coyote.http11.Http11Processor service
... 131.650285 ms org.apache.coyote.http11.Http11Processor:service()
...

Drilling down to org.apache.catalina.webresources.JarWarResourceSet:getArchiveEntries() exposed a 75 ms cost while loading JAR entries, especially META‑INF resources.

[arthas@24851]$ trace org.apache.catalina.webresources.JarWarResourceSet getArchiveEntries
... 75.743681 ms org.apache.catalina.webresources.JarWarResourceSet:getArchiveEntries()
   +---[0.451916 ms] org.apache.catalina.webresources.TomcatJarInputStream:
+---[34.479307 ms] 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/swagger-ui.html
...

Removing the springfox-swagger2 and springfox-swagger-ui dependencies eliminated the extra ~70 ms latency.

Tomcat‑Embed Bug Analysis & Solution

The root cause is a bug in Tomcat 8.5.31 (bundled with Spring Boot 2.0.2.RELEASE) where org.apache.catalina.mapper.Mapper#internalMapWrapper re‑checks static resources on every request. The result is cached for 5 seconds, explaining why consecutive requests are fast.

Upgrading the embedded Tomcat to 8.5.40+ (or upgrading Spring Boot to 2.1.0+ which ships a newer Tomcat) fixes the problem.

For Maven projects that inherit spring-boot-starter-parent , the version can be overridden:

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

Alternatively, upgrade the Spring Boot version.

Conclusion

By combining network diagnostics, curl timing, and Arthas tracing, the hidden cost of loading Swagger‑UI resources in an old Tomcat embed was uncovered and resolved with a simple version bump.