Server processing time in tomcat access logs

Question

In order to debug a performance issue I enabled access logs in tomcat. We are not using any apache server. Its the embedded tomcat that we are using.

I'm using following pattern for access logs.

access-patten = %h %l %u %t "%r" %s %b %D

%D = time at which first byte of the request is received ~ time at which last byte of the response is send.

So %D includes network latency as well.

But how do I print time difference between first byte of the request received and first byte of the response sent.

Answer 1

Try %F

You can use %F:

%F - Time taken to commit the response, in milliseconds

Added in 2013

As mentioned by Tomer, since Tomcat version 7.0.42 there is a new log element %F available in the AccessLogValve implementation. You can find a better description of the difference between %D and %F in the case description:

Bug 55102 - Add ability to report time taken to prepare response:

Tomcat's AccessLogValve is able to report the time taken to send an entire request using %D. This is the total processing time and may be affected by network conditions. It is sometimes useful to be able to record the time taken by the server to prepare the response and send the first content to the client.

Attached is a patch that records the time the response is committed and then allows that to be reported in the access log using a %F pattern (which is the same as used by the mod-log-firstbyte module for HTTPD).

Answer 2

How about:

write time until first byte is written (commit time) in millis - %F

from AccessLogValve.html