nginx worker 进程cpu 100%的问题

sailorf

Hi all，

我在使用openresty的过程，碰到worker进程cpu跑满的情况，调试了一下，无法找到原因，希望各位大大帮帮忙。

服务器：

Linux xxxx 2.6.32-5-amd64 #1 SMP Mon Sep 23 22:14:43 UTC 2013 x86_64 GNU/Linux

openresty版本：

ngx_openresty-1.2.4.14

有luajit2.0.0

进程情况：

15864 nobody 20 0 143m 7152 1836 R 100 0.1 455:58.97 nginx

21582 nobody 20 0 817m 681m 1848 S 3 5.7 1:16.76 nginx

15864这个进程cpu 100，其他进程有也可能出现，无法必然重现，所以调试起来很麻烦。

服务器是生产机，无法重装系统加入utrace，所以nginx-systemtap-toolkit工具集无法使用。

gdb attach到进程，stop后打出的栈：

#0 0x00007f82864ae2dc in ctype_child (g=0x404343b8, cd=0x4044cc18) at lj_ctype.h:413

#1 ctype_raw (g=0x404343b8, cd=0x4044cc18) at lj_ctype.h:420

#2 lj_cdata_free (g=0x404343b8, cd=0x4044cc18) at lj_cdata.c:69

#3 0x00007f8286448a85 in gc_sweep (g=0x404343b8, p=0x404445c8, lim=17) at lj_gc.c:405

#4 0x00007f8286449666 in gc_onestep (L=0x4044e690) at lj_gc.c:632

#5 0x00007f82864497f8 in lj_gc_step (L=0x4044e690) at lj_gc.c:676

#6 0x00007f828645f576 in lj_parse_keepstr (ls=0x7fff96906160,

str=0x40453b88 "Cen_type[?]\"signed char u_char;\n\nu_char * ngx_hex_dump(u_char *dst, const u_char *src, size_t len);\n\nintptr_t ngx_atoi(const unsigned char *line, size_t n);\n]]", len=1)

at lj_parse.c:238

#7 0x00007f828645e087 in llex (ls=0x7fff96906160, tv=0x7fff96906170) at lj_lex.c:274

#8 0x00007f828645eee4 in lj_lex_next (ls=0x7fff96906160) at lj_lex.c:430

#9 0x00007f8286461a80 in lex_opt (ls=0x7fff96906160, tok=41) at lj_parse.c:984

#10 0x00007f8286461afa in lex_match (ls=0x7fff96906160, what=41, who=40, line=31) at lj_parse.c:1001

#11 0x00007f8286464f4f in parse_args (ls=0x7fff96906160, e=0x7fff969057b0) at lj_parse.c:1930

#12 0x00007f828646532c in expr_primary (ls=0x7fff96906160, v=0x7fff969057b0) at lj_parse.c:1988

#13 0x00007f8286465723 in expr_simple (ls=0x7fff96906160, v=0x7fff969057b0) at lj_parse.c:2034

#14 0x00007f8286465906 in expr_unop (ls=0x7fff96906160, v=0x7fff969057b0) at lj_parse.c:2100

#15 0x00007f8286465982 in expr_binop (ls=0x7fff96906160, v=0x7fff969057b0, limit=0) at lj_parse.c:2113

#16 0x00007f8286465a8e in expr (ls=0x7fff96906160, v=0x7fff969057b0) at lj_parse.c:2132

#17 0x00007f8286464e2b in expr_list (ls=0x7fff96906160, v=0x7fff969057b0) at lj_parse.c:1900

#18 0x00007f82864661ef in parse_local (ls=0x7fff96906160) at lj_parse.c:2284

#19 0x00007f82864675f3 in parse_stmt (ls=0x7fff96906160) at lj_parse.c:2670

#20 0x00007f82864676b0 in parse_chunk (ls=0x7fff96906160) at lj_parse.c:2706

