-
-
Save davidsmalley/a80ffa3126c5b1b01d27 to your computer and use it in GitHub Desktop.
Garbage Collection Bug
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
| $ ps aux | grep Rack | |
| deploy 2742 99.7 2.8 286916 117420 ? Rl 07:58 193:57 Rack: /home/deploy/litmus/current | |
| deploy 15693 99.6 3.1 298468 128828 ? Rl Jun19 881:50 Rack: /home/deploy/litmus/current | |
| deploy 24979 2.3 3.2 301364 131732 ? Sl 10:59 0:19 Rack: /home/deploy/litmus/current | |
| deploy 25426 4.3 3.2 368756 134328 ? Sl 11:03 0:24 Rack: /home/deploy/litmus/current | |
| $ passenger-status | |
| ----------- General information ----------- | |
| max = 52 | |
| count = 4 | |
| active = 2 | |
| inactive = 2 | |
| Waiting on global queue: 0 | |
| ----------- Application groups ----------- | |
| /home/deploy/litmus/current: | |
| App root: /home/deploy/litmus/current | |
| * PID: 26593 Sessions: 0 Processed: 176 Uptime: 4m 49s | |
| * PID: 24979 Sessions: 0 Processed: 288 Uptime: 20m 23s | |
| * PID: 15693 Sessions: 1 Processed: 115 Uptime: 14h 51m 30s | |
| * PID: 2742 Sessions: 1 Processed: 10 Uptime: 3h 20m 55s | |
| ^^ Two processes running the longest have the lowest number of processed requests - and also have active (presumably stuck) sessions | |
| Inspecting further... | |
| # gdb ruby | |
| <snip> | |
| (gdb) attach 2742 | |
| Attaching to program: /usr/bin/ruby, process 2742 | |
| <snip> | |
| (gdb) bt | |
| #0 0x00007fd2874bc1d5 in find_entry (key=94758960, hash_val=94758960, bin_pos=<optimized out>, table=<optimized out>) at st.c:451 | |
| #1 0x00007fd2874bcac6 in st_lookup (table=0x165e158, key=94758960, value=0x7fffa5dec218) at st.c:505 | |
| #2 0x00007fd2874ec800 in rb_mark_generic_ivar (obj=<optimized out>) at variable.c:910 | |
| #3 0x00007fd287429f2f in gc_mark_children (objspace=0x1566990, ptr=94758960, lev=3) at gc.c:1868 | |
| #4 0x00007fd28742a423 in gc_mark_children (objspace=0x1566990, ptr=<optimized out>, lev=2) at gc.c:2063 | |
| #5 0x00007fd28742a3ab in gc_mark_children (objspace=0x1566990, ptr=<optimized out>, lev=1) at gc.c:2030 | |
| #6 0x00007fd28742a712 in mark_locations_array (objspace=0x1566990, x=0x63fe6a0, n=<optimized out>) at gc.c:1603 | |
| #7 0x00007fd2875013ee in env_mark (ptr=0x63fe960) at vm.c:247 | |
| #8 0x00007fd287429f82 in gc_mark_children (objspace=0x1566990, ptr=95505920, lev=1) at gc.c:2054 | |
| #9 0x00007fd28742a712 in mark_locations_array (objspace=0x1566990, x=0x63fe738, n=<optimized out>) at gc.c:1603 | |
| #10 0x00007fd2875013ee in env_mark (ptr=0x63fe6d0) at vm.c:247 | |
| #11 0x00007fd287429f82 in gc_mark_children (objspace=0x1566990, ptr=95505760, lev=1) at gc.c:2054 | |
| #12 0x00007fd28741e325 in proc_mark (ptr=0x63fe7a0) at proc.c:54 | |
| #13 0x00007fd287429f82 in gc_mark_children (objspace=0x1566990, ptr=95505520, lev=11) at gc.c:2054 | |
| #14 0x00007fd28742a86a in mark_method_entry_i (key=<optimized out>, me=<optimized out>, data=<optimized out>) at gc.c:1732 | |
| #15 0x00007fd2874be20e in st_foreach (table=0x6633bc8, func=0x7fd28742a850 <mark_method_entry_i>, arg=140735976228208) at st.c:1181 | |
| #16 0x00007fd28742a24c in mark_m_tbl (lev=10, tbl=<optimized out>, objspace=0x1566990) at gc.c:1743 | |
| #17 gc_mark_children (objspace=0x1566990, ptr=63894080, lev=10) at gc.c:2014 | |
| #18 0x00007fd287429dbf in gc_mark_children (objspace=0x1566990, ptr=63894120, lev=9) at gc.c:2009 | |
| #19 0x00007fd28742a3ab in gc_mark_children (objspace=0x1566990, ptr=<optimized out>, lev=8) at gc.c:2030 | |
| #20 0x00007fd28742a8d0 in mark_keyvalue (key=<optimized out>, value=36477040, data=<optimized out>) at gc.c:1679 | |
| #21 0x00007fd2874be20e in st_foreach (table=0x2843ec8, func=0x7fd28742a8a0 <mark_keyvalue>, arg=140735976228608) at st.c:1181 | |
| #22 0x00007fd287429fd4 in mark_hash (lev=7, tbl=<optimized out>, objspace=0x1566990) at gc.c:1690 | |
| #23 gc_mark_children (objspace=0x1566990, ptr=36432280, lev=7) at gc.c:2036 | |
| #24 0x00007fd28742a902 in mark_entry (key=<optimized out>, value=<optimized out>, data=<optimized out>) at gc.c:1636 | |
| #25 0x00007fd2874be289 in st_foreach (table=0x2843e68, func=0x7fd28742a8f0 <mark_entry>, arg=140735976228784) at st.c:1153 | |
| #26 0x00007fd287429710 in mark_tbl (lev=<optimized out>, tbl=<optimized out>, objspace=<optimized out>) at gc.c:1647 | |
| #27 mark_tbl (objspace=<optimized out>, tbl=<optimized out>, lev=<optimized out>) at gc.c:1641 | |
| #28 0x00007fd28742a268 in gc_mark_children (objspace=0x1566990, ptr=36432400, lev=6) at gc.c:2016 | |
| #29 0x00007fd287429dbf in gc_mark_children (objspace=0x1566990, ptr=36410760, lev=5) at gc.c:2009 | |
| #30 0x00007fd287429dbf in gc_mark_children (objspace=0x1566990, ptr=35578840, lev=4) at gc.c:2009 | |
| #31 0x00007fd28742a896 in mark_const_entry_i (key=<optimized out>, ce=<optimized out>, data=<optimized out>) at gc.c:1766 | |
| #32 0x00007fd2874be20e in st_foreach (table=0x2813748, func=0x7fd28742a880 <mark_const_entry_i>, arg=140735976229216) at st.c:1181 | |
| #33 0x00007fd28742a290 in mark_const_tbl (lev=3, tbl=<optimized out>, objspace=0x1566990) at gc.c:1777 | |
| #34 gc_mark_children (objspace=0x1566990, ptr=35536480, lev=3) at gc.c:2017 | |
| #35 0x00007fd28742a896 in mark_const_entry_i (key=<optimized out>, ce=<optimized out>, data=<optimized out>) at gc.c:1766 | |
| #36 0x00007fd2874be20e in st_foreach (table=0x2429dc8, func=0x7fd28742a880 <mark_const_entry_i>, arg=140735976229408) at st.c:1181 | |
| #37 0x00007fd28742a290 in mark_const_tbl (lev=2, tbl=<optimized out>, objspace=0x1566990) at gc.c:1777 | |
| #38 gc_mark_children (objspace=0x1566990, ptr=26531600, lev=2) at gc.c:2017 | |
| ^^ Stuck in Garbage collection - then the other process | |
| (gdb) attach 15693 | |
| (gdb) bt | |
| #0 st_numcmp (x=124727520, y=481) at st.c:1713 | |
| #1 0x00007fd2874bd748 in st_delete (table=0x165e158, key=0x7fffa5df13b0, value=0x7fffa5df13b8) at st.c:894 | |
| #2 0x00007fd2874ec871 in rb_free_generic_ivar (obj=<optimized out>) at variable.c:945 | |
| #3 0x00007fd28742ba85 in obj_free (obj=124727520, objspace=<optimized out>) at gc.c:2486 | |
| #4 slot_sweep (objspace=0x1566990, sweep_slot=0x6e3a520) at gc.c:2227 | |
| #5 0x00007fd28742c7ef in gc_sweep (objspace=0x1566990) at gc.c:2431 | |
| #6 garbage_collect (objspace=0x1566990) at gc.c:2716 | |
| #7 0x00007fd28742cac1 in vm_malloc_prepare (size=16424, objspace=0x1566990) at gc.c:813 | |
| #8 vm_xcalloc (elsize=<optimized out>, count=<optimized out>, objspace=0x1566990) at gc.c:939 | |
| #9 ruby_xcalloc (n=<optimized out>, size=<optimized out>) at gc.c:948 | |
| #10 0x00007fd2874bc2ae in st_alloc_bins (size=2053) at st.c:101 | |
| #11 st_realloc_bins (oldsize=<optimized out>, newsize=<optimized out>, bins=<optimized out>) at st.c:116 | |
| #12 rehash (table=0x165e158) at st.c:778 | |
| #13 0x00007fd2874bd440 in add_direct (bin_pos=<optimized out>, hash_val=135069160, value=131213336, key=135069160, table=0x165e158) at st.c:576 | |
| #14 st_add_direct (table=0x165e158, key=135069160, value=131213336) at st.c:768 | |
| #15 0x00007fd2874ecb1b in generic_ivar_set (val=<optimized out>, id=<optimized out>, obj=<optimized out>) at variable.c:863 | |
| #16 rb_ivar_set (obj=135069160, id=66169, val=2) at variable.c:1105 | |
| #17 0x00007fd2875071f6 in vm_setivar (ic=0x22f6530, val=2, id=66169, obj=135069160) at vm_insnhelper.c:1363 | |
| #18 vm_exec_core (th=<optimized out>, initial=<optimized out>) at insns.def:172 | |
| #19 0x00007fd28750b59d in vm_exec (th=0x1566610) at vm.c:1220 | |
| #20 0x00007fd28750c7cd in vm_call0 (th=0x1566610, recv=<optimized out>, id=456, argc=1, argv=0x7fd2878e7d60, me=0x25e4a30) at vm_eval.c:66 | |
| #21 0x00007fd28745be00 in rb_class_new_instance (argc=1, argv=0x7fd2878e7d60, klass=<optimized out>) at object.c:1636 | |
| #22 0x00007fd28750ed41 in vm_call_cfunc (me=0x15694f0, blockptr=0x0, recv=<optimized out>, num=1, reg_cfp=0x7fd2879e24f0, th=<optimized out>) at vm_insnhelper.c:404 | |
| #23 vm_call_method (th=<optimized out>, cfp=0x7fd2879e24f0, num=<optimized out>, blockptr=0x0, flag=<optimized out>, id=<optimized out>, me=0x15694f0, recv=28960640) at vm_insnhelper.c:534 | |
| #24 0x00007fd287505b52 in vm_exec_core (th=<optimized out>, initial=<optimized out>) at insns.def:1015 | |
| #25 0x00007fd28750b59d in vm_exec (th=0x1566610) at vm.c:1220 | |
| #26 0x00007fd28751130e in invoke_block_from_c (cref=0x0, blockptr=0x0, argv=0x7fffa5df1a88, argc=1, self=150068240, block=0x7fd2879e2780, th=0x1566610) at vm.c:624 | |
| #27 vm_yield (th=0x1566610, argv=0x7fffa5df1a88, argc=1) at vm.c:654 | |
| #28 rb_yield_0 (argv=0x7fffa5df1a88, argc=1) at vm_eval.c:760 | |
| #29 rb_yield (val=149608840) at vm_eval.c:770 | |
| #30 0x00007fd2873e8892 in rb_ary_each (array=136841760) at array.c:1478 | |
| #31 0x00007fd28750ed41 in vm_call_cfunc (me=0x1607fa0, blockptr=0x7fd2879e2780, recv=<optimized out>, num=0, reg_cfp=0x7fd2879e2758, th=<optimized out>) at vm_insnhelper.c:404 | |
| #32 vm_call_method (th=<optimized out>, cfp=0x7fd2879e2758, num=<optimized out>, blockptr=0x7fd2879e2780, flag=<optimized out>, id=<optimized out>, me=0x1607fa0, recv=136841760) at vm_insnhelper.c:534 | |
| #33 0x00007fd287505b52 in vm_exec_core (th=<optimized out>, initial=<optimized out>) at insns.def:1015 | |
| #34 0x00007fd28750b59d in vm_exec (th=0x1566610) at vm.c:1220 | |
| #35 0x00007fd2875118e6 in invoke_block_from_c (cref=0x0, blockptr=0x0, argv=0x7fffa5df1da0, argc=<optimized out>, self=150068240, block=<optimized out>, th=0x1566610) at vm.c:624 | |
| #36 vm_yield (th=0x1566610, argv=0x7fffa5df1da0, argc=<optimized out>) at vm.c:654 | |
| #37 rb_yield_0 (argv=0x7fffa5df1da0, argc=<optimized out>) at vm_eval.c:760 | |
| #38 rb_yield_values (n=<optimized out>) at vm_eval.c:792 | |
| ^^ Stuck somewhere else - but still garbage collection? (frame #6 is quite high up and is definitely doing GC) |
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment