Hi,
We use a java lib (HttpClient) to measure a web page response time, the page is
served by httpd.
We trace the time taken to serve the request using a %D in the LogFormat
directive, but sometimes the duration logged in the access file does not match
the duration measured using HttpClient (less than a 1ms against 3 seconds)
We've found that the "missing" time is consumed during the sending of the
request on the HttpClient side (i.e., NOT during the response reading).
My question is: "does the time taken to server the request include the time
taken to read the request from the client"?
I had a quick look at modules/loggers/mod_log_config.c and server/protocol.c.
in the mod_log_config.c, I've found:
===================================
static const char *log_request_duration(request_rec *r, char *a)
{
apr_time_t duration = apr_time_now() - r->request_time;
return apr_psprintf(r->pool, "%" APR_TIME_T_FMT, apr_time_sec(duration));
}
static const char *log_request_duration_microseconds(request_rec *r, char *a)
{
return apr_psprintf(r->pool, "%" APR_TIME_T_FMT,
(apr_time_now() - r->request_time));
}
===================================
in the server/protocol.c,
=========================
static int read_request_line(request_rec *r, apr_bucket_brigade *bb){
....
do { apr_status_t rv;
/* insure ap_rgetline allocates memory each time thru the loop
* if there are empty lines */ r->the_request = NULL; rv =
ap_rgetline(&(r->the_request), (apr_size_t)(r->server->limit_req_line + 2),
&len, r, 0, bb);
if (rv != APR_SUCCESS) { r->request_time = apr_time_now();
/* ap_rgetline returns APR_ENOSPC if it fills up the *
buffer before finding the end-of-line. This is only going to *
happen if it exceeds the configured limit for a request-line. */
if (rv == APR_ENOSPC) {
r->status = HTTP_REQUEST_URI_TOO_LARGE;
r->proto_num = HTTP_VERSION(1,0);
r->protocol = apr_pstrdup(r->pool, "HTTP/1.0");
}
return 0;
}
} while ((len <= 0) && (++num_blank_lines < max_blank_lines));
/* we've probably got something to do, ignore graceful restart requests */
r->request_time = apr_time_now();
ll = r->the_request;
r->method = ap_getword_white(r->pool, &ll);
....
=========================
I'm neither an httpd expert, nor a C expert, but what I understand is that the
r->request_time "top" is taken when the request is being read, that's why we
cannot see in the access log the time taken for the request to be sent from the
client to the server.
Am I wrong?
Thanks.
--
Christophe Furmaniak
________________________________
Ce message et les pi?ces jointes sont confidentiels et r?serv?s ? l'usage
exclusif de ses destinataires. Il peut ?galement ?tre prot?g? par le secret
professionnel. Si vous recevez ce message par erreur, merci d'en avertir
imm?diatement l'exp?diteur et de le d?truire. L'int?grit? du message ne pouvant
?tre assur?e sur Internet, la responsabilit? du groupe Atos Origin ne pourra
?tre recherch?e quant au contenu de ce message. Bien que les meilleurs efforts
soient faits pour maintenir cette transmission exempte de tout virus,
l'exp?diteur ne donne aucune garantie ? cet ?gard et sa responsabilit? ne
saurait ?tre recherch?e pour tout dommage r?sultant d'un virus transmis.
This e-mail and the documents attached are confidential and intended solely for
the addressee; it may also be privileged. If you receive this e-mail in error,
please notify the sender immediately and destroy it. As its integrity cannot be
secured on the Internet, the Atos Origin group liability cannot be triggered
for the message content. Although the sender endeavours to maintain a computer
virus-free network, the sender does not warrant that this transmission is
virus-free and will not be liable for any damages resulting from any virus
transmitted.