#21 0x00007f8286464c1f in parse_body (ls=0x7fff96906160, e=0x7fff96905c00, needself=0, line=29) at lj_parse.c:1877

#22 0x00007f82864662f8 in parse_func (ls=0x7fff96906160, line=29) at lj_parse.c:2309

#23 0x00007f82864675d4 in parse_stmt (ls=0x7fff96906160) at lj_parse.c:2666

#24 0x00007f82864676b0 in parse_chunk (ls=0x7fff96906160) at lj_parse.c:2706

#25 0x00007f82864678de in lj_parse (ls=0x7fff96906160) at lj_parse.c:2739

#26 0x00007f828646a671 in cpparser (L=0x4044e690, dummy=0, ud=0x7fff96906160) at lj_load.c:41

#27 0x00007f82864457ec in lj_vm_cpcall () from /usr/local/openresty/luajit/lib/libluajit-5.1.so.2

#28 0x00007f828646a7d2 in lua_loadx (L=0x4044e690, reader=0x7f828646a873 <reader_file>, data="" chunkname=0x403a9d70 "@/usr/local/openresty/lualib/resty/string.lua", mode=0x0) at lj_load.c:58

#29 0x00007f828646a9ee in luaL_loadfilex (L=0x4044e690, filename=0x4044e710 "/usr/local/openresty/lualib/resty/string.lua", mode=0x0) at lj_load.c:101

#30 0x00007f828646ab39 in luaL_loadfile (L=0x4044e690, filename=0x4044e710 "/usr/local/openresty/lualib/resty/string.lua") at lj_load.c:119

#31 0x00007f82864d01c3 in lj_cf_package_loader_lua (L=0x4044e690) at lib_package.c:345

#32 0x00007f82864454ab in lj_BC_FUNCC () from /usr/local/openresty/luajit/lib/libluajit-5.1.so.2

#33 0x00007f828645bdae in lua_call (L=0x4044e690, nargs=1, nresults=1) at lj_api.c:1034

#34 0x00007f82864d06a7 in lj_cf_package_require (L=0x4044e690) at lib_package.c:423

#35 0x00007f82864454ab in lj_BC_FUNCC () from /usr/local/openresty/luajit/lib/libluajit-5.1.so.2

#36 0x00007f828645c3ac in lua_resume (L=0x4044e690, nargs=0) at lj_api.c:1134

#37 0x0000000000494c78 in ngx_http_lua_run_thread (L=0x40434378, r=<value optimized out>, ctx=<value optimized out>, nret=<value optimized out>) at ../ngx_lua-0.7.9/src/ngx_http_lua_util.c:1017

#38 0x0000000000496de5 in ngx_http_lua_content_by_chunk (L=0x40434378, r=0x10cae90) at ../ngx_lua-0.7.9/src/ngx_http_lua_contentby.c:100

#39 0x000000000049701c in ngx_http_lua_content_handler_file (r=0x10cae90) at ../ngx_lua-0.7.9/src/ngx_http_lua_contentby.c:266

#40 0x0000000000497154 in ngx_http_lua_content_handler (r=0x10cae90) at ../ngx_lua-0.7.9/src/ngx_http_lua_contentby.c:197

#41 0x000000000043f24b in ngx_http_core_content_phase (r=0x404343b8, ph=0x10de9a0) at src/http/ngx_http_core_module.c:1407

#42 0x0000000000439f83 in ngx_http_core_run_phases (r=0x10cae90) at src/http/ngx_http_core_module.c:888

#43 0x000000000043a07d in ngx_http_handler (r=0x404343b8) at src/http/ngx_http_core_module.c:871

#44 0x0000000000443a4f in ngx_http_process_request (r=0x10cae90) at src/http/ngx_http_request.c:1694

#45 0x000000000044403c in ngx_http_process_request_headers (rev=<value optimized out>) at src/http/ngx_http_request.c:1144

