[BUG] Segmation fault in combination of heavy socket I/O and multi-threading

ruby-talk
1

This is one bug(Or perhaps even a set of bugs) I ran into more then once
during the development of Radical, it is often solveable by forcing only
one thread to run the inducer code concurrently, i.e. using
Thread.critical or Mutex.

I had a problem reproducing the matter in simple TCP/IP snippets,
however, I have managed reproducing it using a heavly stripped version
of Radical, using pure ruby code(no extensions).

The initial way to reproduce the bug was using siege HTTP benchmarking
tool available here:
http://www.joedog.org/siege/
(Or if you are using debian/gentoo you may use apt-get/emerge siege)

Then on one console:

bzip2 -dc ruby-bug.tar.bz2|tar xv

cd httpserve

gdb ruby

ruby ./radical.rb
Radical =>

On the second console:
siege -b -c 100 -t 120S -u http://localhost:4000/blender

Initially things will go right, but the response times will slowly rise,
and after a while(less then a minute mostly) the interepter will crash
in some manner.
NOTE: In one occaction the interepter hanged and started mallocing like
mad until it was killed by the kernel, so when performing this test
please be aware the stability of your system might be in risk.

This is for instance one backtrace I was able to produce:
Radical=>
Program received signal SIGSEGV, Segmentation fault.
0x4103a618 in siglongjmp () from /lib/libc.so.6
(gdb) bt
#0 0x4103a618 in siglongjmp () from /lib/libc.so.6
#1 0x41177b10 in rb_thread_restore_context (th=0x4, exit=1) at eval.c:7567
#2 0x41177927 in stack_extend (th=0x0, exit=1074284600) at eval.c:7509
#3 0x00001039 in ?? ()
(gdb)

Another one:
Radical=>
Program received signal SIGSEGV, Segmentation fault.
0x4117799f in rb_thread_restore_context (th=0x87f9878, exit=1) at
eval.c:7533
7533 eval.c: No such file or directory.
in eval.c
(gdb) bt
#0 0x4117799f in rb_thread_restore_context (th=0x87f9878, exit=1) at
eval.c:7533
#1 0x41177927 in stack_extend (th=0x850da58, exit=1) at eval.c:7509
#2 0x41177b10 in rb_thread_restore_context (th=0x850da50, exit=1) at
eval.c:7567
#3 0x41177927 in stack_extend (th=0x411c60c8, exit=43) at eval.c:7509

