设置keepalive-timeout情况下log的request_time显示为0.000

huangfxbupt · 2012-06-20T11:01:59+00:00

Hello! On Wed, Jun 20, 2012 at 10:56 AM, 曾海军 <hai...@gmail.com> wrote: > rt,master记录的总连&#x6...

设置keepalive-timeout情况下log的request_time显示为0.000

huangfxbupt

在keepalive_timeout设置（如60）情况下，access_log的$request_time显示几乎都为0.000，请问这种情况下怎么获取每个请求的真实request_time。多谢~

huangfxbupt

agentzh

Hello!

2012/6/20 huangfxbupt <huang...@gmail.com>:
> 在keepalive_timeout设置（如60）情况下，access_log的$request_time显示几乎都为0.000，请问这种情况下怎么获取每个请求的真实request_time。多谢~
>

我用下面这个简单的配置不能复现你说的问题（同时在 Linux x86_64 上面尝试过了 nginx 1.0.15 和 1.2.1）：

    http {
        keepalive_timeout  60;
        log_format test '[$time_local] "$request" $status $request_time';
        server {
            listen 1984;
            location /t {
                access_log logs/access2.log test;
                content_by_lua '
                    ngx.sleep(0.002)
                ';
            }
        }
    }

使用 ab 的 HTTP 1.0 keepalive 功能连续请求 10 次 /t 得到的访问日志如下：

    [20/Jun/2012:13:53:14 +0800] "GET /t HTTP/1.0" 200 0.002
    [20/Jun/2012:13:53:14 +0800] "GET /t HTTP/1.0" 200 0.002
    [20/Jun/2012:13:53:14 +0800] "GET /t HTTP/1.0" 200 0.002
    [20/Jun/2012:13:53:14 +0800] "GET /t HTTP/1.0" 200 0.002
    [20/Jun/2012:13:53:14 +0800] "GET /t HTTP/1.0" 200 0.002
    [20/Jun/2012:13:53:14 +0800] "GET /t HTTP/1.0" 200 0.003
    [20/Jun/2012:13:53:14 +0800] "GET /t HTTP/1.0" 200 0.002
    [20/Jun/2012:13:53:14 +0800] "GET /t HTTP/1.0" 200 0.002
    [20/Jun/2012:13:53:14 +0800] "GET /t HTTP/1.0" 200 0.002
    [20/Jun/2012:13:53:14 +0800] "GET /t HTTP/1.0" 200 0.002
    [20/Jun/2012:13:53:14 +0800] "GET /t HTTP/1.0" 200 0.002

可以看到最后一列记录的时间符合预期。

我使用的 ab 命令行是

    ab -c1 -n10 -k localhost:1984/t

ab 生成的报告中显示 HTTP 1.0 keepalive 确实生效了：

    Keep-Alive requests:    10

使用 weighttp 工具发起 HTTP 1.1 keepalive 请求或者手工 telnet 处理之，也可以得到类似的结果：

    [20/Jun/2012:13:53:59 +0800] "GET /t HTTP/1.1" 200 0.002
    [20/Jun/2012:13:53:59 +0800] "GET /t HTTP/1.1" 200 0.002
    [20/Jun/2012:13:53:59 +0800] "GET /t HTTP/1.1" 200 0.002
    [20/Jun/2012:13:53:59 +0800] "GET /t HTTP/1.1" 200 0.002
    [20/Jun/2012:13:53:59 +0800] "GET /t HTTP/1.1" 200 0.002
    [20/Jun/2012:13:53:59 +0800] "GET /t HTTP/1.1" 200 0.002
    [20/Jun/2012:13:53:59 +0800] "GET /t HTTP/1.1" 200 0.002
    [20/Jun/2012:13:53:59 +0800] "GET /t HTTP/1.1" 200 0.002
    [20/Jun/2012:13:53:59 +0800] "GET /t HTTP/1.1" 200 0.002
    [20/Jun/2012:13:53:59 +0800] "GET /t HTTP/1.1" 200 0.002

所以需要你提供关于此问题的更多信息，包括 nginx 的版本号、主要的 nginx 配置等等。

Regards,
-agentzh

agentzh

Hello!

