Tomcat access log setup: adding %D and %T for per-request latency

Tomcat’s common and combined access log patterns record the request line, status, and byte count. They do not record per-request latency. Without per-request timing in the access log, you are limited to the cumulative average that JMX exposes via processingTime / requestCount on the GlobalRequestProcessor MBean. That average hides the tail: a few 15-second requests averaged against a thousand 10-millisecond requests looks fine while real users time out.

Adding %D or %T to the AccessLogValve pattern puts per-request latency alongside the status code, URL, and client IP. This enables p95/p99 computation, 5xx-only latency filtering, and per-endpoint slow-request investigation. The change is one pattern string. The traps are version-specific units and synchronous logging overhead.

What this captures

The timing patterns measure wall-clock time from when the request is received by the connector to when the response is fully processed. They do not include time spent waiting in the OS accept queue for a worker thread. If clients report high latency but %D looks normal, the bottleneck is in thread-pool queuing or connection acceptance, not in request processing. For the full request lifecycle, see How Tomcat actually works in production.

sequenceDiagram
    participant C as Client
    participant Q as OS Accept Queue
    participant W as Worker Thread
    participant B as App or Backend

    C->>Q: TCP connect
    Note over Q: Wait for free thread
Not in %D
    Q->>W: Dispatch
    Note over W: %D and %T start
    W->>B: Process request
    B-->>W: Response data
    W->>C: First byte
    Note over W: %F stops
    W->>C: Body complete
    Note over W: %D and %T stop

The %F pattern measures time to first byte. The gap between %F and %D reveals how long the application spent writing the response body after the first byte was committed. A large gap with a small %F points to slow streaming or large response serialization.

The unit of %D depends on your Tomcat version. Verify this before relying on the numbers.

The critical difference: %D changed from milliseconds to microseconds in Tomcat 10.0, aligning with Apache httpd semantics. A 250-millisecond request logs as 250 on Tomcat 9.0.x and as 250000 on Tomcat 10.0+. The numerical value jumps 1000x with no actual performance change. If you migrate between versions without adjusting, dashboards and alert thresholds break silently.

The %{xxx}T family (available on Tomcat 10.0 and later) lets you pin the unit explicitly. Use %{ms}T for millisecond output regardless of Tomcat version semantics. This is the version-portable choice for cross-version deployments or migration periods.

Prerequisites

Standalone Tomcat. The AccessLogValve is configured in $CATALINA_BASE/conf/server.xml, typically nested inside the <Host> element. Most distributions ship it enabled with the common pattern. Verify before editing:

# Check current AccessLogValve configuration
grep -A5 'AccessLogValve' $CATALINA_BASE/conf/server.xml

Embedded Tomcat (Spring Boot). Access logging is disabled by default. Enable it via application properties, not server.xml. The pattern uses the same codes as the standalone valve.

Know your version. The %D unit depends on whether you are on 10.0 or later. Check with:

# Print Tomcat version
java -cp $CATALINA_HOME/lib/catalina.jar org.apache.catalina.util.ServerInfo

Procedure

1. Back up the current configuration

# Standalone Tomcat: back up server.xml
cp $CATALINA_BASE/conf/server.xml $CATALINA_BASE/conf/server.xml.bak

2. Add the timing pattern

For standalone Tomcat, edit the pattern attribute on the AccessLogValve element in server.xml. Append %D to your existing pattern:

<Valve className="org.apache.catalina.valves.AccessLogValve"
       directory="logs"
       prefix="localhost_access_log" suffix=".txt"
       pattern="%h %l %u %t &quot;%r&quot; %s %b %D" />

The " entities are XML escaping for the literal double quotes around %r. If you are on Tomcat 10.0 or later and want explicit millisecond output, use %{ms}T instead of %D:

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

For Spring Boot embedded Tomcat, add the properties to your application.properties or application.yml:

server.tomcat.accesslog.enabled=true
server.tomcat.accesslog.pattern=%h %l %u %t "%r" %s %b %D

On Spring Boot with embedded Tomcat 10.0+, use %{ms}T instead of %D for consistent millisecond units.

3. Consider structured logging on 10.1+

If you are on Tomcat 10.1.8 or later, the JsonAccessLogValve outputs the same pattern codes as JSON objects instead of delimited text. This eliminates field-position parsing fragility and is preferable if your log pipeline expects structured data:

<Valve className="org.apache.catalina.valves.JsonAccessLogValve"
       directory="logs"
       prefix="localhost_access_log" suffix=".json"
       pattern="%h %l %u %t &quot;%r&quot; %s %b %D" />

