You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@tomcat.apache.org by ??G??S ???O???S <co...@hua.gr> on 2011/02/18 08:06:04 UTC
AccessLogValve pattern (timestamp, bytes sent and time taken)
Tomcat 5.5 or 6.0
Win XP or Vista (32)
I've read the configuration (http://tomcat.apache.org/tomcat-5.5-doc/config/valve.html) and the api (http://tomcat.apache.org/tomcat-5.5-doc/catalina/docs/api/org/apache/catalina/valves/AccessLogValve.html) but there are some details that are not specified:
timestamp (%t in pattern)
In apache documentation it is stated that this is the time that the request was received. I'd like some simple confirmation that this also holds true for the tomcat (and is not, for example, the time that the response was sent).
bytes sent (either %b or %B in pattern)
Is this the number of bytes actually sent to the client, or simply the size in bytes of the HTTP response (which will differ, for instance, if the connection is aborted)? The apache httpd 2.0 provides the %O format as well to distinguish between these two cases, whereas in 1.3 it didn't. Since tomcat does not provide such an option, my guess is towards the number of bytes actually sent to the client, but I'd like some simple confirmation on this.
time taken (either %D or %T in pattern)
Is the network transmission time included in the processing time? To be more precise, is this the time the server used to process, prepare the HTTP response and deliver it to the underlying layer for transmission (i.e. non-blocking threads on tcp send)? Or does it also include the underlying layer sending time (e.g. blocking threads on tcp send)? Apache's documentation is also obscure on that point...
We're going to use tomcat on a faster than real time web server simulation experiment, and I need the above details to correctly build a satisfactory initial model for the web server.
Thank you,
Antonios Kogias
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
Re: AccessLogValve pattern (timestamp, bytes sent and time taken)
Posted by Christopher Schultz <ch...@christopherschultz.net>.
-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1
Antonios,
On 2/24/2011 11:28 AM, Antonios Kogias wrote:
> And I would like some clarification on "Depending on exactly where the
> Valve falls within the Valve chain and how the RequestDispatcher works
> with Valves, it may or may not include time to render the response at all."
If your servlet redirects to a dynamic response, then the time for the
first request necessarily does not include the time to render a response
(unless you consider issuing a 30x status to be "rendering the
response"). That seems clear to me.
On the other hand, your servlet can issue a "forward" which is
essentially a server-side redirect that allows a second (or third, or
fourth, ...) servlet to generate a response after the first servlet does
it's work. I'm not sure where the Valve chain fits into that (does the
AccessLogValve time the calls to each individual forward, or does it
time the entire request/response as the client sees it?), but the answer
to that question can significantly change the timings that you observe.
- -chris
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.10 (MingW32)
Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org/
iEYEARECAAYFAk1rxdEACgkQ9CaO5/Lv0PCmDQCeLofJSFjkIDeFElfWU9Q10sc2
sQUAni1wjqcATxwpi8+Y5Z8i8yr5qN71
=7144
-----END PGP SIGNATURE-----
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
Re: AccessLogValve pattern (timestamp, bytes sent and time taken)
Posted by Antonios Kogias <co...@hua.gr>.
Thank you for the answer Chris. You noted about confirmation of some
issues, and I'd been waiting for it until now.
You stated that "For a simple request, the timing will include any time
blocking on response buffers..." and it would be good enough for me, if
confirmed.
And I would like some clarification on "Depending on exactly where the
Valve falls within the Valve chain and how the RequestDispatcher works
with Valves, it may or may not include time to render the response at all."
On 2/22/2011 10:12 PM, Christopher Schultz wrote:
> -----BEGIN PGP SIGNED MESSAGE-----
> Hash: SHA1
>
> Antonios,
>
> On 2/21/2011 11:05 AM, Antonios Kogias wrote:
>> If we use tomcat 7.0.8, the "timing for the whole request processing
>> cycle" will incorporate transmit time?
>> e.g. if using HTTP/1.0, will it represent the total time until the
>> teardown of the connection? Or will it be the net processing time
>> /before/ transmission starts (i.e. time to prepare the http response and
>> push it to the network layer)?
> (I'd like Konstantin to confirm the following, presuming it's true...)
>
> The Valve terminates after the servlet (the code actually doing the
> work) completed its work. For a simple request, the timing will include
> any time blocking on response buffers but can't by definition include
> any time waiting for the client to drain the buffer.
>
> Depending on exactly where the Valve falls within the Valve chain and
> how the RequestDispatcher works with Valves, it may or may not include
> time to render the response at all. Let me explain:
>
> Many servlets look like this:
>
> public void doGet(...) {
> try {
> // do some stuff
>
> getRequestDispatcher("/result.jsp").forward(request, response);
> } catch (Exception e) {
> // log the error, whatever
> getRequestDispatcher("/error.jsp").forward(request, response);
> }
> }
>
> If the Valve wraps around only the original request (to, say, servlet
> "/foo") then you're only timing the execution of the code shown above:
> the processing of result.jsp (or error.jsp for that matter) will be
> shown in a separate log message.
>
> I don't believe Apache httpd has a notion of an internal request forward
> the way that Java does, so I'm not sure there's an analog, there.
>
> - -chris
> -----BEGIN PGP SIGNATURE-----
> Version: GnuPG v1.4.10 (MingW32)
> Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org/
>
> iEYEARECAAYFAk1kGKkACgkQ9CaO5/Lv0PA8WgCeP0uLrgXyT2sHkwRkbaVtsrkC
> ZDsAoJQpc75Zl8iJYPzRPgKOhlOef/gw
> =Ysn0
> -----END PGP SIGNATURE-----
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
> For additional commands, e-mail: users-help@tomcat.apache.org
>
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
Re: AccessLogValve pattern (timestamp, bytes sent and time taken)
Posted by Christopher Schultz <ch...@christopherschultz.net>.
-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1
Antonios,
On 2/21/2011 11:05 AM, Antonios Kogias wrote:
> If we use tomcat 7.0.8, the "timing for the whole request processing
> cycle" will incorporate transmit time?
> e.g. if using HTTP/1.0, will it represent the total time until the
> teardown of the connection? Or will it be the net processing time
> /before/ transmission starts (i.e. time to prepare the http response and
> push it to the network layer)?
(I'd like Konstantin to confirm the following, presuming it's true...)
The Valve terminates after the servlet (the code actually doing the
work) completed its work. For a simple request, the timing will include
any time blocking on response buffers but can't by definition include
any time waiting for the client to drain the buffer.
Depending on exactly where the Valve falls within the Valve chain and
how the RequestDispatcher works with Valves, it may or may not include
time to render the response at all. Let me explain:
Many servlets look like this:
public void doGet(...) {
try {
// do some stuff
getRequestDispatcher("/result.jsp").forward(request, response);
} catch (Exception e) {
// log the error, whatever
getRequestDispatcher("/error.jsp").forward(request, response);
}
}
If the Valve wraps around only the original request (to, say, servlet
"/foo") then you're only timing the execution of the code shown above:
the processing of result.jsp (or error.jsp for that matter) will be
shown in a separate log message.
I don't believe Apache httpd has a notion of an internal request forward
the way that Java does, so I'm not sure there's an analog, there.
- -chris
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.10 (MingW32)
Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org/
iEYEARECAAYFAk1kGKkACgkQ9CaO5/Lv0PA8WgCeP0uLrgXyT2sHkwRkbaVtsrkC
ZDsAoJQpc75Zl8iJYPzRPgKOhlOef/gw
=Ysn0
-----END PGP SIGNATURE-----
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
Re: AccessLogValve pattern (timestamp, bytes sent and time taken)
Posted by Antonios Kogias <co...@hua.gr>.
Thank you Konstantin, for the clarification of details - now I got a
much better understanding of the issues involved.
My understanding is that the logAccess(...) call happens when the output
buffer has been flushed and closed (in http/1.0 that would also close
the tcp connection, thus I called it 'teardown'), and the timestamp
recorded is of the call time of the logAccess(...).
I would like to use the log's <timestamp> to measure request
inter-arrival time intervals.
It seems that to get a valid timestamp for the calculation (i.e. a more
accurate approximation of the request arrival time), I need to subtract
the <time taken> from the <timestamp> written in the log.
Can you please confirm this?
(I think that I can get away with considering the Request Arrival Time
the same as Response Processing Start i.e. negligible time for reading
and parsing the http request line etc.)
About the processing time recorded <time taken> it seems that it
contains the whole of transmission as well (i.e. pushing the data to the
network layer and closing the output). Chris put an interesting question
(thank you for bringing it up) that I'm not sure how to handle at the
moment (beyond not using such "forwarding" servlets in the initial
experimental setups):
On 2/28/2011 5:57 PM, Christopher Schultz wrote:
On the other hand, your servlet can issue a "forward" which is
essentially a server-side redirect that allows a second (or third, or
fourth, ...) servlet to generate a response after the first servlet does
it's work. I'm not sure where the Valve chain fits into that (does the
AccessLogValve time the calls to each individual forward, or does it
time the entire request/response as the client sees it?), but the answer
to that question can significantly change the timings that you observe.
Can you provide any feedback on that?
For the modeling scheme to work, the web server needs be configured with
blocking (traditional sockets) threads on read and - especially - on
write. I read the Connector configuration
http://tomcat.apache.org/tomcat-7.0-doc/config/http.html and it states
in the introduction:
"Each incoming request requires a thread for the duration of that
request. If more simultaneous requests are received than can be handled
by the currently available request processing threads, additional
threads will be created up to the configured maximum (the value of
the|maxThreads|attribute). If still more simultaneous requests are
received, they are stacked up inside the server socket created by
the*Connector*, up to the configured maximum (the value of
the|acceptCount|attribute. Any further simultaneous requests will
receive "connection refused" errors, until resources are available to
process them."
and I'm perfectly happy with that. But at the page bottom (comparison of
the connectors) I don't understand:
a) How can I choose one of the three connectors to use in server config?
b) What does "Sim Blocking" in the Java Nio Blocking Connectormean?
On 2/27/2011 9:43 PM, Konstantin Kolinko wrote:
> 2011/2/21 Antonios Kogias<co...@hua.gr>:
>> Thank you very much for the detailed answer. Now there's just one more thing
>> to ask.
>> If we use tomcat 7.0.8, the "timing for the whole request processing cycle"
>> will incorporate transmit time?
>> e.g. if using HTTP/1.0, will it represent the total time until the teardown
>> of the connection? Or will it be the net processing time /before/
>> transmission starts (i.e. time to prepare the http response and push it to
>> the network layer)?
> In TC 7.0.8 and later:
>
> The start time:
> = when org.apache.coyote.Request#setStartTime() is called
>
> That is done by processors. Some initial processing is already done at
> that point (e.g. reading the request line).
>
> The end time:
> = when org.apache.catalina.connector.CoyoteAdapter#service() calls logAccess(..)
>
> That is done when service() completes processing the request. At that
> point the content is already generated and response.finishResponse()
> is already called (which closes output buffer and writes remaining
> data to the socket).
>
> After that Tomcat performs cleaning of its internal state and is ready
> to process next request.
>
> I am not sure what you mean by "teardown".
>
>
> A correction: I wrote:
>
>> In latest versions of TC7 (7.0.8 and later) (...)
>> That version prints timestamp when request was received
> That is not true. With %t the AccessLogValve still prints the current
> time when logging is performed, not when processing was started.
> (There was a patch discussed on dev@ to change the behaviour, but it
> has not been applied yet).
>
>
> BTW, if you want to debug Tomcat,
> http://wiki.apache.org/tomcat/FAQ/Developing
>
> Best regards,
> Konstantin Kolinko
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
> For additional commands, e-mail: users-help@tomcat.apache.org
>
Re: AccessLogValve pattern (timestamp, bytes sent and time taken)
Posted by Konstantin Kolinko <kn...@gmail.com>.
2011/2/21 Antonios Kogias <co...@hua.gr>:
> Thank you very much for the detailed answer. Now there's just one more thing
> to ask.
> If we use tomcat 7.0.8, the "timing for the whole request processing cycle"
> will incorporate transmit time?
> e.g. if using HTTP/1.0, will it represent the total time until the teardown
> of the connection? Or will it be the net processing time /before/
> transmission starts (i.e. time to prepare the http response and push it to
> the network layer)?
In TC 7.0.8 and later:
The start time:
= when org.apache.coyote.Request#setStartTime() is called
That is done by processors. Some initial processing is already done at
that point (e.g. reading the request line).
The end time:
= when org.apache.catalina.connector.CoyoteAdapter#service() calls logAccess(..)
That is done when service() completes processing the request. At that
point the content is already generated and response.finishResponse()
is already called (which closes output buffer and writes remaining
data to the socket).
After that Tomcat performs cleaning of its internal state and is ready
to process next request.
I am not sure what you mean by "teardown".
A correction: I wrote:
> In latest versions of TC7 (7.0.8 and later) (...)
> That version prints timestamp when request was received
That is not true. With %t the AccessLogValve still prints the current
time when logging is performed, not when processing was started.
(There was a patch discussed on dev@ to change the behaviour, but it
has not been applied yet).
BTW, if you want to debug Tomcat,
http://wiki.apache.org/tomcat/FAQ/Developing
Best regards,
Konstantin Kolinko
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
Re: AccessLogValve pattern (timestamp, bytes sent and time taken)
Posted by Antonios Kogias <co...@hua.gr>.
On 2/18/2011 12:12 PM, Konstantin Kolinko wrote:
> 2011/2/18 ??G??S ???O???S<co...@hua.gr>:
>> Tomcat 5.5 or 6.0
>> Win XP or Vista (32)
>>
>> I've read the configuration (http://tomcat.apache.org/tomcat-5.5-doc/config/valve.html) and the api (http://tomcat.apache.org/tomcat-5.5-doc/catalina/docs/api/org/apache/catalina/valves/AccessLogValve.html) but there are some details that are not specified:
>>
>> timestamp (%t in pattern)
>> In apache documentation it is stated that this is the time that the request was received. I'd like some simple confirmation that this also holds true for the tomcat (and is not, for example, the time that the response was sent).
>>
>> bytes sent (either %b or %B in pattern)
>> Is this the number of bytes actually sent to the client, or simply the size in bytes of the HTTP response (which will differ, for instance, if the connection is aborted)? The apache httpd 2.0 provides the %O format as well to distinguish between these two cases, whereas in 1.3 it didn't. Since tomcat does not provide such an option, my guess is towards the number of bytes actually sent to the client, but I'd like some simple confirmation on this.
>>
>> time taken (either %D or %T in pattern)
>> Is the network transmission time included in the processing time? To be more precise, is this the time the server used to process, prepare the HTTP response and deliver it to the underlying layer for transmission (i.e. non-blocking threads on tcp send)? Or does it also include the underlying layer sending time (e.g. blocking threads on tcp send)? Apache's documentation is also obscure on that point...
>>
> In short:
>
> regarding TC 5.5 and 6.0 your hopes are wrong. The timestamp is when
> the processing is the layer below the valve has ended (and the log
> statement is printed), with some caching of generated timestamp string
> (not worse than 1 sec). Time taken: time spend in the layer below the
> valve. The size is raw size, before gzip compression.
>
>
> In latest versions of TC7 (7.0.8 and later) the access valve has
> different implementation, and is directly invoked from the connector
> adapter layer. That version prints timestamp when request was
> received, timing for the whole request processing cycle (though '0'
> when it cannot be determined), reports count of bytes sent (taking
> compression into account).
>
>
> Best regards,
> Konstantin Kolinko
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
> For additional commands, e-mail: users-help@tomcat.apache.org
>
Thank you very much for the detailed answer. Now there's just one more
thing to ask.
If we use tomcat 7.0.8, the "timing for the whole request processing
cycle" will incorporate transmit time?
e.g. if using HTTP/1.0, will it represent the total time until the
teardown of the connection? Or will it be the net processing time
/before/ transmission starts (i.e. time to prepare the http response and
push it to the network layer)?
Re: AccessLogValve pattern (timestamp, bytes sent and time taken)
Posted by Konstantin Kolinko <kn...@gmail.com>.
2011/2/18 ??G??S ???O???S <co...@hua.gr>:
> Tomcat 5.5 or 6.0
> Win XP or Vista (32)
>
> I've read the configuration (http://tomcat.apache.org/tomcat-5.5-doc/config/valve.html) and the api (http://tomcat.apache.org/tomcat-5.5-doc/catalina/docs/api/org/apache/catalina/valves/AccessLogValve.html) but there are some details that are not specified:
>
> timestamp (%t in pattern)
> In apache documentation it is stated that this is the time that the request was received. I'd like some simple confirmation that this also holds true for the tomcat (and is not, for example, the time that the response was sent).
>
> bytes sent (either %b or %B in pattern)
> Is this the number of bytes actually sent to the client, or simply the size in bytes of the HTTP response (which will differ, for instance, if the connection is aborted)? The apache httpd 2.0 provides the %O format as well to distinguish between these two cases, whereas in 1.3 it didn't. Since tomcat does not provide such an option, my guess is towards the number of bytes actually sent to the client, but I'd like some simple confirmation on this.
>
> time taken (either %D or %T in pattern)
> Is the network transmission time included in the processing time? To be more precise, is this the time the server used to process, prepare the HTTP response and deliver it to the underlying layer for transmission (i.e. non-blocking threads on tcp send)? Or does it also include the underlying layer sending time (e.g. blocking threads on tcp send)? Apache's documentation is also obscure on that point...
>
In short:
regarding TC 5.5 and 6.0 your hopes are wrong. The timestamp is when
the processing is the layer below the valve has ended (and the log
statement is printed), with some caching of generated timestamp string
(not worse than 1 sec). Time taken: time spend in the layer below the
valve. The size is raw size, before gzip compression.
In latest versions of TC7 (7.0.8 and later) the access valve has
different implementation, and is directly invoked from the connector
adapter layer. That version prints timestamp when request was
received, timing for the whole request processing cycle (though '0'
when it cannot be determined), reports count of bytes sent (taking
compression into account).
Best regards,
Konstantin Kolinko
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org