Re: [openresty] lua 访问mysql 报错1040，另求redis的lua函数指导

agentzh · 2012-07-27T01:43:33+00:00

第一个getcount()递回没出口？Lance On Thu, Jul 26, 2012 at 7:59 PM, Wendal Chen <wend...@gmail.com&g...

Re: [openresty] lua 访问mysql 报错1040，另求redis的lua函数指导

agentzh

Hello!

On Thu, Jul 26, 2012 at 2:32 AM, ganggewudi <3925...@qq.com> wrote:
>
> 不知道为什么会循环运行getcount(),一直报错， Too many connections ，报1040的错误。
>

因为你的 getcount() 是一个无限递归函数，它做的事情就是：

   1. 建立一个新的 mysql 连接
   2. 执行一个查询
   3. 跳回步骤 1 继续

显然这是一个死循环，而且只是无谓地不断创建新的 mysql 连接。

> 还有，我想设置一个redis，用来存储数据库的数据，添加了以下两个函数，不过编译不通过

简单地说“编译不通过”并不是好的问题报告 :) 我需要知道怎么编译不通过，你的 error.log 文件中具体给出了怎样的出错信息。

Best regards,
-agentzh

392523211

谢谢大神们啊，改好了，能完成这个逻辑了。对了，大神，还有个问题，我从url里面获得value,table，然后用LUA组成一个sql语句，存入缓存，因为很多tracker上报，所以只要sql语句存入pool就关闭连接，然后后台如何实现pool不空，就插入mysql呢，resty有这个功能吗。可以知道pool不空，能随时监听。

在 2012年7月27日星期五UTC+8上午1时43分32秒，agentzh写道：

Hello!
On Thu, Jul 26, 2012 at 2:32 AM, ganggewudi <3925...@qq.com> wrote:
>
> 不知道为什么会循环运行getcount(),一直报错， Too many connections ，报1040的错误。
>
因为你的 getcount() 是一个无限递归函数，它做的事情就是：
1. 建立一个新的 mysql 连接
2. 执行一个查询
3. 跳回步骤 1 继续
显然这是一个死循环，而且只是无谓地不断创建新的 mysql 连接。
> 还有，我想设置一个redis，用来存储数据库的数据，添加了以下两个函数，不过编译不通过
简单地说“编译不通过”并不是好的问题报告 :) 我需要知道怎么编译不通过，你的 error.log 文件中具体给出了怎样的出错信息。
Best regards,
-agentzh

agentzh

Hello!

2012/7/26 ganggewudi <3925...@qq.com>:
> 谢谢大神们啊，改好了，能完成这个逻辑了。对了，大神，还有个问题，我从url里面获得value,table，然后用LUA组成一个sql语句，存入缓存，因为很多tracker上报，所以只要sql语句存入pool就关闭连接，然后后台如何实现pool不空，就插入mysql呢，resty有这个功能吗。可以知道pool不空，能随时监听。
>

有一个常用的折衷技巧是，在 mysql 等耗时查询之前调用 ngx.eof() 结束响应体数据的发送，并且禁用 http
keepalive，这样设计良好的 HTTP 客户端一般会主动提前关闭连接。

Best regards,
-agentzh

392523211

ngx.eof()是返回http请求了，但是接下来的数据库查询还会继续执行吗？线程不销毁吗？memc,resdis有现成的模块自动在后台监听吗？峰值有时候来了大量的url，就想一秒内先把数据全接下来，然后就返回，而不是等三四秒，之后再执行数据库插入动作，我很迷惑的就是谁来执行这个插入动作，我想的解决办法是pub到channel上，写脚本监听，或者是直接插到rabbitmq这样的软件中，就返回，插入数据库动作就又第三方完成。但是这都不是最好的解决办法，要是在lua直接就完成了，就好了。大神能不能跟我说详细点，麻烦你了

在 2012年7月27日星期五UTC+8下午1时15分05秒，agentzh写道：

