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

Background – A company’s channel system, built as a Spring Boot web application with embedded Tomcat, was experiencing an unexpected ~100 ms extra latency: the server logged ~150 ms processing time while the client observed ~250 ms.

Investigation Process

Code Analysis

The project had no custom filters or interceptors, so the issue was not in business logic.

Call Flow Analysis

The request path was Nginx → Channel System. Network latency between the client, Nginx, and the server was verified with ping commands, all showing sub‑millisecond delays.

ping 10.0.0.139
64 bytes from 10.0.0.139: icmp_seq=1 ttl=64 time=0.029 ms

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

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

Repeated requests showed the same pattern: the first call after a pause was slow, subsequent calls were fast.

Using Arthas for Diagnosis

Arthas, Alibaba’s open‑source Java diagnostic tool, was employed. The trace command was used to monitor the Spring MVC entry point, revealing that Spring MVC only consumed ~18 ms of the total time, leaving ~97 ms unaccounted for.

Further tracing of the Tomcat request processor ( org.apache.coyote.http11.Http11Processor.service) exposed a 129 ms hotspot.

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

The method TomcatJarInputStream.createZipEntry() was called 31 times, taking a total of 74 ms, suggesting heavy JAR‑resource loading.

protected ZipEntry createZipEntry(String name) {
    JarEntry e = new JarEntry(name);
    if (man != null) {
        e.attr = man.getAttributes(name);
    }
    return e;
}

Using Arthas watch on this method revealed that the loaded resources were Swagger‑ui static files (from springfox-swagger2 and springfox-swagger-ui).

Tomcat‑embed Bug Analysis & Solution

The root cause was a bug in Tomcat‑embed 8.5.31 (bundled with Spring Boot 2.0.2.RELEASE) where the method org.apache.catalina.mapper.Mapper#internalMapWrapper re‑examined static resources on every request, bypassing the cache.

Because the cache TTL is 5000 ms, a request after the cache expires incurs the 70 ms overhead while consecutive requests hit the cache and are fast.

Fix: upgrade the embedded Tomcat version to 8.5.40 or later (or upgrade Spring Boot to 2.1.x which includes a newer Tomcat). The Maven change is either:

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

or simply bump the Spring Boot parent version.

Conclusion

The latency issue was not due to business code but to a Tomcat‑embed bug triggered by Swagger‑ui resources. Upgrading Tomcat (or Spring Boot) eliminates the extra 70 ms delay.

For further reading, the author provides PDF collections of Spring Cloud, Spring Boot, and MyBatis advanced topics (links omitted here).