Re: Access-log ordering
On 18.04.2013 23:58, Christopher Schultz wrote:
Mark is of course right. Adding some info here concerning your log format:
We are using the following format string:
%a %t quot;%rquot; %s %D
The value of %t is the interesting one, of course, but it's
resolution is only in seconds, and we are seeing an access log file
like this:
127.0.0.1 [18/Apr/2013:16:19:08 -0400] POST /request/B HTTP/1.1 200 108
127.0.0.1 [18/Apr/2013:16:19:08 -0400] POST /request/A HTTP/1.1 200 263
In TC 7 you can log start time and end time and also milliseconds:
%{begin}t %{begin:msec_frac}t %{end}t %{end:msec_frac}t
or (maybe a bit slower but formatted more nicely)
%{begin:dd/MMM/:HH:mm:ss.SSS Z}t %{end:dd/MMM/:HH:mm:ss.SSS Z}t
The %{begin:msec}t and %{end:msec}t can also be useful. They are
milliseconds since the epoch, so not nicely readable for humans, but
nice for doing calculations.
AFAIR times are consistent if you use multiple formatting tokens, to te
time for begin and end is only taken once and then the various formats
use those two time values consistently.
The end: prefix is the default, so it can be ommitted.
Regards,
Rainer
-
To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org
For additional commands, e-mail: users-h...@tomcat.apache.org
Access-log ordering
-BEGIN PGP SIGNED MESSAGE- Hash: SHA256 All, I suspect I already know the answer to this, but I wanted to double-check. Requests are logged to the access log in the order in which they were accepted from the connector, right? Or, if they can't be guaranteed to be de-queued-and-dispatched serially (because there are multiple acceptor threads), they are at least logged (or queued to be logged) as soon as possible? I'm asking because we are observing an external process that should be making two separate, serial requests us (that is, request A is made and completes before request B is made) and in some cases request B is appearing in the access log before request A is showing up. There is a ton of other circumstantial evidence that this external process is in fact /not/ waiting for request A to be processed before making request B, but I just wanted to double-check. Of course the first response when asking if maybe someone else's code isn't working properly is to have them ask *you* if you're sure *your* code is working properly ;) So, this is my due diligence to determine if, in addition to the mountain of evidence we otherwise have, Tomcat does in fact log requests in the order in which they are received. We are using the following format string: %a %t quot;%rquot; %s %D The value of %t is the interesting one, of course, but it's resolution is only in seconds, and we are seeing an access log file like this: 127.0.0.1 [18/Apr/2013:16:19:08 -0400] POST /request/B HTTP/1.1 200 108 127.0.0.1 [18/Apr/2013:16:19:08 -0400] POST /request/A HTTP/1.1 200 263 Thanks, - -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/ iQIcBAEBCAAGBQJRcGyJAAoJEBzwKT+lPKRYBOQP/3Hq+9vqqDazy+2mzKADtaUZ ycTjjs4BCQWQoW7OJxweGkMp2hr84QcZmdx/K2f3AzYPBmuVBpym8BpIOj0Cj4aM sTJFcnN5Tu8zXj38FZkOKhBDEXrnCL1/Vvk4+NFc7K43UpgsKq82MMtLHe0fI512 GPF6GiBapyRg/EA3Zi5xqn0PZzghmWW1ZPAUkImffXt3c2OXndYaqPjMJuueg3n4 NNtBINbXoy5caQ/CFzZK+QBAIV4Uo9uBlo6sc3bpLAmwYpjfcXuVZuhSuMnpjQk8 /VGdGKMHmL8Xjiv2p6RRw6XcpUPoodo94ZAtPep4rrS5RiOPMUtLRClpFLvgxfGU hbgbHe+EUIVIxlXkvn45T9aeGfg1qbjqszkH6RSgG6ct9WoGzymA3PJ6petHKRE7 cz5UsNg9mFRdDQ++aCUwPbUwGaqS4+ga+PJGZUb+N1L8fTdlXBDoMpdbMfKdfeTK rqSQL4M6EK4ruNXvkMaYPasYVTwQ468DV0CT62SFfVCuXupmfGAgckWX3A4/rPuR aWMtK1UKDi7sNlefB3Tf0fdJd3Au9Pv2hfFidE4N7j20GP3jfo4THP0kwnjW/Zqj zZaHy4zWCzs3JMBfqBCuIfjHccqq9TyCZA9NtktZYdpHHTgYgdM9Dnr0Ae/XTX0b hIhQdAr/BDcsXwK6aUbf =7812 -END PGP SIGNATURE- - To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org For additional commands, e-mail: users-h...@tomcat.apache.org
Re: Access-log ordering
On 18/04/2013 22:58, Christopher Schultz wrote: So, this is my due diligence to determine if, in addition to the mountain of evidence we otherwise have, Tomcat does in fact log requests in the order in which they are received. Tomcat logs requests in the order they complete (so it can log the time spent processing, bytes sent, etc.). Additionally, there is a sync block around the writing to the log which is not guaranteed to use fair ordering so it is possible in a busy server for request A to finish before request B but for request B to be logged first. If those requests are on the same connection then they will always be logged in the order they were made. HTH, Mark - To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org For additional commands, e-mail: users-h...@tomcat.apache.org
Re: Access-log ordering
-BEGIN PGP SIGNED MESSAGE- Hash: SHA256 Mark, On 4/18/13 6:30 PM, Mark Thomas wrote: On 18/04/2013 22:58, Christopher Schultz wrote: So, this is my due diligence to determine if, in addition to the mountain of evidence we otherwise have, Tomcat does in fact log requests in the order in which they are received. Tomcat logs requests in the order they complete (so it can log the time spent processing, bytes sent, etc.). Additionally, there is a sync block around the writing to the log which is not guaranteed to use fair ordering so it is possible in a busy server for request A to finish before request B but for request B to be logged first. If those requests are on the same connection then they will always be logged in the order they were made. Okay, that definitely does help: this server is /not/ highly-loaded (those two examples I showed were the only requests received during that particular second of the day) and having request B complete before request A completes (especially when they are roughly equivalent in terms of time-to-complete at ~200ms each) clearly shows that the client is /not/ waiting for request A to complete before submitting request B. Thanks, - -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/ iQIcBAEBCAAGBQJRcKz8AAoJEBzwKT+lPKRY5osP/0FXQeOQdfpXiw4BbCPGBJNY LAxvIWZ0NPsmqFtwPzIBrt4RvAbTIZrix1JZUGExT0xPE46sDLC2OqQ//P5nEvkE J9npnAIqGzj+qG1ZOAeHcBu8TyZaIIEd4prrH7fekFpTeflLdClmtdyuEwKbEGXi cwJfNFdDHkFBnJ1c/ap7bOSCdUU3Kg5S7Sg+Q9aD6ottdbkyt/FEVFuqKZyV5XT/ zk+1vC19bWgY+AXXNsCaPGLF2rOM/CGhW9IbOMiZd/W90NMki/aDhH7/VdbljdXa VI8rEEgZ+5Ad6BBZwfGibpJTVwwuaScYNyQaEVIqq+1yu7weAFSCWzhva+s7yUvz UkzivLt9AYMXNDYvGWIXRe7Np+dq8+SneiPt/eoXn5+9oRQ34gDmU2VShTB67Ok9 zmRRYTJ7DnPKyiH6UZR/YWw52nCDJZz1lRl2as/dSRPWXWgtmCMJZLqwM2oj/Y1o m1T3pqMn8MQBqGx0IWjghfTSwqQMmPmFu1qWlyHe5ZNh0CG3JGu4nXYHSNWhXDCu vUpxJpVwodd0tXMKsHsqyRVU/UcKO75YBMdVYyjByaFdIM032whBcZ/uLQQG88Fk gu5PBCvnJ6P1/D5v1Uu9HufNuGwDagqGK/4YLEVr9jiQGH/l6V33++kkfxRwWvnk dYhF9boj9T2zvJhY0JyR =+0wg -END PGP SIGNATURE- - To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org For additional commands, e-mail: users-h...@tomcat.apache.org