And number three:
Radical=>
Program received signal SIGSEGV, Segmentation fault.
0x4117f2fb in mark_locations_array (x=0xc0000000, n=-1073796479) at gc.c:353
353 gc.c: No such file or directory.
in gc.c
(gdb) bt
#0 0x4117f2fb in mark_locations_array (x=0xc0000000, n=-1073796479) at
gc.c:353
#1 0x4118007a in rb_gc_mark_frame (frame=0x40cc2744) at gc.c:958
#2 0x41177375 in thread_mark (th=0x80b1ea0) at eval.c:7342
#3 0x4117f908 in rb_gc_mark (ptr=0) at gc.c:676
#4 0x4117f3eb in mark_entry (key=12202, value=1074215600) at gc.c:446
#5 0x411b5739 in st_foreach (table=0x80b1ab0, func=0x4117f3d0
<mark_entry>, arg=0x0) at st.c:488
#6 0x4117f41c in rb_mark_tbl (tbl=0xc0000000) at gc.c:455
#7 0x4117f86a in rb_gc_mark (ptr=1092089970) at gc.c:650
#8 0x4117f8a1 in rb_gc_mark (ptr=1092089970) at gc.c:659
#9 0x4117f3eb in mark_entry (key=12250, value=1074215900) at gc.c:446
#10 0x411b5739 in st_foreach (table=0x80a6198, func=0x4117f3d0
<mark_entry>, arg=0x0) at st.c:488
#11 0x4117f41c in rb_mark_tbl (tbl=0xc0000000) at gc.c:455
#12 0x4117f86a in rb_gc_mark (ptr=1092089970) at gc.c:650
#13 0x4117f335 in mark_locations_array (x=0xbfff911c, n=1) at gc.c:419
#14 0x4118007a in rb_gc_mark_frame (frame=0xbfff9230) at gc.c:958
#15 0x41180200 in rb_gc () at gc.c:1034
#16 0x4117ec65 in ruby_xmalloc (size=16) at gc.c:94
#17 0x411b4f87 in st_init_table_with_size (type=0x4117f872, size=11) at
st.c:163
#18 0x411b4fcd in st_init_table (type=0x411d9f54) at st.c:176
#19 0x411b4ff3 in st_init_numtable () at st.c:182
#20 0x411c1c0d in rb_ivar_set (obj=1074294420, id=12178, val=1074216020)
at variable.c:958
#21 0x4116ba24 in rb_eval (self=1074294420, n=0x4117f872) at eval.c:2745
#22 0x4116a65a in rb_eval (self=1074294420, n=0x4117f872) at eval.c:2053
#23 0x41170c4e in rb_call0 (klass=1074217380, recv=1074294420, id=2865,
argc=0, argv=0xbfff9568,
body=0x4007836c, nosuper=0) at eval.c:4547
#24 0x4117113c in rb_call (klass=1074217380, recv=1074294420, mid=2865,
argc=2, argv=0xbfff9560,
scope=1) at eval.c:4640
#25 0x4117148d in rb_funcall2 (recv=3221225472, mid=2865, argc=2,
argv=0xbfff9560) at ruby.h:574
#26 0x411737e1 in rb_obj_call_init (obj=1074294420, argc=2,
argv=0xbfff9560) at eval.c:5726
#27 0x41173832 in rb_class_new_instance (argc=2, argv=0xbfff9560,
klass=3221197592) at eval.c:5742
#28 0x4117058d in call_cfunc (func=0x411737f0 <rb_class_new_instance>,
recv=1074217380,
len=-1073741824, argc=2, argv=0x0) at eval.c:4276
#29 0x41170929 in rb_call0 (klass=1073999096, recv=1074217380, id=3177,
argc=2, argv=0xbfff9560,
body=0x4003dde4, nosuper=1) at eval.c:4416
#30 0x4117113c in rb_call (klass=1073999096, recv=1074217380, mid=3177,
argc=2, argv=0xbfff9560,
scope=0) at eval.c:4640
#31 0x4116c012 in rb_eval (self=1074216020, n=0xbfff9318) at eval.c:2556
#32 0x4116c0eb in rb_eval (self=1074216020, n=0xbfff9318) at ruby.h:579
#33 0x4116a65a in rb_eval (self=1074216020, n=0xbfff9318) at eval.c:2053
#34 0x4116a65a in rb_eval (self=1074216020, n=0xbfff9318) at eval.c:2053
#35 0x4116aedb in rb_eval (self=1074216020, n=0xbfff9318) at eval.c:2237
#36 0x4116eccd in rb_yield_0 (val=6, self=1074216020, klass=0, acheck=2)
at eval.c:3644
#37 0x41179a13 in rb_thread_yield (arg=1074215380, th=0x80b8450) at
eval.c:8592
#38 0x411798f1 in rb_thread_start_0 (fn=0x411799dc <rb_thread_yield>,
arg=0x400739d4,
th_arg=0xbfff9318) at eval.c:8525
#39 0x41179ac0 in rb_thread_initialize (thread=1074215400,
args=1074215380) at eval.c:8621
#40 0x4117058d in call_cfunc (func=0x41179a88 <rb_thread_initialize>,
recv=1074215400,
len=-1073741824, argc=0, argv=0x0) at eval.c:4276
#41 0x41170929 in rb_call0 (klass=1073978296, recv=1074215400, id=2865,
argc=0, argv=0x0,
body=0x40039b68, nosuper=1) at eval.c:4416
#42 0x4117113c in rb_call (klass=1073978296, recv=1074215400, mid=2865,
argc=0, argv=0x0, scope=1)
at eval.c:4640
#43 0x4117148d in rb_funcall2 (recv=3221225472, mid=2865, argc=0,
argv=0x0) at ruby.h:574
#44 0x411737e1 in rb_obj_call_init (obj=1074215400, argc=0, argv=0x0) at
eval.c:5726
#45 0x41179a4c in rb_thread_s_new (argc=0, argv=0x0, klass=1073978296)
at eval.c:8605
#46 0x4117058d in call_cfunc (func=0x41179a18 <rb_thread_s_new>,
recv=1073978296,
len=-1073741824, argc=0, argv=0x0) at eval.c:4276
#47 0x41170929 in rb_call0 (klass=1073978276, recv=1073978296, id=3177,
argc=0, argv=0x0,
body=0x40039b90, nosuper=1) at eval.c:4416
#48 0x4117113c in rb_call (klass=1073978276, recv=1073978296, mid=3177,
argc=0, argv=0x0, scope=0)
at eval.c:4640
#49 0x4116c012 in rb_eval (self=1074216020, n=0xbfffb668) at eval.c:2556
#50 0x4116b3cd in rb_eval (self=1074216020, n=0xbfffb668) at eval.c:2304
#51 0x4116ba0c in rb_eval (self=1074216020, n=0xbfffb668) at eval.c:2744
#52 0x4116a65a in rb_eval (self=1074216020, n=0xbfffb668) at eval.c:2053
#53 0x41170c4e in rb_call0 (klass=1074217300, recv=1074216020, id=5633,
argc=0, argv=0xbfffd094,
body=0x40075f90, nosuper=0) at eval.c:4547
#54 0x4117113c in rb_call (klass=1074217300, recv=1074216020, mid=5633,
argc=1, argv=0xbfffd090,
scope=1) at eval.c:4640
#55 0x4116c012 in rb_eval (self=1074216020, n=0xbfffb668) at eval.c:2556
#56 0x41170c4e in rb_call0 (klass=1074216180, recv=1074216020, id=2865,
argc=0, argv=0xbfffda98,
body=0x4007aff4, nosuper=0) at eval.c:4547
#57 0x4117113c in rb_call (klass=1074216180, recv=1074216020, mid=2865,
argc=6, argv=0xbfffda80,
scope=1) at eval.c:4640
#58 0x4117148d in rb_funcall2 (recv=3221225472, mid=2865, argc=6,
argv=0xbfffda80) at ruby.h:574
#59 0x411737e1 in rb_obj_call_init (obj=1074216020, argc=6,
argv=0xbfffda80) at eval.c:5726
#60 0x41173832 in rb_class_new_instance (argc=6, argv=0xbfffda80,
klass=3221215288) at eval.c:5742
#61 0x4117058d in call_cfunc (func=0x411737f0 <rb_class_new_instance>,
recv=1074216180,
len=-1073741824, argc=6, argv=0x0) at eval.c:4276
#62 0x41170929 in rb_call0 (klass=1073999096, recv=1074216180, id=3177,
argc=6, argv=0xbfffda80,
body=0x4003dde4, nosuper=1) at eval.c:4416
#63 0x4117113c in rb_call (klass=1073999096, recv=1074216180, mid=3177,
argc=6, argv=0xbfffda80,
scope=0) at eval.c:4640
#64 0x4116c012 in rb_eval (self=1073994976, n=0xbfffd838) at eval.c:2556
#65 0x4116c0eb in rb_eval (self=1073994976, n=0xbfffd838) at ruby.h:579
#66 0x4116eccd in rb_yield_0 (val=1074247100, self=1073994976, klass=0,
acheck=0) at eval.c:3644
#67 0x4116f004 in rb_yield (val=1074247100) at eval.c:3732
#68 0x4115baa3 in rb_ary_each (ary=1074247200) at array.c:630
#69 0x4117058d in call_cfunc (func=0x4115ba68 <rb_ary_each>,
recv=1074247200, len=-1073741824,
argc=0, argv=0x0) at eval.c:4276
#70 0x41170929 in rb_call0 (klass=1073970976, recv=1074247200, id=3577,
argc=0, argv=0x0,
body=0x40037b4c, nosuper=1) at eval.c:4416
#71 0x4117113c in rb_call (klass=1073970976, recv=1074247200, mid=3577,
argc=0, argv=0x0, scope=0)
at eval.c:4640
#72 0x4116b283 in rb_eval (self=1073994976, n=0xbfffd838) at ruby.h:574
#73 0x4116a65a in rb_eval (self=1073994976, n=0xbfffd838) at eval.c:2053
#74 0x41168908 in ruby_run () at eval.c:1230
#75 0x080485b4 in main ()
#76 0x410299f1 in __libc_start_main () from /lib/libc.so.6

