Diagnosing and Resolving a 100 ms Latency Issue in a Spring Boot Channel System Using Arthas

Background

The company runs a channel system built with Spring Boot and embedded Tomcat that mainly performs message conversion and parameter validation. After code optimizations, the interface still exhibited an extra ~100 ms latency: the server logged ~150 ms processing time while the client observed ~250 ms.

Investigation Process

Code Analysis

The project is a typical Spring Boot web application using the integrated Tomcat; no custom filters or interceptors were found, so business code was initially ruled out.

Call Flow Analysis

Requests flow through Nginx → Channel System . Network latency was verified with ping commands, showing no delay between the client, Nginx, and the server.

[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
...

Directly calling the service via curl on localhost:7744/send still took ~73 ms for the first request and ~3 ms for the second, indicating a caching effect.

[jboss@VM_10_91_centos tmp]$ curl -w "@curl-time.txt" http://127.0.0.1:7744/send
success
http: 200
time_total: 0.073 s

Repeated requests were fast, suggesting that some cache was involved.

Arthas Analysis

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

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

Further tracing of org.apache.coyote.http11.Http11Processor.service revealed a 131 ms cost, with a notable 74 ms spent in org.apache.catalina.webresources.JarWarResourceSet:getArchiveEntries() , which loads JAR resources.

[arthas@24851]$ trace org.apache.catalina.webresources.JarWarResourceSet getArchiveEntries
... 75.743681ms org.apache.catalina.webresources.JarWarResourceSet:getArchiveEntries()

Using watch on TomcatJarInputStream.createZipEntry displayed the loaded resources, all belonging to Swagger‑UI (e.g., META-INF/resources/webjars/springfox-swagger-ui/ ).

result=@ArrayList[
    @String[META-INF/],
    @String[META-INF/MANIFEST.MF],
    @String[META-INF/resources/],
    @String[META-INF/resources/swagger-ui.html],
    ...
]

Removing the Swagger dependencies from pom.xml eliminated the extra latency.

io.springfox
springfox-swagger2
2.9.2
io.springfox
springfox-swagger-ui
2.9.2

Tomcat‑Embed Bug Analysis & Solution

The root cause is a bug in Tomcat‑embed 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 the ~70 ms overhead. The bug is mitigated by the internal cache ( org.apache.catalina.webresources.Cache ) which expires after 5 seconds, explaining why consecutive requests are fast.

Upgrading Tomcat‑embed to 8.5.40 or newer fixes the issue. This can be done by overriding the tomcat.version property in the Maven pom.xml or by upgrading Spring Boot to 2.1.0.RELEASE or later.

8.5.40

Conclusion

By systematically eliminating network factors, measuring request times, and leveraging Arthas for deep tracing, the hidden latency was traced to a Tomcat‑embed bug triggered by Swagger‑UI resources. Upgrading Tomcat (or Spring Boot) resolves the performance problem.