[Mongrel] Mongrel spewing backtraces and nanosleeping

Jacob Atzen jacob at jacobatzen.dk
Wed Sep 13 10:00:21 EDT 2006


Hi list,

I'm seeing a couple of issues with Mongrel. I'm running FreeBSD 6.1 and
have previously been told that there are known conflicts between this
and Mongrel, yet I hope these issues will be resolved with time.

I'm overloading Mongrel with httperf on my local workstation. Mongrel is
started directly with the mongrel_rails command and there is only one
mongrel running. Soon I will start seeing:

Server overloaded with N processors (M max). Dropping connection.
Wed Sep 13 00:03:05 CEST 2006: Reaping N threads for slow workers because of 'max processors' 

Now this is fine, but sooner or later I start getting the following in
the mongrel.log:

Thread #<Thread:0x8f1a364 sleep> is too old, killing.
Wed Sep 13 00:34:42 CEST 2006: Error calling Dispatcher.dispatch #<Sync_m::Err::UnknownLocker: Thread(#<Thread:0x8f1a364 run>) not locked.>
/usr/local/lib/ruby/1.8/sync.rb:57:in `Fail'
/usr/local/lib/ruby/1.8/sync.rb:63:in `Fail'
/usr/local/lib/ruby/1.8/sync.rb:183:in `sync_unlock'
/usr/local/lib/ruby/1.8/sync.rb:231:in `synchronize'
/usr/local/lib/ruby/gems/1.8/gems/mongrel-0.3.13.4/lib/mongrel/rails.rb:83:in `process'
/usr/local/lib/ruby/gems/1.8/gems/mongrel-0.3.13.4/lib/mongrel.rb:580:in `process_client'
/usr/local/lib/ruby/gems/1.8/gems/mongrel-0.3.13.4/lib/mongrel.rb:579:in `process_client'
/usr/local/lib/ruby/gems/1.8/gems/mongrel-0.3.13.4/lib/mongrel.rb:686:in `run'
/usr/local/lib/ruby/gems/1.8/gems/mongrel-0.3.13.4/lib/mongrel.rb:686:in `run'
/usr/local/lib/ruby/gems/1.8/gems/mongrel-0.3.13.4/lib/mongrel.rb:673:in `run'
/usr/local/lib/ruby/gems/1.8/gems/mongrel-0.3.13.4/lib/mongrel/configurator.rb:267:in `run'
/usr/local/lib/ruby/gems/1.8/gems/mongrel-0.3.13.4/lib/mongrel/configurator.rb:266:in `run'
/usr/local/lib/ruby/gems/1.8/gems/mongrel-0.3.13.4/bin/mongrel_rails:127:in `run'
/usr/local/lib/ruby/gems/1.8/gems/mongrel-0.3.13.4/lib/mongrel/command.rb:203:in `run'
/usr/local/lib/ruby/gems/1.8/gems/mongrel-0.3.13.4/bin/mongrel_rails:231
/usr/local/bin/mongrel_rails:18

Often I get many, many of these in succession. Usually mongrel will stop
responding shortly after these start showing up, but not always.

Now when Mongrel dies it sometimes uses up all of the CPU time it can
get it's hands on.  I tried to get a backtrace from gdb by attaching to
the running process and asking nicely for a backtrace, here's what gdb
tells me (not sure if it really tells that much):

