ngx.re.match/gmatch有时会造成nginx进程出错

lancelijade

hi agentzh,

以下为测试代码
    server
    {
        listen 80;
        server_name test;
        location /
        {
            content_by_lua '
              local key = string.rep ("x", 200000)
              local ctx = {}
              local m, err = ngx.re.match(key, ".", "soja", ctx)
              while m do
                ngx.print(m[0])
                m, err = ngx.re.match(key, ".", "soja", ctx)
              end
            ';
        }
    }

其中字符串长度 200000 时有时会出错，有时不会，加大到 300000 时基本完全会出错。

出错时的现象，nginx cpu占用100%，输出中止，类似
[root@test conf]# curl "http://test/"
xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx

出错时pstack 查看出错进程
[root@test conf]# pstack 15060
#0 0x000000000041838a in ngx_chain_update_chains ()
#1 0x00000000004549a9 in ngx_http_chunked_body_filter ()
#2 0x00000000004593e1 in ngx_http_gzip_body_filter ()
#3 0x000000000045a213 in ngx_http_postpone_filter ()
#4 0x000000000045a820 in ngx_http_ssi_body_filter ()
#5 0x000000000045e935 in ngx_http_charset_body_filter ()
#6 0x000000000047cf36 in ngx_http_xss_body_filter ()
#7 0x0000000000498c37 in ngx_http_lua_capture_body_filter ()
#8 0x00000000004b5e6f in ngx_http_rds_csv_body_filter ()
#9 0x0000000000418911 in ngx_output_chain ()
#10 0x00000000004455f9 in ngx_http_copy_filter ()
#11 0x0000000000454b09 in ngx_http_range_body_filter ()
#12 0x00000000004383ea in ngx_http_output_filter ()
#13 0x000000000049458a in ngx_http_lua_output_filter ()
#14 0x0000000000494e87 in ngx_http_lua_send_chain_link ()
#15 0x000000000048ae14 in ngx_http_lua_ngx_echo ()
#16 0x000000000048aeb1 in ngx_http_lua_ngx_print ()
#17 0x00002af4b00a1d3b in lj_BC_FUNCC () from /usr/local/openresty/luajit/lib/libluajit-5.1.so.2
#18 0x0000000000494f36 in ngx_http_lua_run_thread ()
#19 0x00000000004978aa in ngx_http_lua_content_by_chunk ()
#20 0x00000000004979c1 in ngx_http_lua_content_handler_inline ()
#21 0x00000000004975a7 in ngx_http_lua_content_handler ()
#22 0x000000000043cc21 in ngx_http_core_content_phase ()
#23 0x0000000000438063 in ngx_http_core_run_phases ()
#24 0x0000000000438160 in ngx_http_handler ()
#25 0x000000000044196d in ngx_http_process_request ()
#26 0x00000000004421aa in ngx_http_process_request_headers ()
#27 0x00000000004426c2 in ngx_http_process_request_line ()
#28 0x000000000043fd40 in ngx_http_init_request ()
#29 0x000000000042abaa in ngx_event_process_posted ()
#30 0x000000000042aa6f in ngx_process_events_and_timers ()
#31 0x00000000004307a8 in ngx_worker_process_cycle ()
#32 0x000000000042f107 in ngx_spawn_process ()
#33 0x000000000042fe8e in ngx_start_worker_processes ()
#34 0x0000000000431333 in ngx_master_process_cycle ()
#35 0x0000000000415d9d in main ()

换用 gmatch 现象类似。

openresty版本见下，pcre是在系统里编译的 8.32

