Ben Gribaudo
2006-Oct-17 19:23 UTC
Debugging a Hanging Rails App -- Suspect blocking due to file locking
Hello,
I am debugging a Rails app which hangs every one to three days. The
process doesn''t crash; it just stops responding. I have been unable to
predictably reproduce this failure in a testing environment.
The hang occurs after a call to Authentication controller''s access
method (code below). This action is called many times each day but only
once in a while does the call cause a hang.
Right now, my hypothesis is that the hang is file system blocking caused
by a file lock. Tmpreaper runs every minute or two to remove old session
files. My limited knowledge of Linux file systems makes me think that if
it were, lsof would show it holding a lock.
The fact that lsof shows ruby holding two locks on the session file
makes me wonder if both Rail''s default session handling functionality
and the call to "CGI::Session.new(CGI.new, options)" are both trying
to
keep the same file open, thus causing blocking.
Any clues on what might be causing this locking or how to resolve it?
Thank you,
Ben
Chicago 2006 Alumni
===================System Specs:
Ruby 1.8.5 built from stable source
Ubuntu 6.06
Rails 1.1.6 using Webrick behind an Apache 2 reverse proxy
Here''s relevant output from lsof from when the system hung this
morning:
ruby 748 dailysuccess 6uW REG 104,1
0 167704
/tmp/sessions/dailysuccess/service/ruby_sess.e223f7c38046356c (deleted)
ruby 748 dailysuccess 7uW REG 104,1
0 167704
/tmp/sessions/dailysuccess/service/ruby_sess.e223f7c38046356c (deleted)
Using gdb to examine the process (thanks to Jamis Buck''s recent blog
postings) and execute a backtrace reveals:
0x89c1750:
"/var/iblp/dailysuccess/ruby/lib/ruby/1.8/pstore.rb:292:in
`flock''"
0x89c1798:
"/var/iblp/dailysuccess/ruby/lib/ruby/1.8/pstore.rb:292:in
`transaction''"
0x89c17e8:
"/var/iblp/dailysuccess/ruby/lib/ruby/1.8/cgi/session/pstore.rb:81:in
`update''"
0x87d2438:
"/var/iblp/dailysuccess/ruby/lib/ruby/1.8/cgi/session/pstore.rb:88:in
`close''"
0x87d2490:
"/var/iblp/dailysuccess/ruby/lib/ruby/1.8/cgi/session.rb:166:in
`callback''"
0x87d24e0:
"/var/iblp/dailysuccess/ruby/lib/ruby/1.8/pstore.rb:368:in
`call''"
0x87d2528:
"/var/iblp/dailysuccess/ruby/lib/ruby/1.8/pstore.rb:368:in
`commit_new''"
0x87d2578:
"/var/iblp/dailysuccess/ruby/lib/ruby/1.8/pstore.rb:334:in
`transaction''"
0x87d25c8:
"/var/iblp/dailysuccess/ruby/lib/ruby/1.8/cgi/session/pstore.rb:62:in
`initialize''"
0x87d2620:
"/var/iblp/dailysuccess/ruby/lib/ruby/1.8/cgi/session.rb:273:in
`new''"
0x87d2670:
"/var/iblp/dailysuccess/ruby/lib/ruby/1.8/cgi/session.rb:273:in
`initialize''"
0x87d26c0:
"/var/iblp/dailysuccess/service/current-version/script/../config/../app/controllers/authentication_controller.rb:5:in
`new''"
0x87d2740:
"/var/iblp/dailysuccess/service/current-version/script/../config/../app/controllers/authentication_controller.rb:5:in
`access''"
And here are a few lines from the process backtrace:
#0 0xffffe410 in __kernel_vsyscall ()
#1 0xb7f0508d in select () from /lib/tls/i686/cmov/libc.so.6
#2 0x0806842e in rb_thread_schedule () at ../ruby-1.8.5/eval.c:10638
#3 0x080697e3 in rb_thread_polling () at ../ruby-1.8.5/eval.c:11349
#4 0x0806f1ab in rb_thread_flock (fd=7, op=6, fptr=0x8251c48) at
../ruby-1.8.5/file.c:3156
#5 0x0806f299 in rb_file_flock (obj=3080224540, operation=5) at
../ruby-1.8.5/file.c:3216
#6 0x0805f1a4 in call_cfunc (func=0x806f1e3 <rb_file_flock>,
recv=3080224540, len=1, argc=1, argv=0xbfbc2290) at
../ruby-1.8.5/eval.c:5660
#7 0x0805e6c8 in rb_call0 (klass=3085134580, recv=3080224540, id=8281,
oid=8281, argc=1, argv=0xbfbc2290, body=0xb7e35a28, flags=0)
at ../ruby-1.8.5/eval.c:5810
#8 0x0805fc86 in rb_call (klass=3085134580, recv=3080224540, mid=8281,
argc=1, argv=0xbfbc2290, scope=0) at ../ruby-1.8.5/eval.c:6048
#9 0x08058b53 in rb_eval (self=3079764800, n=0xb7bad184) at
../ruby-1.8.5/eval.c:3443
class AuthenticationController < ApplicationController
# Called by an external template system to determine if Web visitor is
allowed access.
# Template system retrieves cookie from client and passes session ID
into this action
# which loads the session into memory in the Rails application.
def access
options =
default_session_options.stringify_keys.update(''session_id''
=> @params[:id])
session = CGI::Session.new(CGI.new, options)
render(:text => logged_in?(session) ? ''true'' :
''false'')
end
private
def default_session_options
ActionController::CgiRequest::DEFAULT_SESSION_OPTIONS
end
def logged_in?(session)
session[:user].kind_of?(User)
end
end
--~--~---------~--~----~------------~-------~--~----~
You received this message because you are subscribed to the Google Groups
"Ruby on Rails: Talk" group.
To post to this group, send email to
rubyonrails-talk-/JYPxA39Uh5TLH3MbocFFw@public.gmane.org
To unsubscribe from this group, send email to
rubyonrails-talk-unsubscribe-/JYPxA39Uh5TLH3MbocFFw@public.gmane.org
For more options, visit this group at
http://groups.google.com/group/rubyonrails-talk
-~----------~----~----~----~------~----~------~--~---