You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@tomcat.apache.org by Steve van Loben Sels <st...@gmail.com> on 2013/02/14 03:22:13 UTC
AccessLogVale %D with APR Connector Giving Unexpected Results
Greetings.
I recently upgraded from Tomcat 6.0.36 to 7.0.35 with the native APR
connector, and I ran into a problem with numbers in my access Log. I use
the %D ("Time taken to process the request, in millis") to measure the
service delivery quality of the application deployed to Tomcat, and it
showed a large increase in average response time after the upgrade. I had
other independent metrics in place that showed that the performance of the
application had actually improved, so I thought maybe that there was
instead a difference in how the request time was being measured in the 6.0
and 7.0 releases.
What I found is that the client transmission time wasn't factoring into the
time taken in 6.0 (which for me is the desired behavior), but sometimes it
was being factored in with 7.0. Digging in, I found that the time taken is
computed based on the start time associated with the Coyote request. I saw
that the start time is set in the AbstractHttp11Processor, just after
reading the status line but before reading the headers:
request.setStartTime(System.currentTimeMillis());
keptAlive = true;
// Set this every time in case limit has been changed
via JMX
request.getMimeHeaders().setLimit(endpoint.getMaxHeaderCount());
// Currently only NIO will ever return false here
if (!getInputBuffer().parseHeaders()) {
// We've read part of the request, don't recycle it
// instead associate it with the socket
openSocket = true;
readComplete = false;
break;
}
By writing some test cases, I was able to see that the increase in the
measured time was due to time waiting to fill the internal buffer while
parsing the headers in that same code block. I'm assuming that in the 6.0
server, the header data already buffered and was immediately available
whereas the 7.0 server was still waiting on the client transmission. I
tried increasing the maxHttpHeaderSize since I see that the buffer size is
directly correlated to that value, but it had no effect on the behavior.
For fun, I also tried out the other connector types. BIO suffered from the
same problem whereas the NIO connector exhibited the old behavior.
Unfortunately, I'm tied to the APR connector for the SSL implementation.
I'm wondering, is there some knob I can turn to restore the old behavior?
I looked through all the documentation and the change log to see if
anything jumped out at me, but I couldn't come up with anything. It looks
as though the APR connector is treated more or less as a black box. The
time taken is an important metric for me to determine that my application
is meeting an SLA, so it would be great to get it back to how it was
working before.
Thanks in advance,
Steve
Re: AccessLogVale %D with APR Connector Giving Unexpected Results
Posted by stevevls <st...@gmail.com>.
> Mark,
>
> On 2/14/13 5:22 AM, Mark Thomas wrote:
> On 14/02/2013 02:22, Steve van Loben Sels wrote:
>>> Greetings.
>>>
>>> I recently upgraded from Tomcat 6.0.36 to 7.0.35 with the native
>>> APR connector, and I ran into a problem with numbers in my
>>> access Log. I use the %D ("Time taken to process the request, in
>>> millis") to measure the service delivery quality of the
>>> application deployed to Tomcat, and it showed a large increase in
>>> average response time after the upgrade. I had other independent
>>> metrics in place that showed that the performance of the
>>> application had actually improved, so I thought maybe that there
>>> was instead a difference in how the request time was being
>>> measured in the 6.0 and 7.0 releases.
>>
>> Correct.
>>
>>> By writing some test cases, I was able to see that the increase
>>> in the measured time was due to time waiting to fill the internal
>>> buffer while parsing the headers in that same code block. I'm
>>> assuming that in the 6.0 server, the header data already buffered
>>> and was immediately available whereas the 7.0 server was still
>>> waiting on the client transmission. I tried increasing the
>>> maxHttpHeaderSize since I see that the buffer size is directly
>>> correlated to that value, but it had no effect on the behavior.
>>
>> The reason is that in Tomcat 6 start and end time for the request
>> was measured at the point the request/response entered/left the
>> AccessLogValve which is after the connector.
>>
>> In Tomcat 7 the access logging was refactored to take the full
>> request time into account - mainly to align it with httpd.
>>
>>> For fun, I also tried out the other connector types. BIO
>>> suffered from the same problem whereas the NIO connector
>>> exhibited the old behavior. Unfortunately, I'm tied to the APR
>>> connector for the SSL implementation.
>>
>> There is a bug in the NIO connector. The NIO connector is
>> non-blocking while reading the headers and the start time gets
>> reset every time another bit of the headers are read. That needs
>> fixing.
>>
>>> I'm wondering, is there some knob I can turn to restore the old
>>> behavior?
>>
>> Short answer. No.
>>
>>> I looked through all the documentation and the change log to see
>>> if anything jumped out at me, but I couldn't come up with
>>> anything. It looks as though the APR connector is treated more
>>> or less as a black box. The time taken is an important metric
>>> for me to determine that my application is meeting an SLA, so it
>>> would be great to get it back to how it was working before.
>>
>> Long answer. Depending on exactly what you need you could either
>> extend the existing AccessLogValve and modify how the request time
>> is calculated or your could write a simple valve that logs what you
>> need.
>
> Or, write a Valve that wraps the AccessLogValve and sets the "start
> time" there: that should restore the old Tomcat-6-style behavior, no?
>
> - -chris
Thanks for the info and the pointers, guys. Since I'm really only
interested in the time spent in my application's code (for which the %D used
to be a proxy), I'll likely just implement the timing in a Filter. I'm glad
to understand why the number has changed, though, and it makes complete
sense to have it be the same as Apache's interpretation.
Cheers,
Steve
--
View this message in context: http://tomcat.10.n6.nabble.com/AccessLogVale-D-with-APR-Connector-Giving-Unexpected-Results-tp4994361p4994492.html
Sent from the Tomcat - User mailing list archive at Nabble.com.
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
Re: AccessLogVale %D with APR Connector Giving Unexpected Results
Posted by Christopher Schultz <ch...@christopherschultz.net>.
-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA256
Mark,
On 2/14/13 5:22 AM, Mark Thomas wrote:
> On 14/02/2013 02:22, Steve van Loben Sels wrote:
>> Greetings.
>>
>> I recently upgraded from Tomcat 6.0.36 to 7.0.35 with the native
>> APR connector, and I ran into a problem with numbers in my
>> access Log. I use the %D ("Time taken to process the request, in
>> millis") to measure the service delivery quality of the
>> application deployed to Tomcat, and it showed a large increase in
>> average response time after the upgrade. I had other independent
>> metrics in place that showed that the performance of the
>> application had actually improved, so I thought maybe that there
>> was instead a difference in how the request time was being
>> measured in the 6.0 and 7.0 releases.
>
> Correct.
>
>> By writing some test cases, I was able to see that the increase
>> in the measured time was due to time waiting to fill the internal
>> buffer while parsing the headers in that same code block. I'm
>> assuming that in the 6.0 server, the header data already buffered
>> and was immediately available whereas the 7.0 server was still
>> waiting on the client transmission. I tried increasing the
>> maxHttpHeaderSize since I see that the buffer size is directly
>> correlated to that value, but it had no effect on the behavior.
>
> The reason is that in Tomcat 6 start and end time for the request
> was measured at the point the request/response entered/left the
> AccessLogValve which is after the connector.
>
> In Tomcat 7 the access logging was refactored to take the full
> request time into account - mainly to align it with httpd.
>
>> For fun, I also tried out the other connector types. BIO
>> suffered from the same problem whereas the NIO connector
>> exhibited the old behavior. Unfortunately, I'm tied to the APR
>> connector for the SSL implementation.
>
> There is a bug in the NIO connector. The NIO connector is
> non-blocking while reading the headers and the start time gets
> reset every time another bit of the headers are read. That needs
> fixing.
>
>> I'm wondering, is there some knob I can turn to restore the old
>> behavior?
>
> Short answer. No.
>
>> I looked through all the documentation and the change log to see
>> if anything jumped out at me, but I couldn't come up with
>> anything. It looks as though the APR connector is treated more
>> or less as a black box. The time taken is an important metric
>> for me to determine that my application is meeting an SLA, so it
>> would be great to get it back to how it was working before.
>
> Long answer. Depending on exactly what you need you could either
> extend the existing AccessLogValve and modify how the request time
> is calculated or your could write a simple valve that logs what you
> need.
Or, write a Valve that wraps the AccessLogValve and sets the "start
time" there: that should restore the old Tomcat-6-style behavior, no?
- -chris
-----BEGIN PGP SIGNATURE-----
Version: GnuPG/MacGPG2 v2.0.17 (Darwin)
Comment: GPGTools - http://gpgtools.org
Comment: Using GnuPG with Thunderbird - http://www.enigmail.net/
iEYEAREIAAYFAlEdRGAACgkQ9CaO5/Lv0PBRMgCgqPsZgW8s5Jy9Z37KqMHVqwHq
sQgAn0Zt3yuOwQPF7TLGCCqBSqCnF1cK
=xEDb
-----END PGP SIGNATURE-----
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
Re: AccessLogVale %D with APR Connector Giving Unexpected Results
Posted by Mark Thomas <ma...@apache.org>.
On 14/02/2013 02:22, Steve van Loben Sels wrote:
> Greetings.
>
> I recently upgraded from Tomcat 6.0.36 to 7.0.35 with the native APR
> connector, and I ran into a problem with numbers in my access Log. I use
> the %D ("Time taken to process the request, in millis") to measure the
> service delivery quality of the application deployed to Tomcat, and it
> showed a large increase in average response time after the upgrade. I had
> other independent metrics in place that showed that the performance of the
> application had actually improved, so I thought maybe that there was
> instead a difference in how the request time was being measured in the 6.0
> and 7.0 releases.
Correct.
> By writing some test cases, I was able to see that the increase in the
> measured time was due to time waiting to fill the internal buffer while
> parsing the headers in that same code block. I'm assuming that in the 6.0
> server, the header data already buffered and was immediately available
> whereas the 7.0 server was still waiting on the client transmission. I
> tried increasing the maxHttpHeaderSize since I see that the buffer size is
> directly correlated to that value, but it had no effect on the behavior.
The reason is that in Tomcat 6 start and end time for the request was
measured at the point the request/response entered/left the
AccessLogValve which is after the connector.
In Tomcat 7 the access logging was refactored to take the full request
time into account - mainly to align it with httpd.
> For fun, I also tried out the other connector types. BIO suffered from the
> same problem whereas the NIO connector exhibited the old behavior.
> Unfortunately, I'm tied to the APR connector for the SSL implementation.
There is a bug in the NIO connector. The NIO connector is non-blocking
while reading the headers and the start time gets reset every time
another bit of the headers are read. That needs fixing.
> I'm wondering, is there some knob I can turn to restore the old behavior?
Short answer. No.
> I looked through all the documentation and the change log to see if
> anything jumped out at me, but I couldn't come up with anything. It looks
> as though the APR connector is treated more or less as a black box. The
> time taken is an important metric for me to determine that my application
> is meeting an SLA, so it would be great to get it back to how it was
> working before.
Long answer. Depending on exactly what you need you could either extend
the existing AccessLogValve and modify how the request time is
calculated or your could write a simple valve that logs what you need.
Mark
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org