#0  0x2823e9fb in nanosleep () from /lib/libc.so.6
#1  0x281823fe in _nanosleep () from /usr/lib/libpthread.so.2
#2  0x28182602 in nanosleep () from /usr/lib/libpthread.so.2
#3  0x281790eb in select () from /usr/lib/libpthread.so.2
#4  0x280ad34c in rb_thread_wait_for () from /usr/local/lib/libruby18.so.18
#5  0x280e4dec in rb_f_sleep () from /usr/local/lib/libruby18.so.18
#6  0x280a40ac in rb_call0 () from /usr/local/lib/libruby18.so.18
#7  0x280a4c5d in rb_call () from /usr/local/lib/libruby18.so.18
#8  0x2809f369 in rb_eval () from /usr/local/lib/libruby18.so.18
#9  0x280a2444 in rb_yield_0 () from /usr/local/lib/libruby18.so.18
#10 0x280a285e in rb_f_loop () from /usr/local/lib/libruby18.so.18
#11 0x280a40be in rb_call0 () from /usr/local/lib/libruby18.so.18
#12 0x280a4c5d in rb_call () from /usr/local/lib/libruby18.so.18
#13 0x2809f369 in rb_eval () from /usr/local/lib/libruby18.so.18
#14 0x2809e275 in rb_eval () from /usr/local/lib/libruby18.so.18
#15 0x280a2444 in rb_yield_0 () from /usr/local/lib/libruby18.so.18
#16 0x280ae89f in rb_thread_yield () from /usr/local/lib/libruby18.so.18
#17 0x280ae5ed in rb_thread_start_0 () from /usr/local/lib/libruby18.so.18
#18 0x280ae9a7 in rb_thread_initialize () from /usr/local/lib/libruby18.so.18
#19 0x280a4098 in rb_call0 () from /usr/local/lib/libruby18.so.18
#20 0x280a4c5d in rb_call () from /usr/local/lib/libruby18.so.18
#21 0x280a507d in rb_funcall2 () from /usr/local/lib/libruby18.so.18
#22 0x280a785e in rb_obj_call_init () from /usr/local/lib/libruby18.so.18
#23 0x280ae8dc in rb_thread_s_new () from /usr/local/lib/libruby18.so.18
#24 0x280a40ac in rb_call0 () from /usr/local/lib/libruby18.so.18
#25 0x280a4c5d in rb_call () from /usr/local/lib/libruby18.so.18
#26 0x2809f11c in rb_eval () from /usr/local/lib/libruby18.so.18
#27 0x2809e275 in rb_eval () from /usr/local/lib/libruby18.so.18
#28 0x2809fe04 in rb_eval () from /usr/local/lib/libruby18.so.18
#29 0x280a480e in rb_call0 () from /usr/local/lib/libruby18.so.18
#30 0x280a4c5d in rb_call () from /usr/local/lib/libruby18.so.18
#31 0x2809f11c in rb_eval () from /usr/local/lib/libruby18.so.18
#32 0x280a480e in rb_call0 () from /usr/local/lib/libruby18.so.18
#33 0x280a4c5d in rb_call () from /usr/local/lib/libruby18.so.18
#34 0x2809f11c in rb_eval () from /usr/local/lib/libruby18.so.18
#35 0x280a480e in rb_call0 () from /usr/local/lib/libruby18.so.18
#36 0x280a4c5d in rb_call () from /usr/local/lib/libruby18.so.18
#37 0x2809f11c in rb_eval () from /usr/local/lib/libruby18.so.18
#38 0x2809daae in rb_eval () from /usr/local/lib/libruby18.so.18
#39 0x2809ac9d in eval_node () from /usr/local/lib/libruby18.so.18
#40 0x280a6588 in rb_load () from /usr/local/lib/libruby18.so.18
#41 0x280a6842 in rb_f_load () from /usr/local/lib/libruby18.so.18
#42 0x280a40ac in rb_call0 () from /usr/local/lib/libruby18.so.18
#43 0x280a4c5d in rb_call () from /usr/local/lib/libruby18.so.18
#44 0x2809f369 in rb_eval () from /usr/local/lib/libruby18.so.18
#45 0x2809ac9d in eval_node () from /usr/local/lib/libruby18.so.18
#46 0x2809b229 in ruby_exec_internal () from /usr/local/lib/libruby18.so.18
#47 0x2809b28d in ruby_exec () from /usr/local/lib/libruby18.so.18
#48 0x2809b2c1 in ruby_run () from /usr/local/lib/libruby18.so.18
#49 0x08048649 in main ()

This corresponds to what top tells me (nanslp). Additionally I tried
reattaching to the process a couple of times with gdb, and each time the
backtrace looked the same.

I've been trying to dig through the Mongrel code but I haven't fully
grasped what's going on with all the threads in there, so I hope someone
more insightful might be able to solve these issues.

A couple of further observations:

The above seems to be replicating whether I run with numprocs set to 1
or to 1024. Also I'm a bit surprised that I can from time to time
experience that there are one more processor than the max allowed, I
assume this is due to the threading and most likely is not a problem.

I would really like to get this issue resolved so I can get back to
using Mongrel for production on FreeBSD and if necessary I am willing to
spend some time trying to resolve these issues, but I will probably need
some help if I am to succeed. So please let me know if I can provide any
further information or give me a pointer to where to go from here. 

-- 
Cheers,
- Jacob Atzen


More information about the Mongrel-users mailing list