All of these gdb dumps are from ruby 1.6.8…

As an attempt to produce pure-ruby bug reproduction enviroment, I have
written a simple http request flooder to fit the role of siege:
require ‘net/http’
x=Net::HTTP.new ‘localhost’,4000
1.upto 15 do
Thread.new do
while 1
x.get ‘/blender’
end
end
end
while 1
sleep 1
end

This code is also included in the tar/gz. however, running it may also
cause the interepter to chock:
Starting program: /usr/bin/ruby fetcher.rb

Program received signal SIGPIPE, Broken pipe.
0x410cb934 in write () from /lib/libc.so.6
(gdb)
#0 0x410cb934 in write () from /lib/libc.so.6
#1 0x41120ba0 in sys_sigabbrev () from /lib/libc.so.6
#2 0x41077161 in _IO_do_write () from /lib/libc.so.6
#3 0x410770c9 in _IO_do_write () from /lib/libc.so.6
#4 0x41077a02 in _IO_file_sync () from /lib/libc.so.6
#5 0x4106e4db in fflush () from /lib/libc.so.6
#6 0x41183e70 in io_fflush (f=0x80b2908, path=0x0) at io.c:216
#7 0x41183ff7 in io_write (io=134948688, str=1074343880) at io.c:262
#8 0x4117058d in call_cfunc (func=0x41183e8c <io_write>,
recv=1074355840, len=22, argc=1,
argv=0x400a3000) at eval.c:4276
#9 0x41170929 in rb_call0 (klass=1073961256, recv=1074355840, id=6713,
argc=1, argv=0xbfff2a00,
body=0x400354a0, nosuper=1) at eval.c:4416
#10 0x4117113c in rb_call (klass=1073961256, recv=1074355840, mid=6713,
argc=1, argv=0xbfff2a00,
scope=0) at eval.c:4640
#11 0x4116c012 in rb_eval (self=1074357220, n=0xffffffe0) at eval.c:2556
#12 0x4116b95b in rb_eval (self=1074357220, n=0xffffffe0) at eval.c:2724
#13 0x4116c0eb in rb_eval (self=1074357220, n=0xffffffe0) at ruby.h:579
#14 0x4116ba0c in rb_eval (self=1074357220, n=0xffffffe0) at eval.c:2744
#15 0x4116a65a in rb_eval (self=1074357220, n=0xffffffe0) at eval.c:2053
#16 0x41170c4e in rb_call0 (klass=1074372060, recv=1074357220, id=11585,
argc=0, argv=0xbfff4784,
body=0x4009d734, nosuper=0) at eval.c:4547
#17 0x4117113c in rb_call (klass=1074372060, recv=1074357220, mid=11585,
argc=1, argv=0xbfff4780,
scope=1) at eval.c:4640
#18 0x4116c012 in rb_eval (self=1074357220, n=0xffffffe0) at eval.c:2556
#19 0x4116eccd in rb_yield_0 (val=4, self=1074357220, klass=0, acheck=0)
at eval.c:3644
#20 0x4116c80f in rb_eval (self=1074357220, n=0xffffffe0) at eval.c:2386
#21 0x4116a65a in rb_eval (self=1074357220, n=0xffffffe0) at eval.c:2053
#22 0x41170c4e in rb_call0 (klass=1074372060, recv=1074357220, id=11577,
argc=0, argv=0x0,
body=0x4009db80, nosuper=0) at eval.c:4547
#23 0x4117113c in rb_call (klass=1074372060, recv=1074357220, mid=11577,
argc=0, argv=0x0,
scope=1) at eval.c:4640
#24 0x4116c012 in rb_eval (self=1074357220, n=0xffffffe0) at eval.c:2556
#25 0x4116b3cd in rb_eval (self=1074357220, n=0xffffffe0) at eval.c:2304
#26 0x41170c4e in rb_call0 (klass=1074372060, recv=1074357220, id=10521,
argc=0, argv=0xbfff6814,
body=0x400a0768, nosuper=0) at eval.c:4547
#27 0x4117113c in rb_call (klass=1074372060, recv=1074357220, mid=10521,
argc=1, argv=0xbfff6810,
scope=0) at eval.c:4640
#28 0x4116c012 in rb_eval (self=1074347740, n=0xffffffe0) at eval.c:2556
#29 0x4116eccd in rb_yield_0 (val=1074344300, self=1074347740, klass=0,
acheck=0) at eval.c:3644
#30 0x4116c80f in rb_eval (self=1074347740, n=0xffffffe0) at eval.c:2386
#31 0x4116eccd in rb_yield_0 (val=1074346060, self=1074347740, klass=0,
acheck=0) at eval.c:3644
#32 0x4116f004 in rb_yield (val=1074346060) at eval.c:3732
#33 0x41181bea in each_pair_i (key=4294967264, value=1074347520) at
hash.c:591
#34 0x411810ac in rb_hash_foreach_iter (key=22, value=1074347520,
arg=0xbfff77c0) at hash.c:131
#35 0x411b5739 in st_foreach (table=0x80a1920, func=0x41181074
<rb_hash_foreach_iter>,
arg=0xbfff77c0 " >\t@¼\e\030A") at st.c:488
#36 0x4118110c in rb_hash_foreach_call (arg=0x0) at hash.c:142
#37 0x4116feb1 in rb_ensure (b_proc=0x411810e4 <rb_hash_foreach_call>,
data1=3221190592,
e_proc=0x41181118 <rb_hash_foreach_ensure>, data2=1074347680) at
eval.c:4064
#38 0x411811b4 in rb_hash_foreach (hash=22, func=0, farg=0x0) at hash.c:173
#39 0x41181c18 in rb_hash_each_pair (hash=1074347680) at hash.c:599
#40 0x4117058d in call_cfunc (func=0x41181bf4 <rb_hash_each_pair>,
recv=1074347680, len=22,
argc=0, argv=0x400a3000) at eval.c:4276
#41 0x41170929 in rb_call0 (klass=1073968196, recv=1074347680, id=3577,
argc=0, argv=0x0,
body=0x40037098, nosuper=1) at eval.c:4416
#42 0x4117113c in rb_call (klass=1073968196, recv=1074347680, mid=3577,
argc=0, argv=0x0, scope=0)
at eval.c:4640
#43 0x4116c012 in rb_eval (self=1074347740, n=0x0) at eval.c:2556
#44 0x4116b3cd in rb_eval (self=1074347740, n=0x0) at eval.c:2304
#45 0x41170c4e in rb_call0 (klass=1074362920, recv=1074347740, id=10241,
argc=0, argv=0x0,
body=0x400250b4, nosuper=0) at eval.c:4547
#46 0x4117113c in rb_call (klass=1074362920, recv=1074347740, mid=10241,
argc=0, argv=0x0,
scope=1) at eval.c:4640
#47 0x4116c012 in rb_eval (self=1074347740, n=0x0) at eval.c:2556
#48 0x4116b3cd in rb_eval (self=1074347740, n=0x0) at eval.c:2304
#49 0x4116a65a in rb_eval (self=1074347740, n=0x0) at eval.c:2053
#50 0x41170c4e in rb_call0 (klass=1074363880, recv=1074347740, id=9201,
argc=0, argv=0xbfff993c,
body=0x4002026c, nosuper=0) at eval.c:4547
#51 0x4117113c in rb_call (klass=1074363880, recv=1074347740, mid=9201,
argc=3, argv=0xbfff9930,
scope=1) at eval.c:4640
#52 0x4116c012 in rb_eval (self=1074347740, n=0x0) at eval.c:2556
#53 0x41170c4e in rb_call0 (klass=1074363880, recv=1074347740, id=8249,
argc=0, argv=0xbfffa2f4,
body=0x40020e88, nosuper=0) at eval.c:4547
#54 0x4117113c in rb_call (klass=1074363880, recv=1074347740, mid=8249,
argc=4, argv=0xbfffa2e4,
scope=1) at eval.c:4640
#55 0x41171319 in rb_f_send (argc=4, argv=0xbfffa2e4, recv=1074347740)
at ruby.h:574
#56 0x4117058d in call_cfunc (func=0x41171290 <rb_f_send>,
recv=1074347740, len=22, argc=5,
argv=0x400a3000) at eval.c:4276
#57 0x41170929 in rb_call0 (klass=1073998996, recv=1074347740, id=3641,
argc=5, argv=0xbfffa2e0,
body=0x4003d178, nosuper=1) at eval.c:4416
#58 0x4117113c in rb_call (klass=1073998996, recv=1074347740, mid=3641,
argc=5, argv=0xbfffa2e0,
scope=0) at eval.c:4640
#59 0x4116c012 in rb_eval (self=1074361880, n=0x0) at eval.c:2556
#60 0x4116a65a in rb_eval (self=1074361880, n=0x0) at eval.c:2053
#61 0x41170c4e in rb_call0 (klass=1074369700, recv=1074361880, id=9201,
argc=0, argv=0xbfffafe4,
body=0x40029bdc, nosuper=0) at eval.c:4547
#62 0x4117113c in rb_call (klass=1074369700, recv=1074361880, mid=9201,
argc=1, argv=0xbfffafe0,
scope=1) at eval.c:4640
#63 0x4116c012 in rb_eval (self=1074361880, n=0x0) at eval.c:2556
#64 0x4116b3cd in rb_eval (self=1074361880, n=0x0) at eval.c:2304
#65 0x4116a65a in rb_eval (self=1074361880, n=0x0) at eval.c:2053
#66 0x41170c4e in rb_call0 (klass=1074369700, recv=1074361880, id=9041,
argc=0, argv=0xbfffc254,
body=0x4002b9a0, nosuper=0) at eval.c:4547
#67 0x4117113c in rb_call (klass=1074369700, recv=1074361880, mid=9041,
argc=1, argv=0xbfffc250,
scope=0) at eval.c:4640
#68 0x4116c012 in rb_eval (self=1073994976, n=0x0) at eval.c:2556
#69 0x4116aedb in rb_eval (self=1073994976, n=0x0) at eval.c:2237
#70 0x4116eccd in rb_yield_0 (val=6, self=1073994976, klass=0, acheck=2)
at eval.c:3644
#71 0x41179a13 in rb_thread_yield (arg=1074349820, th=0x80a1540) at
eval.c:8592
#72 0x411798f1 in rb_thread_start_0 (fn=0x411799dc <rb_thread_yield>,
arg=0x400946fc, th_arg=0x0)
at eval.c:8525
#73 0x41179ac0 in rb_thread_initialize (thread=1074349880,
args=1074349820) at eval.c:8621
#74 0x4117058d in call_cfunc (func=0x41179a88 <rb_thread_initialize>,
recv=1074349880, len=22,
argc=0, argv=0x400a3000) at eval.c:4276
#75 0x41170929 in rb_call0 (klass=1073978296, recv=1074349880, id=2865,
argc=0, argv=0x0,
body=0x40039b68, nosuper=1) at eval.c:4416
#76 0x4117113c in rb_call (klass=1073978296, recv=1074349880, mid=2865,
argc=0, argv=0x0, scope=1)
at eval.c:4640
#77 0x4117148d in rb_funcall2 (recv=22, mid=2865, argc=0, argv=0x0) at
ruby.h:574
#78 0x411737e1 in rb_obj_call_init (obj=1074349880, argc=0, argv=0x0) at
eval.c:5726
#79 0x41179a4c in rb_thread_s_new (argc=0, argv=0x0, klass=1073978296)
at eval.c:8605
#80 0x4117058d in call_cfunc (func=0x41179a18 <rb_thread_s_new>,
recv=1073978296, len=22, argc=0,
argv=0x400a3000) at eval.c:4276
#81 0x41170929 in rb_call0 (klass=1073978276, recv=1073978296, id=3177,
argc=0, argv=0x0,
body=0x40039b90, nosuper=1) at eval.c:4416
#82 0x4117113c in rb_call (klass=1073978276, recv=1073978296, mid=3177,
argc=0, argv=0x0, scope=0)
at eval.c:4640
#83 0x4116c012 in rb_eval (self=1073994976, n=0xbfffd2c8) at eval.c:2556
#84 0x4116b3cd in rb_eval (self=1073994976, n=0xbfffd2c8) at eval.c:2304
#85 0x4116eccd in rb_yield_0 (val=21, self=1073994976, klass=0,
acheck=0) at eval.c:3644
body=0x40039b68, nosuper=1) at eval.c:4416
#76 0x4117113c in rb_call (klass=1073978296, recv=1074349880, mid=2865,
argc=0, argv=0x0, scope=1)
at eval.c:4640
#77 0x4117148d in rb_funcall2 (recv=22, mid=2865, argc=0, argv=0x0) at
ruby.h:574
#78 0x411737e1 in rb_obj_call_init (obj=1074349880, argc=0, argv=0x0) at
eval.c:5726
#79 0x41179a4c in rb_thread_s_new (argc=0, argv=0x0, klass=1073978296)
at eval.c:8605
#80 0x4117058d in call_cfunc (func=0x41179a18 <rb_thread_s_new>,
recv=1073978296, len=22, argc=0,
argv=0x400a3000) at eval.c:4276
#81 0x41170929 in rb_call0 (klass=1073978276, recv=1073978296, id=3177,
argc=0, argv=0x0,
body=0x40039b90, nosuper=1) at eval.c:4416
#82 0x4117113c in rb_call (klass=1073978276, recv=1073978296, mid=3177,
argc=0, argv=0x0, scope=0)
at eval.c:4640
#83 0x4116c012 in rb_eval (self=1073994976, n=0xbfffd2c8) at eval.c:2556
#84 0x4116b3cd in rb_eval (self=1073994976, n=0xbfffd2c8) at eval.c:2304
#85 0x4116eccd in rb_yield_0 (val=21, self=1073994976, klass=0,
acheck=0) at eval.c:3644
—Type to continue, or q to quit—
#86 0x4116f004 in rb_yield (val=21) at eval.c:3732
#87 0x4118fb5c in fix_upto (from=3, to=3221213896) at numeric.c:1468
#88 0x4117058d in call_cfunc (func=0x4118fb0c <fix_upto>, recv=3,
len=22, argc=1, argv=0x400a3000)
at eval.c:4276
#89 0x41170929 in rb_call0 (klass=1073975016, recv=3, id=4017, argc=1,
argv=0xbfffe3e0,
body=0x400389c0, nosuper=1) at eval.c:4416
#90 0x4117113c in rb_call (klass=1073975016, recv=3, mid=4017, argc=1,
argv=0xbfffe3e0, scope=0)
at eval.c:4640
#91 0x4116c012 in rb_eval (self=1073994976, n=0xbfffd2c8) at eval.c:2556
#92 0x4116b3cd in rb_eval (self=1073994976, n=0xbfffd2c8) at eval.c:2304
#93 0x4116a65a in rb_eval (self=1073994976, n=0xbfffd2c8) at eval.c:2053
#94 0x41168908 in ruby_run () at eval.c:1230
#95 0x080485b4 in main ()
#96 0x410299f1 in __libc_start_main () from /lib/libc.so.6

