> 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