[root@test conf]# /usr/local/openresty/nginx/sbin/nginx -V
nginx version: ngx_openresty/1.2.7.3
built by gcc 4.1.2 20080704 (Red Hat 4.1.2-52)
TLS SNI support disabled
configure arguments: --prefix=/usr/local/openresty/nginx --add-module=../ngx_devel_kit-0.2.18 --add-module=../echo-nginx-module-0.44 --add-module=../xss-nginx-module-0.03rc9 --add-module=../ngx_coolkit-0.2rc1 --add-module=../set-misc-nginx-module-0.22rc8 --add-module=../form-input-nginx-module-0.07 --add-module=../encrypted-session-nginx-module-0.02 --add-module=../srcache-nginx-module-0.19 --add-module=../ngx_lua-0.7.18 --add-module=../headers-more-nginx-module-0.19 --add-module=../array-var-nginx-module-0.03rc1 --add-module=../memc-nginx-module-0.13rc3 --add-module=../redis2-nginx-module-0.10 --add-module=../redis-nginx-module-0.3.6 --add-module=../auth-request-nginx-module-0.2 --add-module=../rds-json-nginx-module-0.12rc10 --add-module=../rds-csv-nginx-module-0.05rc2 --with-ld-opt=-Wl,-rpath,/usr/local/openresty/luajit/lib --with-http_ssl_module

出错时系统errorlog没有内容。

以上。

Lance

agentzh

Hello!

