Tomcat request processing time climbing: reading processingTime correctly

Your monitoring shows Tomcat request processing time trending upward. Before you chase the trend, understand what the processingTime attribute actually represents.

processingTime on the GlobalRequestProcessor MBean is a cumulative counter of wall-clock milliseconds across all requests processed since Tomcat started. It is not a per-request value, not a rate, and not a percentile. Reading it raw produces a number that only increases until the JVM restarts. To get anything useful, compute a delta over a time window and divide by the delta of requestCount over the same window.

Even that gives you an average, which hides the outliers that usually matter most. A few 30-second requests averaged into a thousand 10-millisecond requests look unremarkable. Rising average latency is worth investigating, but it is never the full picture.

This article covers how to read processingTime correctly, what climbing values typically indicate, which correlated signals confirm the root cause, and the common misreadings that send operators down the wrong path.

What processingTime actually measures

The processingTime attribute lives on the Catalina:type=GlobalRequestProcessor,name="http-nio-8080" MBean. Adjust the connector name for your setup (http-nio-8443 for HTTPS, or a different executor name if you configured a shared thread pool).

The attribute accumulates wall-clock milliseconds from the moment a worker thread begins processing a request to when the response is committed.

• Cumulative since JVM start. The value never decreases during normal operation. It resets on restart.
• Wall-clock based. The measurement uses System.currentTimeMillis(), which is not monotonic. Clock adjustments, including NTP steps, can corrupt delta computations.
• Across all requests. It sums processing time for every request: health checks, static assets, slow endpoints, and fast endpoints alike. A global average across heterogeneous traffic is rarely meaningful without filtering by endpoint.
• Excludes queue wait time. The counter starts when a worker thread picks up the request, not when the TCP connection was accepted. Time spent in the accept queue or the NIO poller is invisible to this metric.

The same MBean exposes related attributes:

maxTime is a forensic signal, not a trend. A single outlier sets it permanently until restart.

Reading it correctly: the delta computation

avg_ms = (processingTime[t2] - processingTime[t1]) / (requestCount[t2] - requestCount[t1])

Both attributes are cumulative counters. The delta of each over the same window gives total processing time spent and total requests completed. Their ratio is average milliseconds per request.

Your monitoring system should handle this automatically if it treats both attributes as counters and computes rates. If you read raw JMX values manually, track the previous sample yourself:

# Sample processingTime and requestCount from JMX (adjust connector name)
java -jar jmxterm.jar -l localhost:9090 -n -v silent -e \
  "get -b Catalina:type=GlobalRequestProcessor,name=\"http-nio-8080\" processingTime requestCount"

Run twice with a fixed interval between samples. Subtract earlier values from later values. Divide the processingTime delta by the requestCount delta.

Common errors:

• Reading the raw value. A raw processingTime of 4,800,000 ms means nothing without request count and time window. It could be 4,800 requests at 1 second each, or 4.8 million requests at 1 millisecond each.
• Dividing by wall-clock time instead of request count. processingTime is not a rate. Dividing by elapsed seconds gives “average concurrent processing time,” which is not useful.
• Ignoring counter resets. If Tomcat restarted between samples, the delta goes negative or wraps. Detect resets via uptime change and discard the interval.

What it does not measure

processingTime captures the time from worker thread dispatch to response commit. It excludes:

• Accept queue wait. Time in the OS TCP backlog before Tomcat accepts the connection. Invisible to JMX. Check with ss -tnl Recv-Q on the listen socket.
• Poller-to-thread dispatch wait. With NIO, a connection registered with the poller may wait for a free worker thread. This wait is not in processingTime.
• Network transfer time. The metric stops when the response is committed, not when the client receives the last byte.

If users report slowness but processingTime is flat, the delay is in the queue or the network. Compare client-measured latency with server-side %D from the access log:

# Client-side total time (connect + queue wait + processing + transfer)
curl -s -o /dev/null -w "%{time_total}s" http://localhost:8080/endpoint

The gap between client total time and server-side %D approximates queue wait plus network time.

What climbing processing time usually means

When the computed average rises, the cause is almost always one of four:

Slow backend

The most common cause. A database, downstream API, or external service slows down. Each request holds its worker thread longer while waiting. The thread pool fills, currentThreadsBusy approaches maxThreads, and throughput drops because no threads are available. CPU stays low because threads are blocked on I/O, not computing.

GC pauses

GC pauses inject latency non-uniformly. Only requests processed during a pause are affected, producing a bimodal distribution: most requests complete quickly, while a subset caught during a GC window take hundreds of milliseconds to seconds longer. The average shifts upward, but the median may stay flat. Correlate with collection time from the java.lang:type=GarbageCollector MBeans.

Lock contention

Application-level synchronization bottlenecks. Multiple threads compete for a monitor lock. Thread dumps show many BLOCKED threads at the same code location. CPU may be moderate (some threads compute while others wait), and throughput degrades as concurrency increases.

CPU starvation

When the JVM does not get enough CPU (container throttling, noisy neighbors, genuine overload), every request takes longer. The increase is uniform across endpoints, unlike GC or backend issues. Check ProcessCpuLoad from java.lang:type=OperatingSystem and container cgroup throttle metrics.

Correlating with thread pool and GC signals

Rising average processing time is not actionable alone. You need correlated signals to narrow the cause.

flowchart TD
    AVG["Average processing time rising"]
    AVG --> Q1{"Thread pool busy?"}
    Q1 -->|"Near maxThreads"| Q2{"CPU utilization high?"}
    Q2 -->|"No"| R1["Slow backend: threads blocked on I/O"]
    Q2 -->|"Yes"| R2["CPU-bound work or GC thrashing"]
    Q1 -->|"Low"| Q3{"GC collection time elevated?"}
    Q3 -->|"Yes"| R3["GC pauses: bimodal latency"]
    Q3 -->|"No"| R4["Check access log percentiles for tail"]

Key patterns:

• Processing time and thread pool busy rising together: threads are occupied longer per request. Low CPU means blocked on I/O (backend, database). High CPU means computing (lock spinning, GC consuming cycles).
• Processing time and GC collection time spiking together: GC pauses inject latency. The average rises while the median stays flat.
• Processing time rising, throughput dropping: the system is saturated. Each request takes longer, fewer complete per second, and the thread pool cannot keep up. This is thread starvation.
• Processing time rising, throughput stable: individual requests are slower but the system has capacity. Backend or application regression, not saturation.

When averages lie: the access log alternative

JMX processingTime gives an average. Averages hide the tail. A p50 of 50 ms with a p99 of 8 seconds averages to something that looks acceptable, but 1% of users wait 8 seconds.

For percentile visibility, use per-request data from the access log. The default AccessLogValve pattern does not include timing. You must add a timing pattern element.

The two relevant elements:

• %D: Time taken to process the request, in milliseconds.
• %T: Time taken to process the request, in seconds.

Once you have per-request timing in the access log, compute percentiles:

# Compute p50, p95, p99 from the last column of today's access log
# Assumes %D is the last field in your pattern
awk '{print $NF}' /var/log/tomcat/localhost_access_log.$(date +%Y-%m-%d).txt | \
  sort -n | awk '{a[NR]=$1} END {
    print "p50="a[int(NR*0.5)], "p95="a[int(NR*0.95)], "p99="a[int(NR*0.99)]
  }'

If p99 is 50x p50, you have a bimodal distribution. That typically points to GC pauses or a subset of requests hitting a slow code path.

Common misreadings

Reading the raw cumulative value as per-request. A processingTime of 8,000,000 means 8,000 seconds of cumulative processing since start, not 8 seconds per request. Without the requestCount denominator, the number is meaningless.

Alerting on average alone. A 2x increase in average processing time could mean “every request is 2x slower” (uniform degradation, likely CPU or backend) or “1% of requests are 100x slower” (tail latency, likely GC or a slow endpoint). Only percentile-based alerts from access log data distinguish the two.

Attributing all latency to the application. processingTime starts when the worker thread begins, not when the request arrived at the server. Queue wait, accept backlog, and network latency are invisible. If users report slowness but processingTime is flat, check the OS accept queue and network path.

Assuming maxTime reflects current state. maxTime is set by the slowest single request since JVM start and never decreases. A maxTime of 60,000 ms from a stuck thread three weeks ago tells you nothing about current latency.

Signals to watch in production

How Netdata helps

• Netdata collects processingTime and requestCount from GlobalRequestProcessor at per-second resolution and computes the rate automatically, so you see average ms per request without manual delta math.
• The Tomcat dashboard surfaces currentThreadsBusy alongside maxThreads, so thread saturation and latency spikes share the same per-second timeline.
• JVM GC collection time appears on the same chart timeline as request processing time, making bimodal latency from GC pauses visible when you overlay the charts.
• OS-level signals (CPU utilization, accept queue depth, network counters) sit alongside JVM metrics, so you can distinguish Tomcat-internal latency from queue wait and network delay.

Related guides

• Tomcat accept queue overflow: acceptCount, somaxconn, and Recv-Q
• Tomcat java.net.BindException: Address already in use: the connector never starts
• Tomcat classloader leak on redeploy: why the old WebappClassLoader never dies
• Tomcat connection refused: maxConnections and acceptCount both exhausted
• Tomcat accepts connections but never responds: the TCP-connect trap
• Tomcat frequent Full GC: pause time, G1, and the 5% overhead rule
• Tomcat GC death spiral: full GCs dominating and throughput collapsing
• Tomcat heap dump before restart: capturing evidence with jmap and jstack
• Tomcat heap usage: watch the post-GC baseline, not the sawtooth peak
• How Tomcat actually works in production: a mental model for operators
• Tomcat HTTP Status 503 Service Unavailable: the connector is out of threads
• Tomcat process not running: crashes, OOM-kills, and failed restarts