Tomcat average latency lies: why you need p95/p99 from the access log

Your latency dashboard says Tomcat is healthy at 250ms. Your users say requests take 15 seconds. Both are right. The JMX average your dashboard consumes is structurally incapable of representing the tail.

Catalina:type=GlobalRequestProcessor exposes processingTime (cumulative milliseconds since startup) and requestCount. Divide the deltas over a window and you get a mean. A workload where p50 is 100ms but p99 is 15s produces an average of roughly 250ms. 1% of your users wait an eternity, but the chart looks fine. Stuck threads averaged into fast requests are the classic blind spot, and Tomcat gives you nothing from JMX that breaks the mean open.

To see real user latency you need per-request timings from the access log. The default pattern does not include them. Neither does combined.

How the JMX average works

Tomcat tracks request processing time as a single cumulative counter.

• MBean: Catalina:type=GlobalRequestProcessor,name="http-nio-8080"
• Attributes: processingTime (cumulative ms since server start), requestCount, maxTime, errorCount

To get anything useful, you compute (delta processingTime) / (delta requestCount) over a polling window. That number is an arithmetic mean. It has no shape, no distribution, no percentile information. The JMX MBean does not expose anything richer.

Three properties make this metric dangerous as a user-experience signal:

1. It is a mean over a heavy-tailed population. Web request latency is almost never symmetric. A small fraction of slow requests (slow queries, GC pauses, lock contention, downstream retries) can be invisible at the mean while dominating user experience.
2. It excludes queue time. processingTime measures the time a worker thread spends processing the request. Time spent waiting in the accept queue, or in the NIO poller waiting for a free thread, is not counted. When the thread pool is saturated, the JMX average can keep dropping while users wait seconds for their request to even start.
3. It is a windowless cumulative counter. Most monitoring tools derive a windowed average by differencing. The value still collapses to one number per window. There is no way to recover the original distribution from processingTime and requestCount.

The arithmetic is brutal. Consider a connector serving 989 requests at 100ms and 11 requests stuck at 15 seconds each:

• Total processing time: 989 * 100 + 11 * 15000 = 263,900 ms
• Request count: 1000
• Mean: roughly 264ms
• p99 (nearest-rank, index 990): 15000ms

A dashboard shows ~264ms and pages nobody. The 11 users at 15 seconds are invisible at the mean but dominate p99. This is the gap JMX cannot close.

flowchart LR
  A["1000 requests"] --> B["JMX processingTime sum"]
  B --> C["mean ~264ms
healthy"]
  A --> D["Access log %{ms}T per request"]
  D --> E["p50 = 100ms"]
  D --> F["p95 = 15000ms"]
  D --> G["p99 = 15000ms"]
  G --> H["11 users wait 15s"]
  C -. misses .-> H

maxTime (the slowest single request since startup) is the only tail-related signal in JMX. It is a non-decreasing high watermark that resets on restart. It tells you something bad happened at some point, but not when, not how often, and not the shape of the distribution.

Why default access logs are blind

The default AccessLogValve pattern is the Common Log Format:

%h %l %u %t "%r" %s %b

No timing field. The combined alias appends Referer and User-Agent and still has no timing field. Many deployments copy one of those two patterns, ship the logs to a SIEM or aggregator, and assume latency analysis is possible later. It is not. Without %D, %T, or %{xxx}T, there is no per-request timing in the log at all.

The operational sequence most teams hit:

1. Pagers fire on user-reported latency. The Tomcat dashboard shows average ~250ms.
2. The operator pulls the access log to look for slow requests.
3. The log has status codes, sizes, and URLs, but no timing column.
4. Diagnosis is blocked until someone changes the pattern and waits for new traffic.

The fix is to add a timing field. The trap is that %D is not portable across Tomcat versions.

Enabling per-request timing

Tomcat’s access log valve supports several timing tokens. Their units and availability depend on the major version.

The migration trap is real. The Tomcat 9 to 10 migration guide documents that %D changed from milliseconds to microseconds to align with httpd. Any log parser, dashboard, or alerting rule that assumed %D was milliseconds will silently inflate numbers by 1000x after the upgrade. A 200ms request will appear as 200000 in the log. The recommended portable pattern is %{ms}T, which is explicit and does not depend on the major version.

A practical pattern for Tomcat 10.1+:

%h %l %u %t "%r" %s %b %{ms}T

For Tomcat 9.x, where %{xxx}T is not available, use %D (milliseconds in that line):

%h %l %u %t "%r" %s %b %D

For Spring Boot embedded Tomcat, the equivalent lives in application.properties:

server.tomcat.accesslog.enabled=true
server.tomcat.accesslog.pattern=%h %l %u %t "%r" %s %b %{ms}T

The default Spring Boot pattern is also common, with no timing. You must set both enabled and pattern.

One caveat. Both %D and %{ms}T measure wall-clock time from the moment a worker thread picks up the request to the moment the response is committed. They do not include time spent in the accept queue waiting for a free thread. When the thread pool is saturated, queue time is real user-perceived latency that the access log will not show. To detect that condition, watch currentThreadsBusy / maxThreads approaching 1.0 alongside the access log timings. See Tomcat accepts connections but never responds: the TCP-connect trap.

Computing p95 and p99

Once the log has a timing column, percentiles are a sort and a pick. With %{ms}T as the last field:

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

Practical notes:

• Verify the field position. If your pattern puts timing somewhere other than last, change $NF to the right column index. Timing as the last field is the safest layout.
• Verify the unit. Logs written before a Tomcat 10 migration used %D in milliseconds. After migration, %D is microseconds. Mixing the two in one analysis silently corrupts the result by 1000x.
• Group by endpoint, not just connector. A single slow endpoint hidden inside a healthy aggregate is the most common pattern. Filter by URL pattern and compute percentiles per endpoint.
• Filter out health checks and static assets. These inflate the sample size with sub-millisecond noise and pull the average down without informing you about real user paths.
• Watch for bimodal distributions. A p50 at 50ms and a p99 at 15s with nothing in between usually means two code paths: a fast cached path and a slow uncached path. p95 may sit on either side of the cliff. Plot a histogram, not just the percentiles.

Signals to watch

How Netdata helps

• Per-second collection of processingTime, requestCount, and maxTime from the GlobalRequestProcessor MBean gives you a low-latency mean and a moving watermark. Use this as the trigger to dig into the access log when the mean stays flat but p99 spikes.
• Thread pool utilization alongside latency distinguishes “slow because the app is slow” from “slow because requests are queuing.” When currentThreadsBusy saturates and the JMX mean drops while user latency climbs, you are looking at queue time the access log %D will not show.
• GC pause duration and frequency plotted against request latency reveals the bimodal distribution GC pauses create. Requests in flight during a pause show up as p99 outliers while the mean barely moves.
• Anomaly detection on request-rate and error-rate series surfaces traffic patterns (retry storms, slow-client attacks, bot session creation) that produce tail latency without moving the mean.
• Correlation across connectors, JVM, and host in a single timeline means the moment a p99 spike is reported you can drop straight to the GC, CPU, thread pool, and accept queue views for the same second.

Related guides

• Tomcat accept queue overflow: acceptCount, somaxconn, and Recv-Q
• 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 HTTP Status 503 Service Unavailable: the connector is out of threads
• How Tomcat actually works in production: a mental model for operators