#46 0x0000000000444576 in ngx_http_process_request_line (rev=0x7f827e2c27c8) at src/http/ngx_http_request.c:940

#47 0x0000000000441bb0 in ngx_http_init_request (rev=0x7f827e2c27c8) at src/http/ngx_http_request.c:524

#48 0x000000000042ce66 in ngx_event_process_posted (cycle=<value optimized out>, posted=0x4044cc18) at src/event/ngx_event_posted.c:40

#49 0x000000000042cd36 in ngx_process_events_and_timers (cycle=0x10c06a0) at src/event/ngx_event.c:274

#50 0x00000000004329af in ngx_worker_process_cycle (cycle=0x10c06a0, data="" optimized out>) at src/os/unix/ngx_process_cycle.c:814

#51 0x000000000043128c in ngx_spawn_process (cycle=0x10c06a0, proc=0x4328d7 <ngx_worker_process_cycle>, data="" optimized out>, name=0x4baae9 "worker process", respawn=-3)

at src/os/unix/ngx_process.c:198

#52 0x0000000000432070 in ngx_start_worker_processes (cycle=0x10c06a0, n=8, type=-3) at src/os/unix/ngx_process_cycle.c:367

---Type <return> to continue, or q <return> to quit---

#53 0x0000000000432eed in ngx_master_process_cycle (cycle=0x10c06a0) at src/os/unix/ngx_process_cycle.c:137

#54 0x000000000041886a in main (argc=<value optimized out>, argv=<value optimized out>) at src/core/nginx.c:410

感觉是在luajit的gc过程中死循环了，一直在lj_ctype.h的这个while中跑。

/* Get raw type for a C type ID. */

static LJ_AINLINE CType *ctype_raw(CTState *cts, CTypeID id)

{

CType *ct = ctype_get(cts, id);

while (ctype_isattrib(ct->info)) ct = ctype_child(cts, ct); // 在这里跑

return ct;

}

(gdb) p *ct

$1 = {info = 2147811328, size = 0, sib = 0, next = 0, name = {gcptr32 = 0}}

(gdb) p *cts

$2 = {tab = 0x403c1f70, top = 125, sizetab = 128, L = 0x4044e690, g = 0x404343b8, finalizer = 0x40436c18, miscmap = 0x403a9d10, cb = {fpr = {{d = 0, f = {0, 0}}, {d = 0, f = {0, 0}}, {d = 0, f = {0, 0}}, {

d = 0, f = {0, 0}}, {d = 0, f = {0, 0}}, {d = 0, f = {0, 0}}, {d = 0, f = {0, 0}}, {d = 0, f = {0, 0}}}, gpr = {0, 0, 0, 0, 0, 0, 0, 0}, stack = 0x0, mcode = 0x0, cbid = 0x0, sizeid = 0,

topid = 0, slot = 0}, hash = {11, 0, 7, 0, 118, 65, 94, 123, 14, 17, 18, 100, 19, 0, 119, 0, 108, 99, 41, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 86, 0, 16, 0, 0, 0, 0, 111, 0, 0, 0, 0, 0, 124,

0 <repeats 20 times>, 2, 61, 0, 4, 0, 20, 0, 122, 52, 53, 0, 55, 56, 0, 0, 58, 44, 45, 62, 47, 48, 78, 50, 66, 0, 37, 68, 69, 0, 71, 72, 73, 74, 75, 34, 0, 77, 0, 79, 80, 81, 82, 26, 38, 39, 112, 42,

95, 88, 89, 90, 91, 92, 93, 0, 0, 0, 96, 54, 83, 84, 0, 0, 114, 97}}

lua代码的话，非常抱歉，暂时无法提供，用到了resty-mysql, resty.sha1, resty.string

但无论lua怎么写，应该不会让gc跑死吧？

先行感谢各位大大。

agentzh

Hello!