2012/6/20 agentzh <age...@gmail.com>:
>    http {
>        keepalive_timeout  60;
>        log_format test '[$time_local] "$request" $status $request_time';
>        server {
>            listen 1984;
>            location /t {
>                access_log logs/access2.log test;
>                content_by_lua '
>                    ngx.sleep(0.002)

不好意思，这里少了一行

    ngx.say("ok")

>                ';
>            }
>        }
>    }

Best regards,
-agentzh

zhuzhaoyuan

Hi，

2012/6/20 huangfxbupt <huang...@gmail.com>

在keepalive_timeout设置（如60）情况下，access_log的$request_time显示几乎都为0.000，请问这种情况下怎么获取每个请求的真实request_time。多谢~

$request_time的单位是秒，但是精确到毫秒。如果你的request处理速度很快（小于1毫秒），这里显示是0是对的。

Regards，

--
Joshua Zhu
Senior Software Engineer
Server Platforms Team at Taobao

huangfxbupt

多谢详细测试。

nginx版本1.0.6，感觉也没使用什么特别的配置，主要配置：

http {

keepalive_timeout 60;

tcp_nodelay on;

tcp_nopush on;

log_format access ‘$request_time’;

……

}

另to shudu：我之前配置keepalive_timeout 0，$request_time大部分显示 0.0xx - 0.3xx不等，改完60后所有的都是0.000了。

祝好！

huangfxbupt

发件人： agentzh

发送时间： 2012-06-20 13:54

收件人： openresty

主题： Re: [openresty] 设置keepalive-timeout情况下log的request_time显示为0.000

Hello!

2012/6/20 huangfxbupt <huang...@gmail.com>:

> 在keepalive_timeout设置（如60）情况下，access_log的$request_time显示几乎都为0.000，请问这种情况下怎么获取每个请求的真实request_time。多谢~

我用下面这个简单的配置不能复现你说的问题（同时在 Linux x86_64 上面尝试过了 nginx 1.0.15 和 1.2.1）：