Hello!
2012/7/26 ganggewudi <3925...@qq.com>:
> 谢谢大神们啊，改好了，能完成这个逻辑了。对了，大神，还有个问题，我从url里面获得value,table，然后用LUA组成一个sql语句，存入缓存，因为很多tracker上报，所以只要sql语句存入pool就关闭连接，然后后台如何实现pool不空，就插入mysql呢，resty有这个功能吗。可以知道pool不空，能随时监听。
>
有一个常用的折衷技巧是，在 mysql 等耗时查询之前调用 ngx.eof() 结束响应体数据的发送，并且禁用 http
keepalive，这样设计良好的 HTTP 客户端一般会主动提前关闭连接。
Best regards,
-agentzh

agentzh

Hello!

2012/7/27 ganggewudi <3925...@qq.com>:
> ngx.eof()是返回http请求了，但是接下来的数据库查询还会继续执行吗？

当然。

> 线程不销毁吗？

nginx 是单线程的程序，不存在线程销毁的概念。如果你说的是 nginx 内部的请求处理生命期，是的，生命期会延后到你所有的 Lua
代码执行完毕，即使客户端提前断开了连接（当然，未来支持了 lua_ignore_client_abort off 就不一定了）。

> memc,resdis有现成的模块自动在后台监听吗？峰值有时候来了大量的url，就想一秒内先把数据全接下来，然后就返回，而不是等三四秒，之后再执行数据库插入动作，我很迷惑的就是谁来执行这个插入动作，我想的解决办法是pub到channel上，写脚本监听，或者是直接插到rabbitmq这样的软件中，就返回，插入数据库动作就又第三方完成。但是这都不是最好的解决办法，要是在lua直接就完成了，就好了。

你说的这些和我上面说的不是一回事。我说的意思是：

    # nginx.conf
    keepalive_timeout 0;

    server {
        location /api {
            content_by_lua '
                 local query = generate_query_from_request()
                 output_response()
                 ngx.eof()
                 do_db_query(query)
            ';
        }
    }

印度的一家流量很大的在线统计应用已经在生产上使用了这种方式。

当然，如果能换成通过外部队列和独立的后台工作进程来实现任务调度和离线计算自然最好了，这样有助于提高 nginx 进程的稳定性，同时也有助于实现任务队列的分布式。

Best regards,
-agentzh

kindy61

春哥，

这个使用 ngx.eof() 的技巧依赖的是当把查询发送到后端机器后，

即使我断开到后端的连接，后端也会继续执行这样的逻辑吧。

当客户端断开到nginx的请求，当前请求建立的到后端的请求都会断开的。

貌似mysql确实会一直执行查询，而不管连接是否还在。

也就是说这个方法不是所有后端都可行。

是不是这样呢？

2012/7/28 agentzh <age...@gmail.com>

Hello!

2012/7/27 ganggewudi <3925...@qq.com>:
> ngx.eof()是返回http请求了，但是接下来的数据库查询还会继续执行吗？

当然。

> 线程不销毁吗？

nginx 是单线程的程序，不存在线程销毁的概念。如果你说的是 nginx 内部的请求处理生命期，是的，生命期会延后到你所有的 Lua
代码执行完毕，即使客户端提前断开了连接（当然，未来支持了 lua_ignore_client_abort off 就不一定了）。

> memc,resdis有现成的模块自动在后台监听吗？峰值有时候来了大量的url，就想一秒内先把数据全接下来，然后就返回，而不是等三四秒，之后再执行数据库插入动作，我很迷惑的就是谁来执行这个插入动作，我想的解决办法是pub到channel上，写脚本监听，或者是直接插到rabbitmq这样的软件中，就返回，插入数据库动作就又第三方完成。但是这都不是最好的解决办法，要是在lua直接就完成了，就好了。

你说的这些和我上面说的不是一回事。我说的意思是：

# nginx.conf
keepalive_timeout 0;

server {
location /api {
content_by_lua '
local query = generate_query_from_request()
output_response()
ngx.eof()
do_db_query(query)
';
}
}

印度的一家流量很大的在线统计应用已经在生产上使用了这种方式。

当然，如果能换成通过外部队列和独立的后台工作进程来实现任务调度和离线计算自然最好了，这样有助于提高 nginx 进程的稳定性，同时也有助于实现任务队列的分布式。