On Wed, Nov 13, 2013 at 7:04 PM, sailorf wrote:
>
> openresty版本：
> ngx_openresty-1.2.4.14
> 有luajit2.0.0
>

题外话：建议升级到最新的 ngx_openresty 稳定版（目前是 1.4.3.4）。

>
> 服务器是生产机，无法重装系统加入utrace，所以nginx-systemtap-toolkit工具集无法使用。

建议确保生产环境有 uprobes 支持，这样很多在线问题都可以快速诊断。

> gdb attach到进程，stop后打出的栈：
>
[...]
> #6  0x00007f828645f576 in lj_parse_keepstr (ls=0x7fff96906160,
>     str=0x40453b88 "Cen_type[?]\"signed char u_char;\n\nu_char *
> ngx_hex_dump(u_char *dst, const u_char *src, size_t len);\n\nintptr_t
> ngx_atoi(const unsigned char *line, size_t n);\n]]", len=1)
>     at lj_parse.c:238
> #7  0x00007f828645e087 in llex (ls=0x7fff96906160, tv=0x7fff96906170) at
> lj_lex.c:274
> #8  0x00007f828645eee4 in lj_lex_next (ls=0x7fff96906160) at lj_lex.c:430

这里有趣的不是 GC 相关的帧，而是上面的这些和 LuaJIT parser 和 lexer 相关的帧。这说明你的 Lua 代码正在加载
lua-resty-string 的 Lua 代码。你如果用 gdb 中断多次，得到的 C
调用栈都是类似的，说明你很可能不正确地在生产上配置了 lua_code_cache off 或者自己不正确地清空了
package.loaded 表里的东西。毕竟 Lua module 在 Lua
代码缓存启用的情况下只会加载一次，后续的请求都不会触发重新加载。

Regards,
-agentzh

wang.fl1429

之前我们也遇到过, 最后发现是ｌｕａ代码中的错误,

使用 underscore.lua 中的迭代器, 但是它的迭代器是用 cosocket 实现的,导致了死循环, 最后修改了这个迭代器实现后解决了.

定位问题使用的是 systemtap.

2013/11/14 Yichun Zhang (agentzh) <age...@gmail.com>

Hello!

On Wed, Nov 13, 2013 at 7:04 PM, sailorf wrote:
>
> openresty版本：
> ngx_openresty-1.2.4.14
> 有luajit2.0.0
>

题外话：建议升级到最新的 ngx_openresty 稳定版（目前是 1.4.3.4）。

>
> 服务器是生产机，无法重装系统加入utrace，所以nginx-systemtap-toolkit工具集无法使用。

建议确保生产环境有 uprobes 支持，这样很多在线问题都可以快速诊断。

> gdb attach到进程，stop后打出的栈：
>
[...]

> #6 0x00007f828645f576 in lj_parse_keepstr (ls=0x7fff96906160,
> str=0x40453b88 "Cen_type[?]\"signed char u_char;\n\nu_char *
> ngx_hex_dump(u_char *dst, const u_char *src, size_t len);\n\nintptr_t
> ngx_atoi(const unsigned char *line, size_t n);\n]]", len=1)
> at lj_parse.c:238
> #7 0x00007f828645e087 in llex (ls=0x7fff96906160, tv=0x7fff96906170) at
> lj_lex.c:274
> #8 0x00007f828645eee4 in lj_lex_next (ls=0x7fff96906160) at lj_lex.c:430

这里有趣的不是 GC 相关的帧，而是上面的这些和 LuaJIT parser 和 lexer 相关的帧。这说明你的 Lua 代码正在加载
lua-resty-string 的 Lua 代码。你如果用 gdb 中断多次，得到的 C
调用栈都是类似的，说明你很可能不正确地在生产上配置了 lua_code_cache off 或者自己不正确地清空了
package.loaded 表里的东西。毕竟 Lua module 在 Lua
代码缓存启用的情况下只会加载一次，后续的请求都不会触发重新加载。

Regards,
-agentzh

--