I hope the provided information is enough, I have decided not to attach
the test program here as it’s 21kb(and this message is already large
enough without it), but it may be fetched here:
http://idanso.dyndns.org/maps/ruby-bug.tar.bz2

Idan.

2

I had a problem reproducing the matter in simple TCP/IP snippets,
however, I have managed reproducing it using a heavly stripped version
of Radical, using pure ruby code(no extensions).

It receive VT_ALRM when it's in rb_thread_restore_context(). Can you try
to put ruby in critical phase when it's in rb_thread_restore_context() to
see if there is a change.

Guy Decoux

3

It receive VT_ALRM when it's in rb_thread_restore_context(). Can you try
to put ruby in critical phase when it's in rb_thread_restore_context() to
see if there is a change.

Well, for me the problem is solved

pigeon% siege -b -c 20 -t 120S -u http://localhost:4000/blender
** Siege 2.55
** Preparing 20 concurrent users for battle.
The server is now under siege...
Lifting the server siege... done.
Transactions: 4697 hits
Availability: 100.00 %
Elapsed time: 119.93 secs
Data transferred: 213736985 bytes
Response time: 0.51 secs
Transaction rate: 39.16 trans/sec
Throughput: 1782181.14 bytes/sec
Concurrency: 19.79
Successful transactions: 4697
Failed transactions: 0
pigeon%

pigeon% siege -b -c 100 -t 120S -u http://localhost:4000/blender
** Siege 2.55
** Preparing 100 concurrent users for battle.
The server is now under siege...
Error: SIEGEsocket: connection timed out.: Operation now in progress
[...]
Error: SIEGEsocket: connection timed out.: Operation now in progress

Lifting the server siege.. done.
Transactions: 5800 hits
Availability: 99.59 %
Elapsed time: 120.32 secs
Data transferred: 263929000 bytes
Response time: 1.86 secs
Transaction rate: 48.20 trans/sec
Throughput: 2193558.85 bytes/sec
Concurrency: 89.44
Successful transactions: 5800
Failed transactions: 24
pigeon%

Now if someone can explain me why it need this, I'll very happy ...

p.s. : you must have a bug in your source

Guy Decoux

4

ביום רביעי, 19 בפברואר 2003, 11:46, ts כתב:

It receive VT_ALRM when it’s in rb_thread_restore_context(). Can you
try t> to put ruby in critical phase when it’s in
rb_thread_restore_context() to t> see if there is a change.

Well, for me the problem is solved
I suppose it is a change I have to apply to the ruby source itself?

In anyway according to the results you’ve sent it indeed appears to have
solved the matter, many 10x.

p.s. : you must have a bug in your source
??

