/******************************************************************************************
* 版权声明
* 本文为本人原创，本人拥有此文的版权。鉴于本人持续受益于开源软件社区，
* 本人声明：任何个人及团体均可不受限制的转载和复制本文，无论是否用于盈利
* 之目的，但不得修改文章内容，并必须在转载及复制时同时保留本版权声明，否
* 则为侵权行为，本人保留追究相应主体法律责任之权利。
* speng2005@gmail.com
* 2015-11
******************************************************************************************/
本文参考博客文章：http://blog.sina.com.cn/s/blog_6294abe70101b9mn.html 在此表示感谢。在上面文章中已经讲了apache log的%D所包含的时间问题，文本再深入剖析一下，建议先看上面的文章后再看本文。
总结来说：apache log %D的时间长度是从apache在socket上收到一个完整的HTTP Request请求行开始(不要求请求行格式是否合法，以及后续header是否完整)，到apache将该请求的Response全部调用send()写入到socket的SEND_BUF为止的时间长度(不要求数据是否全部通过物理网络发送到客户端)，单位为微秒。也就是说，%D的时间长度不仅包含服务器端处理业务逻辑占用的全部时间，也包含大部分网络传输时间。
精确地讲，网络传输时间中，客户端发送HTTP请求的网络传输时间并未全部包含在%D的时间长度中。只有当apache从socket上读到的数据片段首次可以尝试解析出请求行时(即读到了\r\n，并且之前的数据非空即可，然后可以判断请求行格式是否合法)，%D才开始计时。极端情况下，如网络较慢或请求行超长时，既使等待接收完整的请求行花费了较长时间，也不会把这些时间包含在%D时间长度中。这一点可见前文对protocol.c中read_request_line()函数的剖析。
另一方面，apache向客户端返回response过程中的网络传输时间也并未全部包含在%D时间长度中。apache只是把将要返回给客户端的response的header和body的全部数据通过send()函数放入服务器端socket的SEND_BUF完成后，即认为发送响应过程完成，并在稍后进入log输出流程中取当前系统时间后计算%D的时间长度并输出log。这个时间并未考虑socket的SEND_BUF中的数据通过物理网络实际发送到客户端的时间延迟。但是，某些情况下，%D的时间长度确实也包含了大部分的返回response的网络传输时间，但不是全部。这是因为，按现行网络架构，apache通过socket将response的全部header及body顺序发送给客户端的过程，数据会按照原有顺序通过send()函数调用被放入服务器端socket的SEND_BUF中，然后数据通过物理网络传输到客户端，接着客户端先将接收到的数据放入客户端socket的RECV_BUF中，然后再由客户端上层应用调用recv()函数而最终接收到response数据。当服务器端socket的SEND_BUF已满时，服务器端将无法继续调用send()函数发送数据，必须等待SEND_BUF中数据全部或部分通过网络发出，腾出空间后才能再次调用send()函数，这会表现出服务器端检测到网络拥塞而导致发送数据处理时间延长。由于各种原因，如服务器到客户端物理链路中某一环节传输速度过慢，或者客户端应用处理socket的数据分片的多次recv()之间的时间间隔较长，都会导致服务器端socket出现SEND_BUF已满的情况，无法连续发送数据，进而表现为处理时间延长。一般情况下，apache要等全部response数据(包括header及body)都通过send()发送完成后，才认为response过程结束，并开始下一阶段处理，最后进入log输出阶段时，取当时的系统时间为终止时间，计算整个%D时间长度。所以，大体来说，%D时间长度包含了大部分返回response的网络传输时间。实测中，一台windows的客户端与一台linux的服务器端建立的socket对中，当服务器向客户端返回response的第一批数据时，由于此时服务器端socket的SEND_BUF及客户端socket的RECV_BUF都是空的，如果网速良好，服务器端可以一次性快速的send()约124100字节数据才能填满双方的socket收发缓冲区；而如果是在传输第2批及以后的数据时出现传输性能很差的情况，则服务器端每发送约65700字节就会发生一次网络拥塞，这时数据堆积在SEND_BUF中等待发送。所以，如果向某请求返回的响应数据总长度很短，例如小于124100字节，则%D时间长度中不包含响应的物理网络传输时间；如果返回的响应总长度较大，则%D时间长度中包含了大部分response的网络传输时间(只有最后一次send()调用的网络传输时间不包含在其中)。要验证这一点，可以更改apache源码并打印日志进行分析(apache httpd-2.4.3)：
找到mod_log_config.c中修改(粗体部分)：
static const char *log_request_duration_microseconds(request_rec *r, char *a)
{
//modified by speng on 2015-1-22
char debug_buf[1024];
apr_snprintf(debug_buf, 1024, "[debug with time]%" APR_TIME_T_FMT " generate %%D in access-log output stage", apr_time_now());
ap_log_error(APLOG_MARK, APLOG_NOERRNO|APLOG_ERR, 0, NULL,debug_buf);
return apr_psprintf(r->pool, "%" APR_TIME_T_FMT, (get_request_end_time(r) - r->request_time));
}
找到core_filters.c中修改(粗体部分)：
static apr_status_t writev_nonblocking(apr_socket_t *s,
struct iovec *vec, apr_size_t nvec,
apr_bucket_brigade *bb,
apr_size_t *cumulative_bytes_written,
conn_rec *c)
{
apr_status_t rv = APR_SUCCESS, arv;
apr_size_t bytes_written = 0, bytes_to_write = 0;
apr_size_t i, offset;
apr_interval_time_t old_timeout;
arv = apr_socket_timeout_get(s, &old_timeout);
if (arv != APR_SUCCESS) {
return arv;
}
arv = apr_socket_timeout_set(s, 0);
if (arv != APR_SUCCESS) {
return arv;
}
for (i = 0; i < nvec; i++) {
bytes_to_write += vec[i].iov_len;
}
{
//modified by speng on 2015-1-22
char debug_buf[1024];
apr_snprintf(debug_buf, 1024, "[debug with time]%" APR_TIME_T_FMT " just before actual send() of writev_nonblocking() in core_filters.c, %d bytes to be send" , apr_time_now(), bytes_to_write);
ap_log_error(APLOG_MARK, APLOG_NOERRNO|APLOG_ERR, 0, NULL,debug_buf);
}
offset = 0;
while (bytes_written < bytes_to_write) {
apr_size_t n = 0;
rv = apr_socket_sendv(s, vec + offset, nvec - offset, &n);
if (n > 0) {
bytes_written += n;
for (i = offset; i < nvec; ) {
apr_bucket *bucket = APR_BRIGADE_FIRST(bb);
if (APR_BUCKET_IS_METADATA(bucket)) {
APR_BUCKET_REMOVE(bucket);
apr_bucket_destroy(bucket);
}
else if (n >= vec[i].iov_len) {
APR_BUCKET_REMOVE(bucket);
apr_bucket_destroy(bucket);
offset++;
n -= vec[i++].iov_len;
}
else {
apr_bucket_split(bucket, n);
APR_BUCKET_REMOVE(bucket);
apr_bucket_destroy(bucket);
vec[i].iov_len -= n;
vec[i].iov_base = (char *) vec[i].iov_base + n;
break;
}
}
}
if (rv != APR_SUCCESS) {
break;
}
}
if ((ap__logio_add_bytes_out != NULL) && (bytes_written > 0)) {
ap__logio_add_bytes_out(c, bytes_written);
}
*cumulative_bytes_written += bytes_written;
{
//modified by speng on 2015-1-22
char debug_buf[1024];
apr_snprintf(debug_buf, 1024, "[debug with time]%" APR_TIME_T_FMT " after send() of writev_nonblocking() in core_filters.c, written %d bytes to net subsystem", apr_time_now(), bytes_written);
ap_log_error(APLOG_MARK, APLOG_NOERRNO|APLOG_ERR, 0, NULL,debug_buf);
}
arv = apr_socket_timeout_set(s, old_timeout);
if ((arv != APR_SUCCESS) && (rv == APR_SUCCESS)) {
return arv;
}
else {
return rv;
}
}
注意一点，如果观察生产环境中apache的access_log，尽管已经设置了Timeout为20秒，但仍然可以发现有少数请求的%D时间长达上百秒，并且访问的是静态资源文件也会这么长时间，而在测试环境中却模拟不到这种超长的响应时间。在模拟环境中，如果采用客户端故意增加两次recv()之间的时间间隔来仿真网络缓慢的情况，如果设置参数不当(例如两次recv()之间的时间间隔，数据接收缓冲区分块大小等)，通常20秒后连接就被apache主动关闭了，无法出现上百秒的延迟。这是因为在设置不当的情况下，客户端调用recv()函数接收RECV_BUF中的数据的速度过慢的话，会导致apache服务器端socket的SEND_BUF中空间占满的时间延长，如果上次成功send()(即有数据被放入SEND_BUF中)到下次成功send()中间的时间间隔超过apache设置的默认网络I/O超时时间，apache将会在超时后立即关闭socket不再进行后续处理，因此这时的%D时间长度不会达到上百秒。只有当设置合适的客户端接收速率后，既不是太快也不是太慢时，才不会导致apache端I/O超时而提前关闭socket终止响应发送，这样的话总体响应传输时间就会被拉长，会出现%D时间超过上百秒的现象。而这样的接收速率条件，在生产环境中总会有被满足的时候，所以偶尔会在access-log出现%D时间超过上百秒的访问记录。
另外观察到一个细节，在apache的access_log中使用%b选项后，该选项输出的是HTTP响应的body的总长度，并不代表此响应实际通过网络传输的长度，比如发送网络超时情况时实际发送数据会偏小。要记录HTTP响应的网络实际传输长度，应使用%O选项。
扫一扫
3435
被折叠的 条评论
为什么被折叠?
到【灌水乐园】发言