Best regards,
-agentzh

--
- - - - - - - - - - - -
林青(Kindy Lin)

agentzh

Hello!

2012/8/19 kindy wrote:
> 这个使用 ngx.eof() 的技巧依赖的是当把查询发送到后端机器后，
> 即使我断开到后端的连接，后端也会继续执行 这样的逻辑吧。
>

目前 ngx_lua 并不会在下游连接断开时自动断开上游连接。换句话说，目前 ngx_lua 总是 ignore client abort 的模式。

> 当客户端断开到nginx的请求，当前请求建立的到后端的请求都会断开的。
> 貌似mysql确实会一直执行查询，而不管连接是否还在。
>

这是 mysql 一侧的 ignore client abort 的行为了，与 ngx_lua 无关。

> 也就是说这个方法不是所有后端都可行。
> 是不是这样呢？
>

对所有后端都应当是可行的。考虑下面这个访问 redis 后端的例子：

    location /t {
        content_by_lua '
            ngx.say("done")
            ngx.eof()
            ngx.log(ngx.NOTICE, "XXX test begin")

            local redis = require "resty.redis"
            local red = redis:new()
            local ok, err = red:connect("127.0.0.1", 6379)
            if not ok then
                ngx.say("failed to connect: ", err)
            end
            local res, err = red:blpop("key-not-exist", 3)
            if not res then
                ngx.log(ngx.ERR, "failed to blpop: ", err)
                return
            end
            ngx.log(ngx.NOTICE, "XXX blpop result: ", res)
        ';
    }

我们在向 HTTP 客户端输出 "done" 之后通过 ngx.eof() 结束当前的响应体，然后再慢慢访问 redis.
注意这里我们有意发送了一条执行需要至少 3 秒的 redis 请求：

    blpop key-not-exist 3

最后在 redis 请求结束之后，我们在 Lua 里面向 nginx 错误日志文件输出这条 blpop 命令的执行结果（如果有的话）。

通过 curl 这样设计良好的 HTTP 客户端，我们可以达成提交中断下游连接的效果：

    $ time curl localhost/t
    done

    real	0m0.007s
    user	0m0.001s
    sys	0m0.004s

我们看到，curl 确实在得到所有的响应体数据之后立即主动断开了连接并立即退出了。

然后我们再查看一下 nginx 的错误日志文件：

    $ grep XXX logs/error.log
    2012/08/19 22:09:19 [notice] 17542#0: *9 [lua] [string
"content_by_lua"]:4: XXX test begin, ...
    2012/08/19 22:09:23 [notice] 17542#0: *9 [lua] [string
"content_by_lua"]:17: XXX blpop result: null, ...

我们看到，location /t 还是继续执行完了那个 3 秒的 blpop 查询，输出了 null
这个结果。注意这两条日志的时间戳，二者输出时的时间间隔是 4 秒，正好略大于 3 秒。由此可见，我们的 redis 慢查询并没有受到
curl 提前断开（下游）连接的影响。

未来等实现了 lua_ignore_client_abort 配置指令（默认自然为 on），如果用户自己显式地配置了

    lua_ignore_client_abort off;

之后，那么下游连接的断开事件会立即触发所有上游连接的断开操作。

Best regards,
-agentzh

agentzh

Hello!

2012/8/19 agentzh <age...@gmail.com>:
>
> 对所有后端都应当是可行的。考虑下面这个访问 redis 后端的例子：
>
>     location /t {
>         content_by_lua '
>             ngx.say("done")
>             ngx.eof()
>             ngx.log(ngx.NOTICE, "XXX test begin")
>
>             local redis = require "resty.redis"
>             local red = redis:new()
>             local ok, err = red:connect("127.0.0.1", 6379)
>             if not ok then
>                 ngx.say("failed to connect: ", err)
>             end
>             local res, err = red:blpop("key-not-exist", 3)
>             if not res then
>                 ngx.log(ngx.ERR, "failed to blpop: ", err)
>                 return
>             end
>             ngx.log(ngx.NOTICE, "XXX blpop result: ", res)
>         ';
>     }
>