On Tue, Apr 2, 2013 at 11:20 PM, Lance wrote:
> 以下为测试代码
>     server
>     {
>         listen 80;
>         server_name test;
>         location /
>         {
>             content_by_lua '
>               local key = string.rep ("x", 200000)
>               local ctx = {}
>               local m, err = ngx.re.match(key, ".", "soja", ctx)
>               while m do
>                 ngx.print(m[0])

你这里不应在一个很热的循环里调用 ngx.print()，因为 ngx.print() 是高代价操作，必然会调用整个 Nginx
输出过滤器链。正确的做法应当是把输出自己缓冲起来，比如放在一个 Lua table 或者 Lua 字符串中，最后在循环外面一次性调用
ngx.print() 输出。

在我的笔记本上直接运行你的例子，200,000 时请求时间是 1.1 秒，300,000 时是 1.7 秒，而当使用 3,000,000
时需要 16.8 秒。如果使用 Nginx Systemtap Toolkit 中的火焰图工具对此时的 Nginx worker
进程进行采样分析，可以得到下面这样的火焰图：

http://agentzh.org/misc/flamegraph/hot-output-filter.svg

从图中可以清楚地看到，Nginx 输出过滤器链条上的 ngx_chain_update_chains 和
ngx_http_write_filter 这两个函数占用了大部分的 CPU 时间。

按照我上面的建议减少 ngx.print() 的调用次数可以解决这里的性能问题，比如：

    location / {
        content_by_lua '
          local key = string.rep ("x", 200000)
          local ctx = {}
          local m, err = ngx.re.match(key, ".", "soja", ctx)
          local i = 0
          local buf = {}
          while m do
            buf[#buf + 1] = m[0]
            i = i + 1
            if i >= 1000 then
                ngx.print(buf)
                i = 0
                buf = {}
            end
            m, err = ngx.re.match(key, ".", "soja", ctx)
          end
        ';
    }

此例在我的本上只需 0.18 秒。而 300,000 也只需 0.21 秒，3,000,000 也只需 2.2 秒。此时得到的 nginx
worker 进程的“火焰图”是这个样子的：

http://agentzh.org/misc/flamegraph/no-hot-output-filter.svg

现在 CPU 时间的分布主要集中在 ngx_http_lua_ngx_re_match  这个函数帧，也就是 ngx.re.match 这个调用上面了。

这里的问题与 PCRE 倒没什么关系，你直接用一个很热的循环专门调用 ngx.print() 也应当会出现类似的 CPU 过热现象。

在分析 CPU 过高问题的时候，火焰图工具比使用 pstack 工具进行手工采样要方便和高级多了。更多细节可以参见

https://github.com/agentzh/nginx-systemtap-toolkit#ngx-sample-bt

Best regards,
-agentzh

lancelijade

我这里碰到不是ngx.print的问题，因为最早发现这个问题时并没有ngx.print输出，而进程100%占用cpu完成不了，例子里用ngx.print只是为了更明显看出问题。

另外，即使ngx.print占用cpu过高，也不应该完成不了请求才对，我这里的实际现象就是请求无法完成。

我试着再改一下测试用例

Lance

2013/4/3 agentzh <age...@gmail.com>

Hello!

On Tue, Apr 2, 2013 at 11:20 PM, Lance wrote:
> 以下为测试代码
> server
> {
> listen 80;
> server_name test;
> location /
> {
> content_by_lua '
> local key = string.rep ("x", 200000)
> local ctx = {}
> local m, err = ngx.re.match(key, ".", "soja", ctx)
> while m do
> ngx.print(m[0])

你这里不应在一个很热的循环里调用 ngx.print()，因为 ngx.print() 是高代价操作，必然会调用整个 Nginx
输出过滤器链。正确的做法应当是把输出自己缓冲起来，比如放在一个 Lua table 或者 Lua 字符串中，最后在循环外面一次性调用
ngx.print() 输出。

在我的笔记本上直接运行你的例子，200,000 时请求时间是 1.1 秒，300,000 时是 1.7 秒，而当使用 3,000,000
时需要 16.8 秒。如果使用 Nginx Systemtap Toolkit 中的火焰图工具对此时的 Nginx worker
进程进行采样分析，可以得到下面这样的火焰图：

http://agentzh.org/misc/flamegraph/hot-output-filter.svg

从图中可以清楚地看到，Nginx 输出过滤器链条上的 ngx_chain_update_chains 和
ngx_http_write_filter 这两个函数占用了大部分的 CPU 时间。

按照我上面的建议减少 ngx.print() 的调用次数可以解决这里的性能问题，比如：

location / {
content_by_lua '
local key = string.rep ("x", 200000)
local ctx = {}
local m, err = ngx.re.match(key, ".", "soja", ctx)

local i = 0
local buf = {}
while m do
buf[#buf + 1] = m[0]
i = i + 1
if i >= 1000 then
ngx.print(buf)
i = 0
buf = {}
end

m, err = ngx.re.match(key, ".", "soja", ctx)
end
';
}

此例在我的本上只需 0.18 秒。而 300,000 也只需 0.21 秒，3,000,000 也只需 2.2 秒。此时得到的 nginx
worker 进程的“火焰图”是这个样子的：

http://agentzh.org/misc/flamegraph/no-hot-output-filter.svg

现在 CPU 时间的分布主要集中在 ngx_http_lua_ngx_re_match 这个函数帧，也就是 ngx.re.match 这个调用上面了。

这里的问题与 PCRE 倒没什么关系，你直接用一个很热的循环专门调用 ngx.print() 也应当会出现类似的 CPU 过热现象。

在分析 CPU 过高问题的时候，火焰图工具比使用 pstack 工具进行手工采样要方便和高级多了。更多细节可以参见

https://github.com/agentzh/nginx-systemtap-toolkit#ngx-sample-bt

Best regards,
-agentzh

--

lancelijade

现在碰到这样一个问题，测试例子改成了
    server
    {
        listen 80;
        server_name test;

        location /
        {
            content_by_lua '
              local key = string.rep ("x", 3000000)
              local ctx = {}
              local m, err = ngx.re.match(key, ".", "soja", ctx)
              while m do
--                ngx.print(m[0])
                m, err = ngx.re.match(key, ".", "soja", ctx)
              end
            ';
        }
    }

即去掉输出，字符串长度加到了3M

开始若干次执行没有问题，在2.x秒内完成，但从某一次后，errorlog 里出了这么一行
nginx: lua atpanic: Lua VM crashed, reason: not enough memory

再之后每次请求，都是500了，errorlog里是
2013/04/03 15:17:25 [error] 15246#0: *1675 lua entry thread aborted: memory allocation error: not enough memory
stack traceback:
coroutine 0:
        [C]: in function 'match'
        [string "content_by_lua"]:7: in function <[string "content_by_lua"]:1>, client: 127.0.0.1, server: test, request: "GET / HTTP/1.1", host: "test"

查看进程列表结果如下
[root@testconf]# ps aux | grep nginx
root     11056 0.0 0.0 1588232 3116 ?        Ss   Apr02   0:00 nginx: master process /usr/local/openresty/nginx/sbin/nginx
www      15246 5.3 3.1 2617776 1032700 ?     S    15:15   0:08 nginx: worker process
www      15247 2.9 1.7 2157872 572708 ?      S    15:15   0:04 nginx: worker process
www      15248 0.0 0.0 1589320 3728 ?        S    15:15   0:00 nginx: worker process
www      15249 0.0 0.0 1589320 3728 ?        S    15:15   0:00 nginx: worker process
www      15250 2.9 1.7 2157872 572708 ?      S    15:15   0:04 nginx: worker process
www      15251 1.4 0.8 1875192 289992 ?      S    15:15   0:02 nginx: worker process

这是内存泄漏？

Lance

2013/4/3 Lance <lance...@gmail.com>

我这里碰到不是ngx.print的问题，因为最早发现这个问题时并没有ngx.print输出，而进程100%占用cpu完成不了，例子里用ngx.print只是为了更明显看出问题。

另外，即使ngx.print占用cpu过高，也不应该完成不了请求才对，我这里的实际现象就是请求无法完成。

我试着再改一下测试用例

Lance

2013/4/3 agentzh <age...@gmail.com>
Hello!

On Tue, Apr 2, 2013 at 11:20 PM, Lance wrote:
> 以下为测试代码
> server
> {
> listen 80;
> server_name test;
> location /
> {
> content_by_lua '
> local key = string.rep ("x", 200000)
> local ctx = {}
> local m, err = ngx.re.match(key, ".", "soja", ctx)
> while m do
> ngx.print(m[0])

你这里不应在一个很热的循环里调用 ngx.print()，因为 ngx.print() 是高代价操作，必然会调用整个 Nginx
输出过滤器链。正确的做法应当是把输出自己缓冲起来，比如放在一个 Lua table 或者 Lua 字符串中，最后在循环外面一次性调用
ngx.print() 输出。

在我的笔记本上直接运行你的例子，200,000 时请求时间是 1.1 秒，300,000 时是 1.7 秒，而当使用 3,000,000
时需要 16.8 秒。如果使用 Nginx Systemtap Toolkit 中的火焰图工具对此时的 Nginx worker
进程进行采样分析，可以得到下面这样的火焰图：

http://agentzh.org/misc/flamegraph/hot-output-filter.svg

从图中可以清楚地看到，Nginx 输出过滤器链条上的 ngx_chain_update_chains 和
ngx_http_write_filter 这两个函数占用了大部分的 CPU 时间。

按照我上面的建议减少 ngx.print() 的调用次数可以解决这里的性能问题，比如：

location / {
content_by_lua '
local key = string.rep ("x", 200000)
local ctx = {}
local m, err = ngx.re.match(key, ".", "soja", ctx)

local i = 0
local buf = {}
while m do
buf[#buf + 1] = m[0]
i = i + 1
if i >= 1000 then
ngx.print(buf)
i = 0
buf = {}
end

m, err = ngx.re.match(key, ".", "soja", ctx)
end
';
}

此例在我的本上只需 0.18 秒。而 300,000 也只需 0.21 秒，3,000,000 也只需 2.2 秒。此时得到的 nginx
worker 进程的“火焰图”是这个样子的：

http://agentzh.org/misc/flamegraph/no-hot-output-filter.svg

现在 CPU 时间的分布主要集中在 ngx_http_lua_ngx_re_match 这个函数帧，也就是 ngx.re.match 这个调用上面了。

这里的问题与 PCRE 倒没什么关系，你直接用一个很热的循环专门调用 ngx.print() 也应当会出现类似的 CPU 过热现象。

在分析 CPU 过高问题的时候，火焰图工具比使用 pstack 工具进行手工采样要方便和高级多了。更多细节可以参见

https://github.com/agentzh/nginx-systemtap-toolkit#ngx-sample-bt

Best regards,
-agentzh

--

kindy61

呃，不是内存泄漏，应该是 lua 还没来得及 gc。

在while循环后面加一句 (主动gc)

collectgarbage "collect"

试试吧。

我这里测试没问题。

2013/4/3 Lance <lance...@gmail.com>

现在碰到这样一个问题，测试例子改成了

    server
    {
        listen 80;
        server_name test;

        location /
        {
            content_by_lua '
              local key = string.rep ("x", 3000000)

              local ctx = {}
              local m, err = ngx.re.match(key, ".", "soja", ctx)
              while m do
--                ngx.print(m[0])

                m, err = ngx.re.match(key, ".", "soja", ctx)
              end
            ';
        }
    }

即去掉输出，字符串长度加到了3M

开始若干次执行没有问题，在2.x秒内完成，但从某一次后，errorlog 里出了这么一行
nginx: lua atpanic: Lua VM crashed, reason: not enough memory

再之后每次请求，都是500了，errorlog里是
2013/04/03 15:17:25 [error] 15246#0: *1675 lua entry thread aborted: memory allocation error: not enough memory
stack traceback:
coroutine 0:
        [C]: in function 'match'
        [string "content_by_lua"]:7: in function <[string "content_by_lua"]:1>, client: 127.0.0.1, server: test, request: "GET / HTTP/1.1", host: "test"

查看进程列表结果如下
[root@testconf]# ps aux | grep nginx
root     11056 0.0 0.0 1588232 3116 ?        Ss   Apr02   0:00 nginx: master process /usr/local/openresty/nginx/sbin/nginx
www      15246 5.3 3.1 2617776 1032700 ?     S    15:15   0:08 nginx: worker process
www      15247 2.9 1.7 2157872 572708 ?      S    15:15   0:04 nginx: worker process
www      15248 0.0 0.0 1589320 3728 ?        S    15:15   0:00 nginx: worker process
www      15249 0.0 0.0 1589320 3728 ?        S    15:15   0:00 nginx: worker process
www      15250 2.9 1.7 2157872 572708 ?      S    15:15   0:04 nginx: worker process
www      15251 1.4 0.8 1875192 289992 ?      S    15:15   0:02 nginx: worker process

这是内存泄漏？

Lance

2013/4/3 Lance <lance...@gmail.com>

我这里碰到不是ngx.print的问题，因为最早发现这个问题时并没有ngx.print输出，而进程100%占用cpu完成不了，例子里用ngx.print只是为了更明显看出问题。

另外，即使ngx.print占用cpu过高，也不应该完成不了请求才对，我这里的实际现象就是请求无法完成。

我试着再改一下测试用例

Lance

2013/4/3 agentzh <age...@gmail.com>
Hello!

On Tue, Apr 2, 2013 at 11:20 PM, Lance wrote:
> 以下为测试代码
> server
> {
> listen 80;
> server_name test;
> location /
> {
> content_by_lua '
> local key = string.rep ("x", 200000)
> local ctx = {}
> local m, err = ngx.re.match(key, ".", "soja", ctx)
> while m do
> ngx.print(m[0])

你这里不应在一个很热的循环里调用 ngx.print()，因为 ngx.print() 是高代价操作，必然会调用整个 Nginx
输出过滤器链。正确的做法应当是把输出自己缓冲起来，比如放在一个 Lua table 或者 Lua 字符串中，最后在循环外面一次性调用
ngx.print() 输出。

在我的笔记本上直接运行你的例子，200,000 时请求时间是 1.1 秒，300,000 时是 1.7 秒，而当使用 3,000,000
时需要 16.8 秒。如果使用 Nginx Systemtap Toolkit 中的火焰图工具对此时的 Nginx worker
进程进行采样分析，可以得到下面这样的火焰图：

http://agentzh.org/misc/flamegraph/hot-output-filter.svg

从图中可以清楚地看到，Nginx 输出过滤器链条上的 ngx_chain_update_chains 和
ngx_http_write_filter 这两个函数占用了大部分的 CPU 时间。

按照我上面的建议减少 ngx.print() 的调用次数可以解决这里的性能问题，比如：

location / {
content_by_lua '
local key = string.rep ("x", 200000)
local ctx = {}
local m, err = ngx.re.match(key, ".", "soja", ctx)

local i = 0
local buf = {}
while m do
buf[#buf + 1] = m[0]
i = i + 1
if i >= 1000 then
ngx.print(buf)
i = 0
buf = {}
end

m, err = ngx.re.match(key, ".", "soja", ctx)
end
';
}

此例在我的本上只需 0.18 秒。而 300,000 也只需 0.21 秒，3,000,000 也只需 2.2 秒。此时得到的 nginx
worker 进程的“火焰图”是这个样子的：

http://agentzh.org/misc/flamegraph/no-hot-output-filter.svg

现在 CPU 时间的分布主要集中在 ngx_http_lua_ngx_re_match 这个函数帧，也就是 ngx.re.match 这个调用上面了。

这里的问题与 PCRE 倒没什么关系，你直接用一个很热的循环专门调用 ngx.print() 也应当会出现类似的 CPU 过热现象。

在分析 CPU 过高问题的时候，火焰图工具比使用 pstack 工具进行手工采样要方便和高级多了。更多细节可以参见

https://github.com/agentzh/nginx-systemtap-toolkit#ngx-sample-bt

Best regards,
-agentzh

--

--
#xA0;

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

lancelijade

确实可以了

Lance

2013/4/3 kindy <kin...@gmail.com>

呃，不是内存泄漏，应该是 lua 还没来得及 gc。
在while循环后面加一句 (主动gc)
collectgarbage "collect"
试试吧。

我这里测试没问题。

2013/4/3 Lance <lance...@gmail.com>

现在碰到这样一个问题，测试例子改成了

    server
    {
        listen 80;
        server_name test;

        location /
        {
            content_by_lua '
              local key = string.rep ("x", 3000000)

              local ctx = {}
              local m, err = ngx.re.match(key, ".", "soja", ctx)
              while m do
--                ngx.print(m[0])

                m, err = ngx.re.match(key, ".", "soja", ctx)
              end
            ';
        }
    }

即去掉输出，字符串长度加到了3M

开始若干次执行没有问题，在2.x秒内完成，但从某一次后，errorlog 里出了这么一行
nginx: lua atpanic: Lua VM crashed, reason: not enough memory

再之后每次请求，都是500了，errorlog里是
2013/04/03 15:17:25 [error] 15246#0: *1675 lua entry thread aborted: memory allocation error: not enough memory
stack traceback:
coroutine 0:
        [C]: in function 'match'
        [string "content_by_lua"]:7: in function <[string "content_by_lua"]:1>, client: 127.0.0.1, server: test, request: "GET / HTTP/1.1", host: "test"

查看进程列表结果如下
[root@testconf]# ps aux | grep nginx
root     11056 0.0 0.0 1588232 3116 ?        Ss   Apr02   0:00 nginx: master process /usr/local/openresty/nginx/sbin/nginx
www      15246 5.3 3.1 2617776 1032700 ?     S    15:15   0:08 nginx: worker process
www      15247 2.9 1.7 2157872 572708 ?      S    15:15   0:04 nginx: worker process
www      15248 0.0 0.0 1589320 3728 ?        S    15:15   0:00 nginx: worker process
www      15249 0.0 0.0 1589320 3728 ?        S    15:15   0:00 nginx: worker process
www      15250 2.9 1.7 2157872 572708 ?      S    15:15   0:04 nginx: worker process
www      15251 1.4 0.8 1875192 289992 ?      S    15:15   0:02 nginx: worker process

这是内存泄漏？

Lance

2013/4/3 Lance <lance...@gmail.com>

我这里碰到不是ngx.print的问题，因为最早发现这个问题时并没有ngx.print输出，而进程100%占用cpu完成不了，例子里用ngx.print只是为了更明显看出问题。

另外，即使ngx.print占用cpu过高，也不应该完成不了请求才对，我这里的实际现象就是请求无法完成。

我试着再改一下测试用例

Lance

2013/4/3 agentzh <age...@gmail.com>
Hello!

On Tue, Apr 2, 2013 at 11:20 PM, Lance wrote:
> 以下为测试代码
> server
> {
> listen 80;
> server_name test;
> location /
> {
> content_by_lua '
> local key = string.rep ("x", 200000)
> local ctx = {}
> local m, err = ngx.re.match(key, ".", "soja", ctx)
> while m do
> ngx.print(m[0])

你这里不应在一个很热的循环里调用 ngx.print()，因为 ngx.print() 是高代价操作，必然会调用整个 Nginx
输出过滤器链。正确的做法应当是把输出自己缓冲起来，比如放在一个 Lua table 或者 Lua 字符串中，最后在循环外面一次性调用
ngx.print() 输出。

在我的笔记本上直接运行你的例子，200,000 时请求时间是 1.1 秒，300,000 时是 1.7 秒，而当使用 3,000,000
时需要 16.8 秒。如果使用 Nginx Systemtap Toolkit 中的火焰图工具对此时的 Nginx worker
进程进行采样分析，可以得到下面这样的火焰图：

http://agentzh.org/misc/flamegraph/hot-output-filter.svg

从图中可以清楚地看到，Nginx 输出过滤器链条上的 ngx_chain_update_chains 和
ngx_http_write_filter 这两个函数占用了大部分的 CPU 时间。

按照我上面的建议减少 ngx.print() 的调用次数可以解决这里的性能问题，比如：

location / {
content_by_lua '
local key = string.rep ("x", 200000)
local ctx = {}
local m, err = ngx.re.match(key, ".", "soja", ctx)

local i = 0
local buf = {}
while m do
buf[#buf + 1] = m[0]
i = i + 1
if i >= 1000 then
ngx.print(buf)
i = 0
buf = {}
end

m, err = ngx.re.match(key, ".", "soja", ctx)
end
';
}

此例在我的本上只需 0.18 秒。而 300,000 也只需 0.21 秒，3,000,000 也只需 2.2 秒。此时得到的 nginx
worker 进程的“火焰图”是这个样子的：

http://agentzh.org/misc/flamegraph/no-hot-output-filter.svg

现在 CPU 时间的分布主要集中在 ngx_http_lua_ngx_re_match 这个函数帧，也就是 ngx.re.match 这个调用上面了。

这里的问题与 PCRE 倒没什么关系，你直接用一个很热的循环专门调用 ngx.print() 也应当会出现类似的 CPU 过热现象。

在分析 CPU 过高问题的时候，火焰图工具比使用 pstack 工具进行手工采样要方便和高级多了。更多细节可以参见

https://github.com/agentzh/nginx-systemtap-toolkit#ngx-sample-bt

Best regards,
-agentzh

--

--
#xA0;

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

--
#xA0;

lancelijade

这个总结一下，似乎是pcre的问题，我重新启一个话题吧。

Lance

2013/4/3 Lance <lance...@gmail.com>

确实可以了

Lance

2013/4/3 kindy <kin...@gmail.com>

呃，不是内存泄漏，应该是 lua 还没来得及 gc。
在while循环后面加一句 (主动gc)
collectgarbage "collect"
试试吧。

我这里测试没问题。

2013/4/3 Lance <lance...@gmail.com>

现在碰到这样一个问题，测试例子改成了

    server
    {
        listen 80;
        server_name test;

        location /
        {
            content_by_lua '
              local key = string.rep ("x", 3000000)

              local ctx = {}
              local m, err = ngx.re.match(key, ".", "soja", ctx)
              while m do
--                ngx.print(m[0])

                m, err = ngx.re.match(key, ".", "soja", ctx)
              end
            ';
        }
    }

即去掉输出，字符串长度加到了3M

开始若干次执行没有问题，在2.x秒内完成，但从某一次后，errorlog 里出了这么一行
nginx: lua atpanic: Lua VM crashed, reason: not enough memory

再之后每次请求，都是500了，errorlog里是
2013/04/03 15:17:25 [error] 15246#0: *1675 lua entry thread aborted: memory allocation error: not enough memory
stack traceback:
coroutine 0:
        [C]: in function 'match'
        [string "content_by_lua"]:7: in function <[string "content_by_lua"]:1>, client: 127.0.0.1, server: test, request: "GET / HTTP/1.1", host: "test"

查看进程列表结果如下
[root@testconf]# ps aux | grep nginx
root     11056 0.0 0.0 1588232 3116 ?        Ss   Apr02   0:00 nginx: master process /usr/local/openresty/nginx/sbin/nginx
www      15246 5.3 3.1 2617776 1032700 ?     S    15:15   0:08 nginx: worker process
www      15247 2.9 1.7 2157872 572708 ?      S    15:15   0:04 nginx: worker process
www      15248 0.0 0.0 1589320 3728 ?        S    15:15   0:00 nginx: worker process
www      15249 0.0 0.0 1589320 3728 ?        S    15:15   0:00 nginx: worker process
www      15250 2.9 1.7 2157872 572708 ?      S    15:15   0:04 nginx: worker process
www      15251 1.4 0.8 1875192 289992 ?      S    15:15   0:02 nginx: worker process

这是内存泄漏？

Lance

2013/4/3 Lance <lance...@gmail.com>

我这里碰到不是ngx.print的问题，因为最早发现这个问题时并没有ngx.print输出，而进程100%占用cpu完成不了，例子里用ngx.print只是为了更明显看出问题。

另外，即使ngx.print占用cpu过高，也不应该完成不了请求才对，我这里的实际现象就是请求无法完成。

我试着再改一下测试用例

Lance

2013/4/3 agentzh <age...@gmail.com>
Hello!

On Tue, Apr 2, 2013 at 11:20 PM, Lance wrote:
> 以下为测试代码
> server
> {
> listen 80;
> server_name test;
> location /
> {
> content_by_lua '
> local key = string.rep ("x", 200000)
> local ctx = {}
> local m, err = ngx.re.match(key, ".", "soja", ctx)
> while m do
> ngx.print(m[0])

你这里不应在一个很热的循环里调用 ngx.print()，因为 ngx.print() 是高代价操作，必然会调用整个 Nginx
输出过滤器链。正确的做法应当是把输出自己缓冲起来，比如放在一个 Lua table 或者 Lua 字符串中，最后在循环外面一次性调用
ngx.print() 输出。

在我的笔记本上直接运行你的例子，200,000 时请求时间是 1.1 秒，300,000 时是 1.7 秒，而当使用 3,000,000
时需要 16.8 秒。如果使用 Nginx Systemtap Toolkit 中的火焰图工具对此时的 Nginx worker
进程进行采样分析，可以得到下面这样的火焰图：

http://agentzh.org/misc/flamegraph/hot-output-filter.svg

从图中可以清楚地看到，Nginx 输出过滤器链条上的 ngx_chain_update_chains 和
ngx_http_write_filter 这两个函数占用了大部分的 CPU 时间。

按照我上面的建议减少 ngx.print() 的调用次数可以解决这里的性能问题，比如：

location / {
content_by_lua '
local key = string.rep ("x", 200000)
local ctx = {}
local m, err = ngx.re.match(key, ".", "soja", ctx)

local i = 0
local buf = {}
while m do
buf[#buf + 1] = m[0]
i = i + 1
if i >= 1000 then
ngx.print(buf)
i = 0
buf = {}
end

m, err = ngx.re.match(key, ".", "soja", ctx)
end
';
}

此例在我的本上只需 0.18 秒。而 300,000 也只需 0.21 秒，3,000,000 也只需 2.2 秒。此时得到的 nginx
worker 进程的“火焰图”是这个样子的：

http://agentzh.org/misc/flamegraph/no-hot-output-filter.svg

现在 CPU 时间的分布主要集中在 ngx_http_lua_ngx_re_match 这个函数帧，也就是 ngx.re.match 这个调用上面了。

这里的问题与 PCRE 倒没什么关系，你直接用一个很热的循环专门调用 ngx.print() 也应当会出现类似的 CPU 过热现象。

在分析 CPU 过高问题的时候，火焰图工具比使用 pstack 工具进行手工采样要方便和高级多了。更多细节可以参见

https://github.com/agentzh/nginx-systemtap-toolkit#ngx-sample-bt

Best regards,
-agentzh

--

--
#xA0;

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

--
#xA0;