If you use non-default relaxedPathChars or relaxedQueryChars on the connector with JsonAccessLogValve, verify you are on Tomcat 11.0.21 or later (or 10.1.54 or later for 10.1.x). Earlier 11.0.x versions, and 10.1.0-M1 through 10.1.53, had a JSON injection issue (CVE-2026-34483) when those attributes were set.

4. Restart Tomcat

server.xml changes are not hot-reloadable. A full restart is required for standalone Tomcat and Spring Boot alike. This drops in-flight requests.

# Disruptive: drops in-flight requests and briefly rejects new connections
sudo systemctl restart tomcat

Verifying it works

After restart, send a test request and check the log output:

# Send a request
curl -s -o /dev/null http://localhost:8080/your-endpoint

# Check the latest entry (timing field is last if %D is last in pattern)
tail -1 $CATALINA_BASE/logs/localhost_access_log.$(date +%Y-%m-%d).txt

The output should end with a numeric timing value. Verify the unit matches your version expectation: on Tomcat 9.0.x, a 50-millisecond request shows approximately 50. On Tomcat 10.0+, the same request shows approximately 50000.

Quick percentile check from the timing field:

# Extract the last field and compute p50/p95/p99
# Assumes %D is the last pattern element
awk '{print $NF}' $CATALINA_BASE/logs/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)]
  }'

The $NF approach works because the timing value is the last whitespace-delimited token regardless of how earlier fields (timestamp, request line) split. For 5xx-only analysis, field positions depend on your exact pattern and whether URLs contain spaces. Use a proper log parser (Filebeat, Fluentd, Vector) or switch to JSON output for reliable structured parsing in production.

Common pitfalls

The %D unit change on 10.0+. The most common migration trap. A 1000x numerical jump in %D values after upgrading from 9.0.x to 10.0+ is expected, not a performance regression. Use %{ms}T on 10.0+ for millisecond output that matches pre-10.0 %D semantics, or update thresholds and dashboards explicitly.

Regression in Tomcat 10.1.0 through 10.1.50. Bug 69932 caused %D and %T to log the request start time instead of the end time. Response times appear artificially low on affected versions. Fixed in 10.1.51. If your timing values look suspiciously flat or low after upgrading to 10.1, check your patch level.

Synchronous logging overhead. The AccessLogValve runs in the request processing thread. With buffered="true" (the default), formatted entries accumulate in a buffer before flushing to disk, which reduces per-request I/O. But the string formatting still happens on the request thread. At very high throughput, access logging becomes its own CPU consumer on request threads. If you add %D and see request-thread CPU rise with no corresponding application work, the pattern string length may be the cause. Keep the pattern minimal: avoid redundant fields you do not parse.

sendfile and byte-count accuracy. When Tomcat uses sendfile for large static responses, bytes are written asynchronously in a separate thread. The %b (bytes sent) field records the count passed to the sendfile thread, not necessarily the bytes fully transmitted. %D and %F timing are not affected by sendfile, but byte-count analysis can be misleading for sendfile-served responses.

%D excludes accept-queue wait. %D starts when the request is received by the connector, after the OS accept queue. If clients report multi-second latency but %D shows sub-100ms values, the delay is in thread-pool queuing or connection backlog, not request processing. Compare client-measured total time against server-side %D to estimate queue wait. For the full accept-queue diagnosis flow, see Tomcat accept queue overflow.

resolveHosts is no longer supported. If your existing configuration uses resolveHosts="true", remove it. It forces a DNS lookup on every request in the request thread, adding unpredictable latency. The attribute is no longer supported; control hostname resolution via the connector’s enableLookups attribute (set to false in production) instead.

JDBCAccessLogValve is deprecated. If you are using JDBCAccessLogValve to write access logs directly to a database, note that it is deprecated and scheduled for removal in Tomcat 12. Each request blocks on a database insert in the request thread, which is worse than file-based logging for latency. Migrate to file-based AccessLogValve or JsonAccessLogValve with a log shipper.

Signals to monitor

How Netdata helps

• Netdata collects per-second JMX metrics from GlobalRequestProcessor and ThreadPool MBeans: processingTime, requestCount, currentThreadsBusy, maxThreads. These give average-latency and thread-pool context that %D cannot provide alone.
• Correlate average processing time with thread-pool utilization to check whether latency spikes coincide with pool saturation. Since %D excludes accept-queue wait, the JMX thread-pool ratio explains the gap between client-perceived latency and server-side %D.
• GC pause metrics from GarbageCollector MBeans at per-second resolution let you check whether p99 spikes align with Full GC events.
• Connection count versus maxConnections and OS-level accept-queue depth (ss Recv-Q) provide context for cases where %D looks healthy but clients report timeouts.
• Error count from GlobalRequestProcessor gives a per-second error-rate baseline to compare against 5xx-only latency from the access log.

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