Skip to content

Instantly share code, notes, and snippets.

@sonots
Last active August 29, 2015 13:59
Show Gist options
  • Star 0 You must be signed in to star a gist
  • Fork 0 You must be signed in to fork a gist
  • Save sonots/10803036 to your computer and use it in GitHub Desktop.
Save sonots/10803036 to your computer and use it in GitHub Desktop.
Fluentd stuck on shutdown (3), This time is at IO#recvfrom
$ gdb /usr/lib64/fluent/ruby/bin/ruby core.22111
(gdb) info thread
18 Thread 0x7f21ae50c700 (LWP 22111) 0x00007f21ae0ec3dc in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
17 Thread 0x7f1deecec700 (LWP 10864) 0x00007f21ae0ec3dc in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
16 Thread 0x7f1eda9e9700 (LWP 22494) 0x00007f21ae0ec75b in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
15 Thread 0x7f1edabeb700 (LWP 22492) 0x00007f21ae0ec75b in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
14 Thread 0x7f1edaded700 (LWP 22491) 0x00007f21ae0ef963 in recvfrom () from /lib64/libpthread.so.0
13 Thread 0x7f1edafef700 (LWP 22471) 0x00007f21ae0ec75b in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
12 Thread 0x7f1edb1f1700 (LWP 22469) 0x00007f21ae0ec75b in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
11 Thread 0x7f219a4e4700 (LWP 22191) 0x00007f21ae0ec75b in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
10 Thread 0x7f219a6e6700 (LWP 22190) 0x00007f21ae0ec75b in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
9 Thread 0x7f219aeee700 (LWP 22186) 0x00007f21ae0ec75b in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
8 Thread 0x7f219b0f0700 (LWP 22185) 0x00007f21ae0ec75b in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
7 Thread 0x7f219b4f4700 (LWP 22183) 0x00007f21ae0ec75b in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
6 Thread 0x7f219b6f6700 (LWP 22182) 0x00007f21ae0ec75b in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
5 Thread 0x7f219bafa700 (LWP 22180) 0x00007f21ae0ec75b in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
4 Thread 0x7f219bcfc700 (LWP 22179) 0x00007f21ae0ec75b in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
3 Thread 0x7f21a0228700 (LWP 22177) 0x00007f21ae0ec75b in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
2 Thread 0x7f21a042a700 (LWP 22176) 0x00007f21ae0ec75b in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
* 1 Thread 0x7f21ae51a700 (LWP 22113) 0x00007f21ad555053 in poll () from /lib64/libc.so.6
(gdb) thread 14
[Switching to thread 14 (Thread 0x7f1edaded700 (LWP 22491))]#0 0x00007f21ae0ef963 in recvfrom () from /lib64/libpthread.so.0
(gdb) bt
#0 0x00007f21ae0ef963 in recvfrom () from /lib64/libpthread.so.0
#1 0x00007f21a47aaf45 in recvfrom (data=0x7f1edadeb460) at /usr/include/bits/socket2.h:77
#2 recvfrom_blocking (data=0x7f1edadeb460) at init.c:103
#3 0x00007f21ae6a0b13 in rb_thread_io_blocking_region (func=0x7f21a47aaf10 <recvfrom_blocking>, data1=0x7f1edadeb460, fd=15) at thread.c:1388
#4 0x00007f21a47ab804 in rsock_s_recvfrom (sock=139782667581400, argc=<value optimized out>, argv=<value optimized out>, from=RECV_IP) at init.c:139
#5 0x00007f21ae67f802 in vm_call_cfunc_with_frame (th=0x7f21b1995210, reg_cfp=0x7f1edaeede30, ci=<value optimized out>) at vm_insnhelper.c:1470
#6 0x00007f21ae688eb1 in vm_exec_core (th=<value optimized out>, initial=<value optimized out>) at insns.def:1028
#7 0x00007f21ae68e2c1 in vm_exec (th=0x7f21b1995210) at vm.c:1304
#8 0x00007f21ae680c81 in vm_call0_body (th=0x7f21b1995210, ci=0x7f1edadec290, argv=<value optimized out>) at vm_eval.c:171
#9 0x00007f21ae685f5d in vm_call0 (recv=139782667581120, mid=53816, n=0) at vm_eval.c:50
#10 rb_call0 (recv=139782667581120, mid=53816, n=0) at vm_eval.c:325
#11 rb_call (recv=139782667581120, mid=53816, n=0) at vm_eval.c:586
#12 rb_funcall (recv=139782667581120, mid=53816, n=0) at vm_eval.c:795
#13 0x00007f21a26cdc29 in Coolio_Loop_dispatch_events (loop_data=0x7f21b0cf6f70) at loop.c:300
#14 0x00007f21a26cdec9 in Coolio_Loop_run_once (argc=<value optimized out>, argv=<value optimized out>, self=<value optimized out>) at loop.c:256
#15 0x00007f21ae67f802 in vm_call_cfunc_with_frame (th=0x7f21b1995210, reg_cfp=0x7f1edaeedf20, ci=<value optimized out>) at vm_insnhelper.c:1470
#16 0x00007f21ae688eb1 in vm_exec_core (th=<value optimized out>, initial=<value optimized out>) at insns.def:1028
#17 0x00007f21ae68e2c1 in vm_exec (th=0x7f21b1995210) at vm.c:1304
#18 0x00007f21ae680c81 in vm_call0_body (th=0x7f21b1995210, ci=0x7f1edadec990, argv=<value optimized out>) at vm_eval.c:171
#19 0x00007f21ae681957 in vm_call0 (th=<value optimized out>, recv=<value optimized out>, id=<value optimized out>, argc=<value optimized out>, argv=<value optimized out>,
me=<value optimized out>, defined_class=139782670243800) at vm_eval.c:50
#20 rb_vm_call (th=<value optimized out>, recv=<value optimized out>, id=<value optimized out>, argc=<value optimized out>, argv=<value optimized out>, me=<value optimized out>,
defined_class=139782670243800) at vm_eval.c:247
#21 0x00007f21ae584c19 in rb_method_call_with_block (argc=0, argv=0x7f21b03f6fb0, method=<value optimized out>, pass_procval=8) at proc.c:1836
#22 0x00007f21ae58569a in bmcall (args=139782667595680, method=139782667578320, argc=0, argv=<value optimized out>, passed_proc=8) at proc.c:2300
#23 0x00007f21ae67fe53 in vm_yield_with_cfunc (th=0x7f21b1995210, block=0x7f21b1000d30, self=<value optimized out>, argc=0, argv=0x7f21b03f1830, blockargptr=<value optimized out>)
at vm_insnhelper.c:2097
#24 0x00007f21ae690474 in invoke_block_from_c (th=0x7f21b1995210, proc=0x7f21b1000d30, self=139782667578320, defined_class=139782653615360, argc=0, argv=0x7f21b03f1830, blockptr=0x0)
at vm.c:735
#25 vm_invoke_proc (th=0x7f21b1995210, proc=0x7f21b1000d30, self=139782667578320, defined_class=139782653615360, argc=0, argv=0x7f21b03f1830, blockptr=0x0) at vm.c:788
#26 0x00007f21ae6904ea in rb_vm_invoke_proc (th=<value optimized out>, proc=<value optimized out>, argc=<value optimized out>, argv=<value optimized out>, blockptr=<value optimized out>)
at vm.c:807
#27 0x00007f21ae69dad0 in thread_start_func_2 (th=0x7f21b1995210, stack_start=<value optimized out>) at thread.c:535
#28 0x00007f21ae6a12c0 in thread_start_func_1 (th_ptr=0x7f21b1995210) at thread_pthread.c:803
#29 0x00007f21ae0e87f1 in start_thread () from /lib64/libpthread.so.0
#30 0x00007f21ad55e70d in clone () from /lib64/libc.so.6
Sigdump at 2014-04-16 00:29:58 +0900 process 22111 (/home/game/fluentd/server/../vendor/bundle/bin/fluentd)
Thread #<Thread:0x007f21af69e768> status=run priority=0
/home/game/fluentd/vendor/bundle/gems/sigdump-0.2.2/lib/sigdump.rb:38:in `backtrace'
/home/game/fluentd/vendor/bundle/gems/sigdump-0.2.2/lib/sigdump.rb:38:in `dump_backtrace'
/home/game/fluentd/vendor/bundle/gems/sigdump-0.2.2/lib/sigdump.rb:24:in `block in dump_all_thread_backtrace'
/home/game/fluentd/vendor/bundle/gems/sigdump-0.2.2/lib/sigdump.rb:23:in `each'
/home/game/fluentd/vendor/bundle/gems/sigdump-0.2.2/lib/sigdump.rb:23:in `dump_all_thread_backtrace'
/home/game/fluentd/vendor/bundle/gems/sigdump-0.2.2/lib/sigdump.rb:16:in `block in dump'
/home/game/fluentd/vendor/bundle/gems/sigdump-0.2.2/lib/sigdump.rb:107:in `open'
/home/game/fluentd/vendor/bundle/gems/sigdump-0.2.2/lib/sigdump.rb:107:in `_open_dump_path'
/home/game/fluentd/vendor/bundle/gems/sigdump-0.2.2/lib/sigdump.rb:14:in `dump'
/home/game/fluentd/vendor/bundle/gems/sigdump-0.2.2/lib/sigdump.rb:7:in `block in setup'
/home/game/fluentd/vendor/bundle/gems/fluentd-0.10.45/lib/fluent/engine.rb:275:in `call'
/home/game/fluentd/vendor/bundle/gems/fluentd-0.10.45/lib/fluent/engine.rb:275:in `join'
/home/game/fluentd/vendor/bundle/gems/fluentd-0.10.45/lib/fluent/engine.rb:275:in `block in shutdown'
/home/game/fluentd/vendor/bundle/gems/fluentd-0.10.45/lib/fluent/engine.rb:274:in `each'
/home/game/fluentd/vendor/bundle/gems/fluentd-0.10.45/lib/fluent/engine.rb:274:in `shutdown'
/home/game/fluentd/vendor/bundle/gems/fluentd-0.10.45/lib/fluent/engine.rb:230:in `run'
/home/game/fluentd/vendor/bundle/gems/fluentd-0.10.45/lib/fluent/supervisor.rb:386:in `run_engine'
/home/game/fluentd/vendor/bundle/gems/fluentd-0.10.45/lib/fluent/supervisor.rb:94:in `block in start'
/home/game/fluentd/vendor/bundle/gems/fluentd-0.10.45/lib/fluent/supervisor.rb:198:in `call'
/home/game/fluentd/vendor/bundle/gems/fluentd-0.10.45/lib/fluent/supervisor.rb:198:in `main_process'
/home/game/fluentd/vendor/bundle/gems/fluentd-0.10.45/lib/fluent/supervisor.rb:173:in `block in supervise'
/home/game/fluentd/vendor/bundle/gems/fluentd-0.10.45/lib/fluent/supervisor.rb:172:in `fork'
/home/game/fluentd/vendor/bundle/gems/fluentd-0.10.45/lib/fluent/supervisor.rb:172:in `supervise'
/home/game/fluentd/vendor/bundle/gems/fluentd-0.10.45/lib/fluent/supervisor.rb:87:in `start'
/home/game/fluentd/vendor/bundle/gems/fluentd-0.10.45/lib/fluent/command/fluentd.rb:168:in `<top (required)>'
/home/game/fluentd/vendor/bundle/gems/fluentd-0.10.45/bin/fluentd:6:in `require'
/home/game/fluentd/vendor/bundle/gems/fluentd-0.10.45/bin/fluentd:6:in `<top (required)>'
/home/game/fluentd/server/../vendor/bundle/bin/fluentd:23:in `load'
/home/game/fluentd/server/../vendor/bundle/bin/fluentd:23:in `<main>'
Thread #<Thread:0x007f21b125b870> status=sleep priority=0
/home/game/fluentd/vendor/bundle/gems/fluentd-0.10.45/lib/fluent/output.rb:157:in `sleep'
/home/game/fluentd/vendor/bundle/gems/fluentd-0.10.45/lib/fluent/output.rb:157:in `wait'
/home/game/fluentd/vendor/bundle/gems/fluentd-0.10.45/lib/fluent/output.rb:157:in `cond_wait'
/home/game/fluentd/vendor/bundle/gems/fluentd-0.10.45/lib/fluent/output.rb:141:in `run'
Thread #<Thread:0x007f21b125b5a0> status=sleep priority=0
/home/game/fluentd/vendor/bundle/gems/fluentd-0.10.45/lib/fluent/output.rb:157:in `sleep'
/home/game/fluentd/vendor/bundle/gems/fluentd-0.10.45/lib/fluent/output.rb:157:in `wait'
...
...
Thread #<Thread:0x007f21b03f1b90> status=sleep priority=0
/home/game/fluentd/server/plugin/in_forward.rb:216:in `recvfrom'
/home/game/fluentd/server/plugin/in_forward.rb:216:in `on_readable'
/home/game/fluentd/vendor/bundle/bundler/gems/cool.io-12eae34b3b4a/lib/cool.io/io.rb:170:in `on_readable'
/home/game/fluentd/server/plugin/in_forward.rb:85:in `run_once'
/home/game/fluentd/server/plugin/in_forward.rb:85:in `run'
Thread #<Thread:0x007f21b03f09e8> status=sleep priority=0
/home/game/fluentd/vendor/bundle/gems/fluent-plugin-measure_time-0.1.1/lib/fluent/plugin/in_measure_time.rb:105:in `sleep'
/home/game/fluentd/vendor/bundle/gems/fluent-plugin-measure_time-0.1.1/lib/fluent/plugin/in_measure_time.rb:105:in `run'
Thread #<Thread:0x007f21b03f7388> status=sleep priority=0
/home/game/fluentd/vendor/bundle/gems/fluentd-0.10.45/lib/fluent/engine.rb:185:in `sleep'
/home/game/fluentd/vendor/bundle/gems/fluentd-0.10.45/lib/fluent/engine.rb:185:in `log_event_loop'
Thread #<Thread:0x007f21b03d2b28> status=sleep priority=0
/home/game/fluentd/server/plugin/in_forward.rb:61:in `join'
/home/game/fluentd/server/plugin/in_forward.rb:61:in `shutdown'
/home/game/fluentd/vendor/bundle/gems/fluentd-0.10.45/lib/fluent/engine.rb:268:in `block (2 levels) in shutdown'
Built-in objects:
267,802: TOTAL
86,997: T_STRING
67,499: FREE
43,658: T_ARRAY
35,148: T_DATA
9,236: T_NODE
...
...
String 9,811,313 bytes
Array 2 elements
Hash 1 pairs
@sonots
Copy link
Author

sonots commented Apr 16, 2014

https://github.com/fluent/fluentd/blob/4d4ee04c86b381c109704890a6af9eaf15400e04/lib/fluent/plugin/in_forward.rb#L47

NONBLOCK にしてるのに、なぜ recvfrom_blocking が呼ばれる??

@sonots
Copy link
Author

sonots commented Apr 16, 2014

単体で走らせると recvfrom_blocking は呼ばれない??
https://gist.github.com/sonots/10814032

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment