tomcat-users mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Antonios Kogias <co...@hua.gr>
Subject Re: AccessLogValve pattern (timestamp, bytes sent and time taken)
Date Mon, 28 Feb 2011 20:14:30 GMT
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<coyas@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
>


Mime
  • Unnamed multipart/alternative (inline, None, 0 bytes)
View raw message