Idan

5

p.s. : you must have a bug in your source

??
I think he was refering to the fact that example two had 5800
transactions, had 5800 successful transactions and there where 24 failed
transactions.

Lifting the server siege.. done. Transactions: 5800 hits Availability: 99.59 % Elapsed time: 120.32 secs Data transferred: 263929000 bytes Response time: 1.86 secs Transaction rate: 48.20 trans/sec Throughput: 2193558.85 bytes/sec Concurrency: 89.44 Successful transactions: 5800 Failed transactions: 24 <<------ problem?
6

I suppose it is a change I have to apply to the ruby source itself?

Yes, like I've said put rb_thread_restore_context() in critical phase
(same for rb_thread_save_context()).

It's easy to understand :
   1) a thread is stopped by the timer
   2) ruby run the scheduler
   3) when ruby call rb_thread_restore_context()
       * it extend the stack (extend_stack)
       * the current thread is with rb_trap_immediate = 1
       * ruby receive VTALRM it re-run the scheduler, at this step the
         frame pointers for this thread *can* be invalid (ruby has not yet
   make the complete copy)

Now if the new thread call the GC, it exist at least one thread with
invalid frame pointers and you have the bug

#0 0x4117f2fb in mark_locations_array (x=0xc0000000, n=-1073796479) at gc.c:353
#1 0x4118007a in rb_gc_mark_frame (frame=0x40cc2744) at gc.c:958
                                    ^^^^^^^^^^^^^^^^