当然，这里为确保 HTTP 客户端不因 HTTP keepalive 的缘故不立即关闭连接，上面这个例子还需要加上一句

    keepalive_timeout 0;

以禁用 HTTP keepalive :) 这对于使用 Firefox 或者 Chrome 等浏览器测试上例中的 /t 接口的朋友来说则是必需的 :)

Best regards,
-agentzh

kindy61

GOT IT

多谢春哥

2012/8/20 agentzh <age...@gmail.com>

Hello!

2012/8/19 kindy wrote:
> 这个使用 ngx.eof() 的技巧依赖的是当把查询发送到后端机器后，
> 即使我断开到后端的连接，后端也会继续执行这样的逻辑吧。
>

目前 ngx_lua 并不会在下游连接断开时自动断开上游连接。换句话说，目前 ngx_lua 总是 ignore client abort 的模式。

> 当客户端断开到nginx的请求，当前请求建立的到后端的请求都会断开的。
> 貌似mysql确实会一直执行查询，而不管连接是否还在。
>

这是 mysql 一侧的 ignore client abort 的行为了，与 ngx_lua 无关。

> 也就是说这个方法不是所有后端都可行。
> 是不是这样呢？
>

对所有后端都应当是可行的。考虑下面这个访问 redis 后端的例子：

location /t {
content_by_lua '
ngx.say("done")
ngx.eof()
ngx.log(ngx.NOTICE, "XXX test begin")

local redis = require "resty.redis"
local red = redis:new()

local ok, err = red:connect("127.0.0.1", 6379)
if not ok then
ngx.say("failed to connect: ", err)
end
local res, err = red:blpop("key-not-exist", 3)
if not res then
ngx.log(ngx.ERR, "failed to blpop: ", err)
return
end
ngx.log(ngx.NOTICE, "XXX blpop result: ", res)
';
}

我们在向 HTTP 客户端输出 "done" 之后通过 ngx.eof() 结束当前的响应体，然后再慢慢访问 redis.
注意这里我们有意发送了一条执行需要至少 3 秒的 redis 请求：

blpop key-not-exist 3

最后在 redis 请求结束之后，我们在 Lua 里面向 nginx 错误日志文件输出这条 blpop 命令的执行结果（如果有的话）。

通过 curl 这样设计良好的 HTTP 客户端，我们可以达成提交中断下游连接的效果：

$ time curl localhost/t
done

real 0m0.007s
user 0m0.001s
sys 0m0.004s

我们看到，curl 确实在得到所有的响应体数据之后立即主动断开了连接并立即退出了。

然后我们再查看一下 nginx 的错误日志文件：

$ grep XXX logs/error.log
2012/08/19 22:09:19 [notice] 17542#0: *9 [lua] [string
"content_by_lua"]:4: XXX test begin, ...
2012/08/19 22:09:23 [notice] 17542#0: *9 [lua] [string
"content_by_lua"]:17: XXX blpop result: null, ...

我们看到，location /t 还是继续执行完了那个 3 秒的 blpop 查询，输出了 null
这个结果。注意这两条日志的时间戳，二者输出时的时间间隔是 4 秒，正好略大于 3 秒。由此可见，我们的 redis 慢查询并没有受到
curl 提前断开（下游）连接的影响。

未来等实现了 lua_ignore_client_abort 配置指令（默认自然为 on），如果用户自己显式地配置了

lua_ignore_client_abort off;

之后，那么下游连接的断开事件会立即触发所有上游连接的断开操作。

Best regards,
-agentzh

--
- - - - - - - - - - - -
林青(Kindy Lin)

ldmiao

ngx.eof() 之后的代码执行有时间或者其它什么限制吗？如果之后有一个死循环，会一直执行吗？

我试了下面的代码，在我的机器上(Mac Mountain Lion, ngx_openresty/1.2.1.14) i 到60左右循环就停掉了，不再打印error log；如果把这一行注释掉，i 就可以远远超过60（观察i到过220多）。

所以很想知道是什么因素决定了ngx.eof()之后代码执行的数量或时间。

# nginx.conf
keepalive_timeout 0;

server {
location /test_eof {
content_by_lua '
local a = string.rep("x", 1000000)

ngx.say(a)

ngx.say("end!")
ngx.eof()

local i = 1

while true do
ngx.log(ngx.ERR, "i:", tostring(i))

i = i + 1

ngx.sleep(1)

end
';
}
}

On Saturday, July 28, 2012, agentzh wrote:

Hello!

2012/7/27 ganggewudi <3925...@qq.com>:
> ngx.eof()是返回http请求了，但是接下来的数据库查询还会继续执行吗？

当然。

> 线程不销毁吗？

nginx 是单线程的程序，不存在线程销毁的概念。如果你说的是 nginx 内部的请求处理生命期，是的，生命期会延后到你所有的 Lua
代码执行完毕，即使客户端提前断开了连接（当然，未来支持了 lua_ignore_client_abort off 就不一定了）。

> memc,resdis有现成的模块自动在后台监听吗？峰值有时候来了大量的url，就想一秒内先把数据全接下来，然后就返回，而不是等三四秒，之后再执行数据库插入动作，我很迷惑的就是谁来执行这个插入动作，我想的解决办法是pub到channel上，写脚本监听，或者是直接插到rabbitmq这样的软件中，就返回，插入数据库动作就又第三方完成。但是这都不是最好的解决办法，要是在lua直接就完成了，就好了。

你说的这些和我上面说的不是一回事。我说的意思是：

# nginx.conf
keepalive_timeout 0;

server {
location /api {
content_by_lua '
local query = generate_query_from_request()
output_response()
ngx.eof()
do_db_query(query)
';
}
}

印度的一家流量很大的在线统计应用已经在生产上使用了这种方式。

当然，如果能换成通过外部队列和独立的后台工作进程来实现任务调度和离线计算自然最好了，这样有助于提高 nginx 进程的稳定性，同时也有助于实现任务队列的分布式。

Best regards,
-agentzh

agentzh

Hello!

2012/8/20 Demiao Lin <ld...@gmail.com>:
> ngx.eof() 之后的代码执行有时间或者其它什么限制吗？如果之后有一个死循环，会一直执行吗？
>

目前在设计上并没有加以限制。

> 我试了下面的代码，在我的机器上(Mac Mountain Lion, ngx_openresty/1.2.1.14) i
> 到60左右循环就停掉了，不再打印error log；如果把 ngx.say(a)  这一行注释掉，i 就可以远远超过60（观察i到过220多）。
> 所以很想知道是什么因素决定了ngx.eof()之后代码执行的数量或时间。
>
>     # nginx.conf
>     keepalive_timeout 0;
>
>     server {
>         location /test_eof {
>             content_by_lua '
>                  local a = string.rep("x", 1000000)
>                  ngx.say(a)
>                  ngx.say("end!")
>                  ngx.eof()
>
>                  local i = 1
>                  while true do
>                       ngx.log(ngx.ERR, "i:", tostring(i))
>                       i = i + 1
>                       ngx.sleep(1)
>                  end
>             ';
>         }
>     }
>

这个示例在我这里（Linux x86_64）也可以复现这个问题，它其实暴露了 ngx_lua 中的和下游写数据相关联的一个定时器的 bug.

具体细节是：当需要向下游发送的数据量足够大时，nginx 一次无法把数据全部写入系统的 socket 发送缓冲区，此时
ngx_http_lua_wev_handler 函数会添加一个定时器，默认定时长度即 send_timeout 配置指令控制的时间，默认是
60 秒。而当数据已经全部写出时，ngx_http_lua_wev_handler 函数却并没有删除那个定时器，从而导致 60
秒后定时器超时，然后触发了 408 REQUEST TIMEOUT错误，中断了当前的 Lua coroutine 的执行。

使用下面这个 systemtap 脚本可以追踪定时器的行为：

    global evtime

    probe process("nginx").mark("timer-add") {
        printf("add timer %d: %d\n", $arg1, $arg2)
        evtime[$arg1] = $arg2
    }

    probe process("nginx").mark("timer-del") {
        time = evtime[$arg1]
        printf("del timer %d: %d\n", $arg1, time)
    }

    probe process("nginx").mark("timer-expire") {
        time = evtime[$arg1]
        printf("expire timer %d: %d\n", $arg1, time)
    }

使用该脚本监视 nginx 在运行上面那个问题示例时，可以得到下面的输出：

    add timer 33004968: 60000
    del timer 33004968: 60000
    add timer 33108632: 1000
    expire timer 33108632: 1000
    add timer 33138232: 60000
    add timer 33108632: 1000
    expire timer 33108632: 1000
    add timer 33108632: 1000
    expire timer 33108632: 1000
    add timer 33108632: 1000
    expire timer 33108632: 1000
    add timer 33108632: 1000
    expire timer 33108632: 1000
    ...
    add timer 33108632: 1000
    expire timer 33138232: 60000
    del timer 33108632: 1000

从输出上可以清楚地看到，第二个时间为 60 秒（60000 毫秒）的定时器并没有删除，而是最终超时（expire）了。那些 1
秒的定时器则是上例中的 ngx.sleep(1) 调用所生成的。我们可以再用下面的 systemtap 脚本输出第二个 60
秒定时器的调用栈：

    global count = 0

    probe process("nginx").mark("timer-add") {
        if ($timer == 60000 && ++count == 2) {
            print_ubacktrace()
        }
    }

得到的输出是

    0x4a3914 : ngx_http_lua_wev_handler+0x54b/0x95e [nginx]
     0x4b043b : ngx_http_lua_sleep_handler+0x148/0x16d [nginx]
     0x42c7db : ngx_event_expire_timers+0xa5/0xba [nginx]
     0x42c3a4 : ngx_process_events_and_timers+0x112/0x17f [nginx]
     0x4346f7 : ngx_single_process_cycle+0x93/0x188 [nginx]
     0x416638 : main+0xa33/0xab0 [nginx]

进一步，通过 addr2line 可以得到第一帧的源文件和行号：

    $ addr2line -e /path/to/nginx/sbin/nginx -i 0x4a3914
    nginx-1.2.3/src/event/ngx_event_timer.h:93
    lua-nginx-module2/src/ngx_http_lua_util.c:1322

由于 ngx_timer_add 实现为了一个 C 内联函数，所以这里打印出了两个源码位置。

而 ngx_http_lua_util.c:1322 则是

    https://github.com/chaoslawful/lua-nginx-module/blob/e282c1/src/ngx_http_lua_util.c#L1322

显然，我们在那里加了定时器之后忘记及时删除了。

信末附上了一个补丁，应当可以修复这个 bug. 应用上此补丁之后，上面第一个 systemtap 脚本的输出便成为下面这个样子：

    add timer 38538808: 60000
    del timer 38538808: 60000
    add timer 38642472: 1000
    expire timer 38642472: 1000
    add timer 38672072: 60000
    add timer 38642472: 1000
    del timer 38672072: 60000
    expire timer 38642472: 1000
    add timer 38642472: 1000
    expire timer 38642472: 1000
    add timer 38642472: 1000
    expire timer 38642472: 1000
    add timer 38642472: 1000
    expire timer 38642472: 1000
    ...

我们看到第二个 60 秒的定时器现在很早就被删除了，这样 ngx.sleep 就可以无限制地循环下去了。

上面的 systemtap 脚本使用了 nginx-dtrace 项目引入的 dtrace 静态探针：

    https://github.com/agentzh/nginx-dtrace

这些 dtrace 探针将会包含在下一个 ngx_openresty 开发版发布 1.2.3.1 中 :)

多谢你的报告！

Thanks!
-agentzh

diff --git a/src/ngx_http_lua_util.c b/src/ngx_http_lua_util.c
index 163cbda..46a27c6 100644
--- a/src/ngx_http_lua_util.c
+++ b/src/ngx_http_lua_util.c
@@ -1338,6 +1338,11 @@ ngx_http_lua_wev_handler(ngx_http_request_t *r)

                 return NGX_DONE;
             }
+
+        } else {
+            if (wev->timer_set) {
+                ngx_del_timer(wev);
+            }
         }
     }