http {

keepalive_timeout 60;

log_format test '[$time_local] "$request" $status $request_time';

server {

listen 1984;

location /t {

access_log logs/access2.log test;

content_by_lua '

ngx.sleep(0.002)

}

使用 ab 的 HTTP 1.0 keepalive 功能连续请求 10 次 /t 得到的访问日志如下：

[20/Jun/2012:13:53:14 +0800] "GET /t HTTP/1.0" 200 0.002

[20/Jun/2012:13:53:14 +0800] "GET /t HTTP/1.0" 200 0.003

[20/Jun/2012:13:53:14 +0800] "GET /t HTTP/1.0" 200 0.002

可以看到最后一列记录的时间符合预期。

我使用的 ab 命令行是

ab -c1 -n10 -k localhost:1984/t

ab 生成的报告中显示 HTTP 1.0 keepalive 确实生效了：

Keep-Alive requests: 10

使用 weighttp 工具发起 HTTP 1.1 keepalive 请求或者手工 telnet 处理之，也可以得到类似的结果：

[20/Jun/2012:13:53:59 +0800] "GET /t HTTP/1.1" 200 0.002

所以需要你提供关于此问题的更多信息，包括 nginx 的版本号、主要的 nginx 配置等等。

Regards,

-agentzh

邮件自: 列表“openresty”,专用于技术讨论!

发言: 请发邮件到 openresty@googlegroups.com

退订: 请发邮件至 openresty+unsubscribe@googlegroups.com

详情: http://groups.google.com/group/openresty

官网: http://openresty.org/

仓库: https://github.com/agentzh/ngx_openresty

建议: 提问的智慧 http://wiki.woodpecker.org.cn/moin/AskForHelp

教程: http://agentzh.org/misc/nginx/agentzh-nginx-tutorials-zhcn.html

fengmo.q

hi,

1.0.6引入了lingering_close指令，且默认是打开，它的主要目的是使nginx具有更好的客户端兼容性，在keepalive关闭的情况下，会生效，request time计算截止点变为客户端读取完响应体并关闭连接，nginx收到事件才记log，也就是这个时间实际上是包括了响应体网络传输的时间。可以将该指令显示的关闭掉。

lingering_close详细请见：

http://nginx.org/en/docs/http/ngx_http_core_module.html#lingering_close

在 2012年6月20日下午2:04，huangfxbupt <huang...@gmail.com>写道：

多谢详细测试。

nginx版本1.0.6，感觉也没使用什么特别的配置，主要配置：

http {

     keepalive_timeout 60;

     tcp_nodelay on;

     tcp_nopush on;

     log_format access ‘$request_time’;

     ……

}

另to shudu：我之前配置keepalive_timeout 0，$request_time大部分显示 0.0xx - 0.3xx不等，改完60后所有的都是0.000了。

祝好！

huangfxbupt

发件人： agentzh

发送时间： 2012-06-20 13:54

收件人： openresty

主题： Re: [openresty] 设置keepalive-timeout情况下log的request_time显示为0.000

Hello!

2012/6/20 huangfxbupt <huang...@gmail.com>:

> 在keepalive_timeout设置（如60）情况下，access_log的$request_time显示几乎都为0.000，请问这种情况下怎么获取每个请求的真实request_time。多谢~

>

我用下面这个简单的配置不能复现你说的问题（同时在 Linux x86_64 上面尝试过了 nginx 1.0.15 和 1.2.1）：

    http {

        keepalive_timeout  60;

        log_format test '[$time_local] "$request" $status $request_time';

        server {

            listen 1984;

            location /t {

                access_log logs/access2.log test;

                content_by_lua '

                    ngx.sleep(0.002)

                ';

            }

        }

    }

使用 ab 的 HTTP 1.0 keepalive 功能连续请求 10 次 /t 得到的访问日志如下：

    [20/Jun/2012:13:53:14 +0800] "GET /t HTTP/1.0" 200 0.002

    [20/Jun/2012:13:53:14 +0800] "GET /t HTTP/1.0" 200 0.002

    [20/Jun/2012:13:53:14 +0800] "GET /t HTTP/1.0" 200 0.002

    [20/Jun/2012:13:53:14 +0800] "GET /t HTTP/1.0" 200 0.002

    [20/Jun/2012:13:53:14 +0800] "GET /t HTTP/1.0" 200 0.002

    [20/Jun/2012:13:53:14 +0800] "GET /t HTTP/1.0" 200 0.003

    [20/Jun/2012:13:53:14 +0800] "GET /t HTTP/1.0" 200 0.002

    [20/Jun/2012:13:53:14 +0800] "GET /t HTTP/1.0" 200 0.002

    [20/Jun/2012:13:53:14 +0800] "GET /t HTTP/1.0" 200 0.002

    [20/Jun/2012:13:53:14 +0800] "GET /t HTTP/1.0" 200 0.002

    [20/Jun/2012:13:53:14 +0800] "GET /t HTTP/1.0" 200 0.002

可以看到最后一列记录的时间符合预期。

我使用的 ab 命令行是

    ab -c1 -n10 -k localhost:1984/t

ab 生成的报告中显示 HTTP 1.0 keepalive 确实生效了：

    Keep-Alive requests:    10

使用 weighttp 工具发起 HTTP 1.1 keepalive 请求或者手工 telnet 处理之，也可以得到类似的结果：

    [20/Jun/2012:13:53:59 +0800] "GET /t HTTP/1.1" 200 0.002

    [20/Jun/2012:13:53:59 +0800] "GET /t HTTP/1.1" 200 0.002

    [20/Jun/2012:13:53:59 +0800] "GET /t HTTP/1.1" 200 0.002

    [20/Jun/2012:13:53:59 +0800] "GET /t HTTP/1.1" 200 0.002

    [20/Jun/2012:13:53:59 +0800] "GET /t HTTP/1.1" 200 0.002

    [20/Jun/2012:13:53:59 +0800] "GET /t HTTP/1.1" 200 0.002

    [20/Jun/2012:13:53:59 +0800] "GET /t HTTP/1.1" 200 0.002

    [20/Jun/2012:13:53:59 +0800] "GET /t HTTP/1.1" 200 0.002

    [20/Jun/2012:13:53:59 +0800] "GET /t HTTP/1.1" 200 0.002

    [20/Jun/2012:13:53:59 +0800] "GET /t HTTP/1.1" 200 0.002

所以需要你提供关于此问题的更多信息，包括 nginx 的版本号、主要的 nginx 配置等等。

Regards,

-agentzh

--

Jinglong
Software Engineer
Server Platforms Team at Taobao