this frame pointer is invalid.

p.s. : you must have a bug in your source

??

Well, if I'm right it exist a possibility that your script will be blocked
in a while loop and never accept new connection : not sure.

Guy Decoux

7

Hi,

···

At Wed, 19 Feb 2003 23:55:48 +0900, ts wrote:

I suppose it is a change I have to apply to the ruby source itself?

Yes, like I’ve said put rb_thread_restore_context() in critical phase
(same for rb_thread_save_context()).

It’s easy to understand :

  1. a thread is stopped by the timer
  2. ruby run the scheduler
  3. when ruby call rb_thread_restore_context()
    • it extend the stack (extend_stack)
    • the current thread is with rb_trap_immediate = 1
    • ruby receive VTALRM it re-run the scheduler, at this step the
      frame pointers for this thread can be invalid (ruby has not yet
      make the complete copy)

What about this?

Index: eval.c

RCS file: //sharui/cvs/ruby/src/ruby/eval.c,v
retrieving revision 1.398
diff -u -2 -p -r1.398 eval.c
— eval.c 19 Feb 2003 09:27:49 -0000 1.398
+++ eval.c 19 Feb 2003 15:32:13 -0000
@@ -7826,4 +7826,5 @@ thread_switch(n)
int n;
{

  • rb_trap_immediate = (curr_thread->flags&0x100)?1:0;
    switch (n) {
    case 0:
    @@ -7891,4 +7892,5 @@ rb_thread_restore_context(th, exit)
    }

  • rb_trap_immediate = 0; /* prohibit interrupts from here */
    ruby_frame = th->frame;
    ruby_scope = th->scope;
    @@ -7899,5 +7901,4 @@ rb_thread_restore_context(th, exit)
    ruby_block = th->block;
    scope_vmode = th->flags&SCOPE_MASK;

  • rb_trap_immediate = (th->flags&0x100)?1:0;
    ruby_iter = th->iter;
    prot_tag = th->tag;

–
Nobu Nakada

8

It’s not a bug but a feature:-)

The MTServer class does not start a thread for every request, but keeps a
limited pool of worker threads, if i’m not mistaken the default setting is up
to 10 workers and additional 10 workers employed during stress time.

So if you flood it with 100 concurrent clients, it is likely some of the
requests will timeout…

Idan.

···

On יום רביעי, 19 בפברואר 2003, 16:46, Robert McGovern wrote:

I think he was refering to the fact that example two had 5800
transactions, had 5800 successful transactions and there where 24 failed
transactions.
Failed transactions: 24 <<------ problem?

9

What about this?

Seems good

Guy Decoux

10

Hi,

···

In message “Re: [BUG] Segmation fault in combination of heavy socket I/O and multi-threading” on 03/02/20, nobu.nokada@softhome.net nobu.nokada@softhome.net writes:

What about this?

Go ahead and commit these fix, please

						matz.