Attachment: ngx_lua-write-event-timer-leftover.patch
Description: Binary data

agentzh

Hello!

2012/8/20 agentzh <age...@gmail.com>:
>
> 信末附上了一个补丁，应当可以修复这个 bug.

我已经把此补丁提交到了 ngx_lua 项目的 git master 分支：

    https://github.com/chaoslawful/lua-nginx-module/commit/e46e490

同时针对此 bug 附上了一个同时使用到 mockeagain 和 systemtap 的测试用例 :) 使用 mockeagain
的好处是不必在测试用例中使用很大的数据就可以精确摸拟写不动的情形。

Best regards,
-agentzh

ldmiao

春哥威武！大家对OpenResty的信心，就是从春哥对每一个问题的授人以渔的回答上建立起来的！

在 2012年8月21日星期二，agentzh 写道：

Hello!

2012/8/20 Demiao Lin <ld...@gmail.com>:
> ngx.eof() 之后的代码执行有时间或者其它什么限制吗？如果之后有一个死循环，会一直执行吗？
>

目前在设计上并没有加以限制。

> 我试了下面的代码，在我的机器上(Mac Mountain Lion, ngx_openresty/1.2.1.14) i
> 到60左右循环就停掉了，不再打印error log；如果把 ngx.say(a) 这一行注释掉，i 就可以远远超过60（观察i到过220多）。
> 所以很想知道是什么因素决定了ngx.eof()之后代码执行的数量或时间。
>
> # nginx.conf
> keepalive_timeout 0;
>
> server {
> location /test_eof {
> content_by_lua '
> local a = string.rep("x", 1000000)
> ngx.say(a)
> ngx.say("end!")
> ngx.eof()
>
> local i = 1
> while true do
> ngx.log(ngx.ERR, "i:", tostring(i))
> i = i + 1
> ngx.sleep(1)
> end
> ';
> }
> }
>

这个示例在我这里（Linux x86_64）也可以复现这个问题，它其实暴露了 ngx_lua 中的和下游写数据相关联的一个定时器的 bug.

具体细节是：当需要向下游发送的数据量足够大时，nginx 一次无法把数据全部写入系统的 socket 发送缓冲区，此时
ngx_http_lua_wev_handler 函数会添加一个定时器，默认定时长度即 send_timeout 配置指令控制的时间，默认是
60 秒。而当数据已经全部写出时，ngx_http_lua_wev_handler 函数却并没有删除那个定时器，从而导致 60
秒后定时器超时，然后触发了 408 REQUEST TIMEOUT错误，中断了当前的 Lua coroutine 的执行。

使用下面这个 systemtap 脚本可以追踪定时器的行为：

global evtime

probe process("nginx").mark("timer-add") {
printf("add timer %d: %d\n", $arg1, $arg2)
evtime[$arg1] = $arg2
}

probe process("nginx").mark("timer-del") {
time = evtime[$arg1]
printf("del timer %d: %d\n", $arg1, time)
}

probe process("nginx").mark("timer-expire") {
time = evtime[$arg1]
printf("expire timer %d: %d\n", $arg1, time)
}

使用该脚本监视 nginx 在运行上面那个问题示例时，可以得到下面的输出：

add timer 33004968: 60000
del timer 33004968: 60000
add timer 33108632: 1000
expire timer 33108632: 1000
add timer 33138232: 60000
add timer 33108632: 1000
expire timer 33108632: 1000
add timer 33108632: 1000
expire timer 33108632: 1000
add timer 33108632: 1000
expire timer 33108632: 1000
add timer 33108632: 1000
expire timer 33108632: 1000
...
add timer 33108632: 1000
expire timer 33138232: 60000
del timer 33108632: 1000

从输出上可以清楚地看到，第二个时间为 60 秒（60000 毫秒）的定时器并没有删除，而是最终超时（expire）了。那些 1
秒的定时器则是上例中的 ngx.sleep(1) 调用所生成的。我们可以再用下面的 systemtap 脚本输出第二个 60
秒定时器的调用栈：

global count = 0

probe process("nginx").mark("timer-add") {
if ($timer == 60000 && ++count == 2) {
print_ubacktrace()
}
}

得到的输出是

0x4a3914 : ngx_http_lua_wev_handler+0x54b/0x95e [nginx]
0x4b043b : ngx_http_lua_sleep_handler+0x148/0x16d [nginx]
0x42c7db : ngx_event_expire_timers+0xa5/0xba [nginx]
0x42c3a4 : ngx_process_events_and_timers+0x112/0x17f [nginx]
0x4346f7 : ngx_single_process_cycle+0x93/0x188 [nginx]
0x416638 : main+0xa33/0xab0 [nginx]

进一步，通过 addr2line 可以得到第一帧的源文件和行号：

$ addr2line -e /path/to/nginx/sbin/nginx -i 0x4a3914
nginx-1.2.3/src/event/ngx_event_timer.h:93
lua-nginx-module2/src/ngx_http_lua_util.c:1322

由于 ngx_timer_add 实现为了一个 C 内联函数，所以这里打印出了两个源码位置。

而 ngx_http_lua_util.c:1322 则是

https://github.com/chaoslawful/lua-nginx-module/blob/e282c1/src/ngx_http_lua_util.c#L1322

显然，我们在那里加了定时器之后忘记及时删除了。

信末附上了一个补丁，应当可以修复这个 bug. 应用上此补丁之后，上面第一个 systemtap 脚本的输出便成为下面这个样子：

add timer 38538808: 60000
del timer 38538808: 60000
add timer 38642472: 1000
expire timer 38642472: 1000
add timer 38672072: 60000
add timer 38642472: 1000
del timer 38672072: 60000
expire timer 38642472: 1000
add timer 38642472: 1000
expire timer 38642472: 1000
add timer 38642472: 1000
expire timer 38642472: 1000
add timer 38642472: 1000
expire timer 38642472: 1000
...

我们看到第二个 60 秒的定时器现在很早就被删除了，这样 ngx.sleep 就可以无限制地循环下去了。

上面的 systemtap 脚本使用了 nginx-dtrace 项目引入的 dtrace 静态探针：

https://github.com/agentzh/nginx-dtrace

这些 dtrace 探针将会包含在下一个 ngx_openresty 开发版发布 1.2.3.1 中 :)

多谢你的报告！

Thanks!
-agentzh

diff --git a/src/ngx_http_lua_util.c b/src/ngx_http_lua_util.c
index 163cbda..46a27c6 100644
--- a/src/ngx_http_lua_util.c
+++ b/src/ngx_http_lua_util.c
@@ -1338,6 +1338,11 @@ ngx_http_lua_wev_handler(ngx_http_request_t *r)

return NGX_DONE;
}
+
+ } else {
+ if (wev->timer_set) {
+ ngx_del_timer(wev);
+ }
}
}

ldmiao

我刚刚从master分支编译了一个最新的ngx_openresty, 测试了5次，ngx.eof()之后的代码执行都能超过60秒，不会停止了，观察到过230秒。

问题这么快得到解决，由衷感谢！

On Tuesday, August 21, 2012, agentzh wrote:

Hello!

2012/8/20 agentzh <age...@gmail.com>:
>
> 信末附上了一个补丁，应当可以修复这个 bug.

我已经把此补丁提交到了 ngx_lua 项目的 git master 分支：

https://github.com/chaoslawful/lua-nginx-module/commit/e46e490

同时针对此 bug 附上了一个同时使用到 mockeagain 和 systemtap 的测试用例 :) 使用 mockeagain
的好处是不必在测试用例中使用很大的数据就可以精确摸拟写不动的情形。

Best regards,
-agentzh

agentzh

Hello!

2012/8/20 Demiao Lin <ld...@gmail.com>:
> 我刚刚从master分支编译了一个最新的ngx_openresty,
> 测试了5次，ngx.eof()之后的代码执行都能超过60秒，不会停止了，观察到过230秒。
>

好极了，多谢反馈！

> 问题这么快得到解决，由衷感谢！
>

那是应该的。其实得多谢你报供的用例！呵呵。

Best regards,
-agentzh