> 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-unsubscr...@tomcat.apache.org
For additional commands, e-mail: users-h...@tomcat.apache.org
