Summary: Thanks to Log4r trying to be nice and thread-safe, my application got into a deadlock when it (unintentionally) caused a method from Log4r that had a synchronize block in it to be called recursively.
It seems to only a problem if I use DeferrableDatabaseOutputter. If I change it to use a simpler outputter, it works just fine:
DatabaseLog4r::apply_outputters(logger) do |logger|
logger.add Log4r::StdoutOutputter.new("Just print it")
end
It seems to only be a problem for dynamic requests (not surprisingly). Dynamic (controller action) requests from the browser will hang (because they use DeferrableDatabaseOutputter). When I hit Escape, I see that the favicon.ico request is still served successfully...
192.168.254.118 - - [09/Apr/2007:13:09:12 PDT] "GET /favicon.ico HTTP/1.1" 200 0 - -> /favicon.ico [hit escape] 192.168.254.118 - - [09/Apr/2007:13:09:24 PDT] "GET /favicon.ico HTTP/1.1" 200 0 - -> /favicon.ico
During bootup (webrick), we get this (before any requests are even made):
> cat log/rails_profiler_development/*
:created_at"Mon Apr 9 13:16:49 2007:
message"App startup: Outputters have been added to logger. Note that any log messages
sent to the logger prior to this point are unlikely to be recorded anywhere.:
level" INFO:extra_data0:application"Rails Profiler:message_class"
If I stop it right after that (still no requests), the file is still there, and nothing has been logged to application_log_entries. Should it have been? Probably not, because flushing is only triggered by requests.
Let's step things up a notch and actually do a request!
sqlite> select * from application_log_entries order by id desc limit 10; id|application|level|message_class|message|created_at 1|Rails Profiler|INFO|String|render_with_rails_profiler: 0.0196309089660645|2007-04-09 13:25:20
It hangs for both webrick and mongrel, but works fine for lighttpd!
For webrick and mongrel, it doesn't shutdown gracefully when you send an Interrupt. Webrick gives a Thread deadlock error.
> ./script/server
=> Booting Mongrel (use 'script/server webrick' to force WEBrick)
...
Processing SlowController#queries (for 192.168.254.118 at 2007-04-09 08:49:33) [GET]
...
** INT signal received.
Mon Apr 09 08:49:51 -0700 2007: Reaping 1 threads for slow workers because of 'shutdown'
Waiting for 1 requests to finish, could take 60 seconds.** INT signal received.
Exiting
/usr/lib/ruby/gems/1.8/gems/mongrel-0.3.13.4/lib/mongrel.rb:753:in `graceful_shutdown': Mongrel::StopServer (Mongrel::StopServer)
from /usr/lib/ruby/gems/1.8/gems/mongrel-0.3.13.4/lib/mongrel/configurator.rb:289:in `join'
from /usr/lib/ruby/gems/1.8/gems/mongrel-0.3.13.4/lib/mongrel/configurator.rb:289:in `join'
from /usr/lib/ruby/gems/1.8/gems/mongrel-0.3.13.4/lib/mongrel/configurator.rb:289:in `each'
from /usr/lib/ruby/gems/1.8/gems/mongrel-0.3.13.4/lib/mongrel/configurator.rb:289:in `join'
from /usr/lib/ruby/gems/1.8/gems/mongrel-0.3.13.4/bin/mongrel_rails:136:in `run'
from /usr/lib/ruby/gems/1.8/gems/mongrel-0.3.13.4/lib/mongrel/command.rb:211:in `run'
from /usr/lib/ruby/gems/1.8/gems/mongrel-0.3.13.4/bin/mongrel_rails:231
from ./script/../config/../vendor/rails/activesupport/lib/active_support/dependencies.rb:488:in `load'
... 8 levels...
from ./script/../config/../vendor/rails/activesupport/lib/active_support/dependencies.rb:495:in `require'
from ./script/../config/../vendor/rails/railties/lib/commands/server.rb:39
from ./script/server:3:in `require'
from ./script/server:3
> ./script/server webrick
=> Booting WEBrick...
...
[2007-04-09 08:54:43] INFO going to shutdown ...
deadlock 0xb74c0bf0: sleep:- - /usr/lib/ruby/1.8/thread.rb:100
deadlock 0xb7f227c4: sleep:J(0xb74c0bf0) (main) - /usr/lib/ruby/1.8/webrick/server.rb:113
/usr/lib/ruby/1.8/webrick/server.rb:113:in `join': Thread(0xb7f227c4): deadlock (fatal)
from /usr/lib/ruby/1.8/webrick/server.rb:113:in `start'
from /usr/lib/ruby/1.8/webrick/server.rb:113:in `each'
from /usr/lib/ruby/1.8/webrick/server.rb:113:in `start'
from /usr/lib/ruby/1.8/webrick/server.rb:23:in `start'
from /usr/lib/ruby/1.8/webrick/server.rb:82:in `start'
from ./script/../config/../vendor/rails/railties/lib/webrick_server.rb:63:in `dispatch'
from ./script/../config/../vendor/rails/railties/lib/commands/servers/webrick.rb:59
from /usr/lib/ruby/site_ruby/1.8/rubygems/custom_require.rb:27:in `gem_original_require'
from /usr/lib/ruby/site_ruby/1.8/rubygems/custom_require.rb:27:in `require'
from ./script/../config/../vendor/rails/activesupport/lib/active_support/dependencies.rb:495:in `require'
from ./script/../config/../vendor/rails/activesupport/lib/active_support/dependencies.rb:342:in `new_constants_in'
from ./script/../config/../vendor/rails/activesupport/lib/active_support/dependencies.rb:495:in `require'
from ./script/../config/../vendor/rails/railties/lib/commands/server.rb:39
from ./script/server:3:in `require'
from ./script/server:3
I'm not sure I like this rescue Exception...
def write(data)
begin
write_without_deferring data
# rescue Exception => error
# # If anything at all goes wrong, fall back to writing to the file.
# defer data
end
end
It prevented me from seeing this error...
NoMethodError: You have a nil object when you didn't expect it! The error occurred while evaluating nil.info ./script/../config/../../lib/rails_profiler.rb:39:in `log'
(so I commented it out for now)
This method in lib/rails_profiler.rb:
def log_with_rails_profiler(sql, name, &block)
return_value = nil
runtime = Benchmark.realtime do
return_value = log_without_rails_profiler(sql, name, &block)
end
puts 'logging'
RailsProfiler::logger.info "log_with_rails_profiler: #{runtime} (sql = #{sql.strip}"
return_value
end
Was trying to use the logger before the logger was initialized...
INSERT INTO application_log_entries ("message", "message_class", "level", "application", "created_at") VALUES('App startup: Outputters have been added to logger. Note that any log messages sent to the logger prior to this point are unlikely to be recorded anywhere.', 'String', 'INFO', 'Rails Profiler', '2007-04-09 15:55:17')
That was easy enough to solve. Just moved this line up before apply_outputters:
RailsProfiler::logger = logger
But I was still getting this other error...
ThreadError: stopping only thread
note: use sleep to stop forever
/usr/lib/ruby/1.8/thread.rb:100:in `stop'
/usr/lib/ruby/1.8/thread.rb:100:in `lock'
/usr/lib/ruby/1.8/thread.rb:133:in `synchronize'
/usr/lib/ruby/gems/1.8/gems/log4r-1.0.5/src/log4r/outputter/outputter.rb:130:in `synch'
/usr/lib/ruby/gems/1.8/gems/log4r-1.0.5/src/log4r/outputter/outputter.rb:108:in `canonical_log'
(eval):3:in `info'
(eval):8:in `info'
(eval):8:in `each'
(eval):8:in `info'
./script/../config/../../lib/rails_profiler.rb:40:in `log'
"What," you ask, "is Outputter#canonical_log, and why are we getting there?" I don't know. But apparently that's what delegates to the actual outputters, as this call stack from doing pp caller(0) in deferrable_database_outputter.rb reveals...
["./script/../config/../vendor/plugins/database_log4r/lib/log4r/deferrable_database_outputter.rb:51:in `write'", "/usr/lib/ruby/gems/1.8/gems/log4r-1.0.5/src/log4r/outputter/outputter.rb:109:in `canonical_log'", "/usr/lib/ruby/gems/1.8/gems/log4r-1.0.5/src/log4r/outputter/outputter.rb:129:in `synch'", "/usr/lib/ruby/1.8/thread.rb:135:in `synchronize'", "/usr/lib/ruby/gems/1.8/gems/log4r-1.0.5/src/log4r/outputter/outputter.rb:129:in `synch'", "/usr/lib/ruby/gems/1.8/gems/log4r-1.0.5/src/log4r/outputter/outputter.rb:109:in `canonical_log'",
When I comment out this line, it no longer hangs:
RailsProfiler::logger.info "log_with_rails_profiler: #{runtime} (sql = #{sql.strip}"
Good, now when the server starts up, we see this in the database (and no deferred-data file is created):
1|Rails Profiler|INFO|String|App startup: Outputters have been added to logger. Note that any log messages sent to the logger prior to this point are unlikely to be recorded anywhere.|2007-04-09 16:18:48 2|Rails Profiler|INFO|String|render_with_rails_profiler: 0.0199239253997803|2007-04-09 16:18:50 3|Rails Profiler|INFO|String|perform_action_with_rails_profiler: 0.116832971572876|2007-04-09 16:18:50
That's good. But we really need to be able to log from ActiveRecord too!
Apparently what was going on was that when it tried to log from render_with_rails_profiler, it was getting in log_with_rails_profiler, where it tried to log the runtime for that database query.
This is evidenced by this output:
Actually logging query 'INSERT INTO application_log_entries ("message", "message_class", "level", "application", "created_at") VALUES('render_with_rails_profiler: 0.0186080932617188', 'String', 'INFO', 'Rails Profiler', '2007-04-09 16:36:28')'
[Hangs here]
[2007-04-09 16:36:53] INFO going to shutdown ...
deadlock 0xb74b7884: sleep:- - /usr/lib/ruby/1.8/thread.rb:100
deadlock 0xb7f237c8: sleep:J(0xb74b7884) (main) - /usr/lib/ruby/1.8/webrick/server.rb:113
fatal: Thread(0xb7f237c8): deadlock
from this debug code:
def log_with_rails_profiler(sql, name, &block)
...
puts "Actually logging query: '#{sql}'"
RailsProfiler::logger.info "log_with_rails_profiler: #{runtime} (sql = #{sql.strip}"
It's almost as if that caused an infinite loop... Why didn't it raise a stack overflow error then???
Anyway, I think the only way it would cause an infinite loop would be when we call RailsProfiler::logger.info from within log_with_rails_profiler...
Would it help if we turned off logging as soon as we got inside of log_with_rails_profiler?:
def log_with_rails_profiler(sql, name, &block)
::ActiveRecord::Base.silence do
return_value = nil
puts "Actually logging query: '#{sql}'"
runtime = Benchmark.realtime do
return_value = log_without_rails_profiler(sql, name, &block)
end
RailsProfiler::logger.info "log_with_rails_profiler: #{runtime} (sql = #{sql.strip}"
return_value
end
end
No, apparently not. We still get hang-age...
Actually logging query: 'INSERT INTO application_log_entries ("message", "message_class", "level", "application", "created_at") VALUES('render_with_rails_profiler: 0.0196490287780762', 'String', 'INFO', 'Rails Profiler', '2007-04-09 18:14:59')'
[Hangs]
It doesn't even work if we move the log-silencing out to DeferrableDatabaseOutputter#write:
def write(data)
::ActiveRecord::Base.silence do
begin
write_without_deferring data
rescue Exception => error
defer data
end
end
end
set_trace_func
puts "Actually logging query: '#{sql}'"
trap("INT") { set_trace_func(nil); exit }
set_trace_func proc { |event, file, line, id, binding, classname|
unless ['c-call', 'c-return'].include? event
printf "%8s %s:%-2d %10s %10s\n", event, file, line, classname, id
end
}
runtime = Benchmark.realtime do
return_value = log_without_rails_profiler(sql, name, &block)
end
RailsProfiler::logger.info "log_with_rails_profiler: #{runtime} (sql = #{sql.strip}"
set_trace_func(nil)
Actually logging query: 'INSERT INTO application_log_entries ("message", "message_class", "level", "application", "created_at") VALUES('render_with_rails_profiler: 0.0196919441223145', 'String', 'INFO', 'Rails Profiler', '2007-04-09 18:32:48')'
line ./script/../config/../../lib/rails_profiler.rb:49 RailsProfiler::ActiveRecord::AbstractAdapter log
call /usr/lib/ruby/1.8/benchmark.rb:306 Benchmark realtime
line /usr/lib/ruby/1.8/benchmark.rb:307 Benchmark realtime
call /usr/lib/ruby/1.8/benchmark.rb:291 Benchmark measure
line /usr/lib/ruby/1.8/benchmark.rb:292 Benchmark measure
call /usr/lib/ruby/1.8/benchmark.rb:128 Benchmark times
line /usr/lib/ruby/1.8/benchmark.rb:129 Benchmark times
return /usr/lib/ruby/1.8/benchmark.rb:130 Benchmark times
line /usr/lib/ruby/1.8/benchmark.rb:293 Benchmark measure
line ./script/../config/../../lib/rails_profiler.rb:50 RailsProfiler::ActiveRecord::AbstractAdapter log
call abstract_adapter.rb:106 ActiveRecord::ConnectionAdapters::AbstractAdapter log_without_rails_profiler
line abstract_adapter.rb:107 ActiveRecord::ConnectionAdapters::AbstractAdapter log_without_rails_profiler
line abstract_adapter.rb:107 ActiveRecord::ConnectionAdapters::AbstractAdapter log_without_rails_profiler
line abstract_adapter.rb:108 ActiveRecord::ConnectionAdapters::AbstractAdapter log_without_rails_profiler
line abstract_adapter.rb:108 ActiveRecord::ConnectionAdapters::AbstractAdapter log_without_rails_profiler
line abstract_adapter.rb:115 ActiveRecord::ConnectionAdapters::AbstractAdapter log_without_rails_profiler
line sqlite_adapter.rb:145 ActiveRecord::ConnectionAdapters::SQLiteAdapter execute
call /usr/lib/ruby/site_ruby/1.8/sqlite3/database.rb:209 SQLite3::Database execute
line /usr/lib/ruby/site_ruby/1.8/sqlite3/database.rb:210 SQLite3::Database execute
call /usr/lib/ruby/site_ruby/1.8/sqlite3/database.rb:182 SQLite3::Database prepare
line /usr/lib/ruby/site_ruby/1.8/sqlite3/database.rb:183 SQLite3::Database prepare
call /usr/lib/ruby/site_ruby/1.8/sqlite3/statement.rb:65 SQLite3::Statement initialize
line /usr/lib/ruby/site_ruby/1.8/sqlite3/statement.rb:66 SQLite3::Statement initialize
line /usr/lib/ruby/site_ruby/1.8/sqlite3/statement.rb:67 SQLite3::Statement initialize
line /usr/lib/ruby/site_ruby/1.8/sqlite3/statement.rb:68 SQLite3::Statement initialize
line /usr/lib/ruby/site_ruby/1.8/sqlite3/statement.rb:69 SQLite3::Statement initialize
call /usr/lib/ruby/site_ruby/1.8/sqlite3/driver/native/driver.rb:88 SQLite3::Driver::Native::Driver prepare
line /usr/lib/ruby/site_ruby/1.8/sqlite3/driver/native/driver.rb:89 SQLite3::Driver::Native::Driver prepare
line /usr/lib/ruby/site_ruby/1.8/sqlite3/driver/native/driver.rb:89 SQLite3::Driver::Native::Driver prepare
line /usr/lib/ruby/site_ruby/1.8/sqlite3/driver/native/driver.rb:89 SQLite3::Driver::Native::Driver prepare
return /usr/lib/ruby/site_ruby/1.8/sqlite3/driver/native/driver.rb:91 SQLite3::Driver::Native::Driver prepare
line /usr/lib/ruby/site_ruby/1.8/sqlite3/statement.rb:70 SQLite3::Statement initialize
call /usr/lib/ruby/site_ruby/1.8/sqlite3/errors.rb:91 SQLite3::Error check
line /usr/lib/ruby/site_ruby/1.8/sqlite3/errors.rb:92 SQLite3::Error check
line /usr/lib/ruby/site_ruby/1.8/sqlite3/errors.rb:92 SQLite3::Error check
return /usr/lib/ruby/site_ruby/1.8/sqlite3/errors.rb:96 SQLite3::Error check
return /usr/lib/ruby/site_ruby/1.8/sqlite3/statement.rb:66 SQLite3::Statement initialize
line /usr/lib/ruby/site_ruby/1.8/sqlite3/database.rb:184 SQLite3::Database prepare
line /usr/lib/ruby/site_ruby/1.8/sqlite3/database.rb:184 SQLite3::Database prepare
line /usr/lib/ruby/site_ruby/1.8/sqlite3/database.rb:185 SQLite3::Database prepare
line /usr/lib/ruby/site_ruby/1.8/sqlite3/database.rb:186 SQLite3::Database prepare
line /usr/lib/ruby/site_ruby/1.8/sqlite3/database.rb:211 SQLite3::Database execute
call /usr/lib/ruby/site_ruby/1.8/sqlite3/statement.rb:153 SQLite3::Statement execute
line /usr/lib/ruby/site_ruby/1.8/sqlite3/statement.rb:154 SQLite3::Statement execute
call /usr/lib/ruby/site_ruby/1.8/sqlite3/statement.rb:232 SQLite3::Statement must_be_open!
line /usr/lib/ruby/site_ruby/1.8/sqlite3/statement.rb:233 SQLite3::Statement must_be_open!
line /usr/lib/ruby/site_ruby/1.8/sqlite3/statement.rb:233 SQLite3::Statement must_be_open!
return /usr/lib/ruby/site_ruby/1.8/sqlite3/statement.rb:236 SQLite3::Statement must_be_open!
line /usr/lib/ruby/site_ruby/1.8/sqlite3/statement.rb:155 SQLite3::Statement execute
line /usr/lib/ruby/site_ruby/1.8/sqlite3/statement.rb:155 SQLite3::Statement execute
line /usr/lib/ruby/site_ruby/1.8/sqlite3/statement.rb:157 SQLite3::Statement execute
line /usr/lib/ruby/site_ruby/1.8/sqlite3/statement.rb:157 SQLite3::Statement execute
line /usr/lib/ruby/site_ruby/1.8/sqlite3/statement.rb:158 SQLite3::Statement execute
call /usr/lib/ruby/site_ruby/1.8/sqlite3/resultset.rb:57 SQLite3::ResultSet initialize
line /usr/lib/ruby/site_ruby/1.8/sqlite3/resultset.rb:58 SQLite3::ResultSet initialize
line /usr/lib/ruby/site_ruby/1.8/sqlite3/resultset.rb:59 SQLite3::ResultSet initialize
line /usr/lib/ruby/site_ruby/1.8/sqlite3/resultset.rb:60 SQLite3::ResultSet initialize
line /usr/lib/ruby/site_ruby/1.8/sqlite3/resultset.rb:61 SQLite3::ResultSet initialize
call /usr/lib/ruby/site_ruby/1.8/sqlite3/resultset.rb:66 SQLite3::ResultSet commence
line /usr/lib/ruby/site_ruby/1.8/sqlite3/resultset.rb:67 SQLite3::ResultSet commence
call /usr/lib/ruby/site_ruby/1.8/sqlite3/driver/native/driver.rb:169 SQLite3::Driver::Native::Driver step
line /usr/lib/ruby/site_ruby/1.8/sqlite3/driver/native/driver.rb:169 SQLite3::Driver::Native::Driver step
return ./script/../config/../vendor/rails/activesupport/lib/active_support/inflector.rb:250 SQLite3::Driver::Native::Driver step
line /usr/lib/ruby/site_ruby/1.8/sqlite3/resultset.rb:68 SQLite3::ResultSet commence
call /usr/lib/ruby/site_ruby/1.8/sqlite3/resultset.rb:73 SQLite3::ResultSet check
line /usr/lib/ruby/site_ruby/1.8/sqlite3/resultset.rb:74 SQLite3::ResultSet check
line /usr/lib/ruby/site_ruby/1.8/sqlite3/resultset.rb:74 SQLite3::ResultSet check
line /usr/lib/ruby/site_ruby/1.8/sqlite3/resultset.rb:75 SQLite3::ResultSet check
line /usr/lib/ruby/site_ruby/1.8/sqlite3/resultset.rb:75 SQLite3::ResultSet check
line /usr/lib/ruby/site_ruby/1.8/sqlite3/resultset.rb:76 SQLite3::ResultSet check
line /usr/lib/ruby/site_ruby/1.8/sqlite3/resultset.rb:76 SQLite3::ResultSet check
return /usr/lib/ruby/site_ruby/1.8/sqlite3/resultset.rb:74 SQLite3::ResultSet check
line /usr/lib/ruby/site_ruby/1.8/sqlite3/resultset.rb:69 SQLite3::ResultSet commence
return /usr/lib/ruby/site_ruby/1.8/sqlite3/resultset.rb:67 SQLite3::ResultSet commence
return /usr/lib/ruby/site_ruby/1.8/sqlite3/resultset.rb:58 SQLite3::ResultSet initialize
line /usr/lib/ruby/site_ruby/1.8/sqlite3/statement.rb:160 SQLite3::Statement execute
line /usr/lib/ruby/site_ruby/1.8/sqlite3/statement.rb:160 SQLite3::Statement execute
line /usr/lib/ruby/site_ruby/1.8/sqlite3/statement.rb:163 SQLite3::Statement execute
return /usr/lib/ruby/site_ruby/1.8/sqlite3/statement.rb:154 SQLite3::Statement execute
line /usr/lib/ruby/site_ruby/1.8/sqlite3/database.rb:212 SQLite3::Database execute
line /usr/lib/ruby/site_ruby/1.8/sqlite3/database.rb:212 SQLite3::Database execute
line /usr/lib/ruby/site_ruby/1.8/sqlite3/database.rb:215 SQLite3::Database execute
call /usr/lib/ruby/site_ruby/1.8/sqlite3/resultset.rb:159 SQLite3::ResultSet each
line /usr/lib/ruby/site_ruby/1.8/sqlite3/resultset.rb:160 SQLite3::ResultSet each
call /usr/lib/ruby/site_ruby/1.8/sqlite3/resultset.rb:108 SQLite3::ResultSet next
line /usr/lib/ruby/site_ruby/1.8/sqlite3/resultset.rb:109 SQLite3::ResultSet next
line /usr/lib/ruby/site_ruby/1.8/sqlite3/resultset.rb:109 SQLite3::ResultSet next
return /usr/lib/ruby/site_ruby/1.8/sqlite3/resultset.rb:109 SQLite3::ResultSet next
return /usr/lib/ruby/site_ruby/1.8/sqlite3/resultset.rb:163 SQLite3::ResultSet each
line /usr/lib/ruby/site_ruby/1.8/sqlite3/database.rb:188 SQLite3::Database prepare
call /usr/lib/ruby/site_ruby/1.8/sqlite3/statement.rb:75 SQLite3::Statement close
line /usr/lib/ruby/site_ruby/1.8/sqlite3/statement.rb:76 SQLite3::Statement close
call /usr/lib/ruby/site_ruby/1.8/sqlite3/statement.rb:232 SQLite3::Statement must_be_open!
line /usr/lib/ruby/site_ruby/1.8/sqlite3/statement.rb:233 SQLite3::Statement must_be_open!
line /usr/lib/ruby/site_ruby/1.8/sqlite3/statement.rb:233 SQLite3::Statement must_be_open!
return /usr/lib/ruby/site_ruby/1.8/sqlite3/statement.rb:236 SQLite3::Statement must_be_open!
line /usr/lib/ruby/site_ruby/1.8/sqlite3/statement.rb:77 SQLite3::Statement close
line /usr/lib/ruby/site_ruby/1.8/sqlite3/statement.rb:78 SQLite3::Statement close
call /usr/lib/ruby/site_ruby/1.8/sqlite3/driver/native/driver.rb:169 SQLite3::Driver::Native::Driver finalize
line /usr/lib/ruby/site_ruby/1.8/sqlite3/driver/native/driver.rb:169 SQLite3::Driver::Native::Driver finalize
return ./script/../config/../vendor/rails/activesupport/lib/active_support/inflector.rb:250 SQLite3::Driver::Native::Driver finalize
return /usr/lib/ruby/site_ruby/1.8/sqlite3/statement.rb:76 SQLite3::Statement close
return /usr/lib/ruby/site_ruby/1.8/sqlite3/database.rb:183 SQLite3::Database prepare
return /usr/lib/ruby/site_ruby/1.8/sqlite3/database.rb:218 SQLite3::Database execute
return abstract_adapter.rb:129 ActiveRecord::ConnectionAdapters::AbstractAdapter log_without_rails_profiler
line /usr/lib/ruby/1.8/benchmark.rb:294 Benchmark measure
call /usr/lib/ruby/1.8/benchmark.rb:128 Benchmark times
line /usr/lib/ruby/1.8/benchmark.rb:129 Benchmark times
return /usr/lib/ruby/1.8/benchmark.rb:130 Benchmark times
line /usr/lib/ruby/1.8/benchmark.rb:295 Benchmark measure
call /usr/lib/ruby/1.8/benchmark.rb:423 Benchmark::Tms initialize
line /usr/lib/ruby/1.8/benchmark.rb:424 Benchmark::Tms initialize
line /usr/lib/ruby/1.8/benchmark.rb:425 Benchmark::Tms initialize
return /usr/lib/ruby/1.8/benchmark.rb:424 Benchmark::Tms initialize
return /usr/lib/ruby/1.8/benchmark.rb:292 Benchmark measure
return /usr/lib/ruby/1.8/benchmark.rb:306 Benchmark realtime
line ./script/../config/../../lib/rails_profiler.rb:53 RailsProfiler::ActiveRecord::AbstractAdapter log
call ./script/../config/../vendor/rails/activesupport/lib/active_support/core_ext/module/attribute_accessors.rb:11 RailsProfiler logger
line ./script/../config/../vendor/rails/activesupport/lib/active_support/core_ext/module/attribute_accessors.rb:12 RailsProfiler logger
return ./script/../config/../vendor/rails/activesupport/lib/active_support/core_ext/module/attribute_accessors.rb:13 RailsProfiler logger
call (eval):2 #<Log4r::Logger:0xb7658b34> info
line (eval):3 #<Log4r::Logger:0xb7658b34> info
line (eval):3 #<Log4r::Logger:0xb7658b34> info
line (eval):5 #<Log4r::Logger:0xb7658b34> info
line (eval):5 #<Log4r::Logger:0xb7658b34> info
line (eval):6 #<Log4r::Logger:0xb7658b34> info
call /usr/lib/ruby/gems/1.8/gems/log4r-1.0.5/src/log4r/logevent.rb:23 Log4r::LogEvent initialize
line /usr/lib/ruby/gems/1.8/gems/log4r-1.0.5/src/log4r/logevent.rb:24 Log4r::LogEvent initialize
line /usr/lib/ruby/gems/1.8/gems/log4r-1.0.5/src/log4r/logevent.rb:25 Log4r::LogEvent initialize
return /usr/lib/ruby/gems/1.8/gems/log4r-1.0.5/src/log4r/logevent.rb:24 Log4r::LogEvent initialize
line (eval):8 #<Log4r::Logger:0xb7658b34> info
line (eval):8 #<Log4r::Logger:0xb7658b34> info
call (eval):2 #<DatabaseLog4r::DeferrableDatabaseOutputter:0xb764ff34> info
line (eval):3 #<DatabaseLog4r::DeferrableDatabaseOutputter:0xb764ff34> info
call /usr/lib/ruby/gems/1.8/gems/log4r-1.0.5/src/log4r/outputter/outputter.rb:107 Log4r::Outputter canonical_log
line /usr/lib/ruby/gems/1.8/gems/log4r-1.0.5/src/log4r/outputter/outputter.rb:108 Log4r::Outputter canonical_log
call /usr/lib/ruby/gems/1.8/gems/log4r-1.0.5/src/log4r/outputter/outputter.rb:128 Log4r::Outputter synch
line /usr/lib/ruby/gems/1.8/gems/log4r-1.0.5/src/log4r/outputter/outputter.rb:128 Log4r::Outputter synch
call /usr/lib/ruby/1.8/thread.rb:132 Mutex synchronize
line /usr/lib/ruby/1.8/thread.rb:133 Mutex synchronize
call /usr/lib/ruby/1.8/thread.rb:97 Mutex lock
line /usr/lib/ruby/1.8/thread.rb:98 Mutex lock
line /usr/lib/ruby/1.8/thread.rb:98 Mutex lock
line /usr/lib/ruby/1.8/thread.rb:98 Mutex lock
line /usr/lib/ruby/1.8/thread.rb:99 Mutex lock
line /usr/lib/ruby/1.8/thread.rb:100 Mutex lock
line /usr/lib/ruby/1.8/webrick/server.rb:90 WEBrick::GenericServer start
line /usr/lib/ruby/1.8/webrick/server.rb:91 WEBrick::GenericServer start
line /usr/lib/ruby/1.8/webrick/server.rb:91 WEBrick::GenericServer start
line /usr/lib/ruby/1.8/webrick/server.rb:90 WEBrick::GenericServer start
line /usr/lib/ruby/1.8/webrick/server.rb:91 WEBrick::GenericServer start
...
[kept repeating]
What do I get out of that? Not terribly much, I admit, partly because I'm not really good at reading such things. But here are a couple observations.
It actually looks pretty normal, about how I'd expect it, until about this point:
call /usr/lib/ruby/1.8/thread.rb:97 Mutex lock
line /usr/lib/ruby/1.8/thread.rb:98 Mutex lock
line /usr/lib/ruby/1.8/thread.rb:98 Mutex lock
line /usr/lib/ruby/1.8/thread.rb:98 Mutex lock
line /usr/lib/ruby/1.8/thread.rb:99 Mutex lock
line /usr/lib/ruby/1.8/thread.rb:100 Mutex lock
97 def lock
98 while (Thread.critical = true; @locked)
99 @waiting.push Thread.current
100 Thread.stop
end
@locked = true
Thread.critical = false
self
end
line /usr/lib/ruby/1.8/webrick/server.rb:90 WEBrick::GenericServer start
line /usr/lib/ruby/1.8/webrick/server.rb:91 WEBrick::GenericServer start
line /usr/lib/ruby/1.8/webrick/server.rb:91 WEBrick::GenericServer start
line /usr/lib/ruby/1.8/webrick/server.rb:90 WEBrick::GenericServer start
line /usr/lib/ruby/1.8/webrick/server.rb:91 WEBrick::GenericServer start
while @status == :Running
90 begin
91 if svrs = IO.select(@listeners, nil, nil, 2.0)
svrs[0].each{|svr|
@tokens.pop # blocks while no token is there.
if sock = accept_client(svr)
th = start_thread(sock, &block)
th[:WEBrickThread] = true
thgroup.add(th)
else
@tokens.push(nil)
end
}
end
It seemed to be stuck in that loop there, waiting for something... another web request perhaps (I thought it was already in the middle of serving one though!)?
The same trace, only this time with my new Ruby Unroller:
Actually logging query: 'INSERT INTO application_log_entries ("message", "message_class", "level", "application", "created_at") VALUES('render_with_rails_profiler: 0.0192890167236328', 'String', 'INFO', 'Rails Profiler', '2007-04-11 12:11:18')'
| | | RailsProfiler::logger.info "log_with_rails_profiler: #{runtime} (sql = #{sql.strip}" | ./script/../config/../../lib/rails_profiler.rb:43
| | | + calling RailsProfiler::logger
| | | / | ...ctivesupport/lib/active_support/core_ext/module/attribute_accessors.rb:11
| | | | def self.#{sym} | ...ctivesupport/lib/active_support/core_ext/module/attribute_accessors.rb:12
| | | \ (returning) @@#{sym} | ...ctivesupport/lib/active_support/core_ext/module/attribute_accessors.rb:13
| | | + calling #<Log4r::Logger:0xb75a34c8>::info
| | | / (eval) | (eval):2
| | | | (eval) | (eval):3
| | | | (eval) | (eval):5
| | | | (eval) | (eval):6
| | | | + calling Log4r::LogEvent::initialize
| | | | / def initialize(level, logger, tracer, data) | /usr/lib/ruby/gems/1.8/gems/log4r-1.0.5/src/log4r/logevent.rb:23
| | | | | @level, @tracer, @data = level, tracer, data | /usr/lib/ruby/gems/1.8/gems/log4r-1.0.5/src/log4r/logevent.rb:24
| | | | | @name, @fullname = logger.name, logger.fullname | /usr/lib/ruby/gems/1.8/gems/log4r-1.0.5/src/log4r/logevent.rb:25
| | | | \ (returning) @level, @tracer, @data = level, tracer, data | /usr/lib/ruby/gems/1.8/gems/log4r-1.0.5/src/log4r/logevent.rb:24
| | | | (eval) | (eval):8
| | | | + calling #<DatabaseLog4r::DeferrableDatabaseOutputter:0xb759a8c8>::info
| | | | / (eval) | (eval):2
| | | | | (eval) | (eval):3
| | | | | + calling Log4r::Outputter::canonical_log
| | | | | / def canonical_log(logevent) | /usr/lib/ruby/gems/1.8/gems/log4r-1.0.5/src/log4r/outputter/outputter.rb:107
| | | | | | synch { write(format(logevent)) } | /usr/lib/ruby/gems/1.8/gems/log4r-1.0.5/src/log4r/outputter/outputter.rb:108
| | | | | | + calling Log4r::Outputter::synch
| | | | | | / def synch; @mutex.synchronize { yield } end | /usr/lib/ruby/gems/1.8/gems/log4r-1.0.5/src/log4r/outputter/outputter.rb:128
| | | | | | | def synch; @mutex.synchronize { yield } end | /usr/lib/ruby/gems/1.8/gems/log4r-1.0.5/src/log4r/outputter/outputter.rb:128
| | | | | | | + calling Mutex::synchronize
| | | | | | | / def synchronize | /usr/lib/ruby/1.8/thread.rb:132
| | | | | | | | lock | /usr/lib/ruby/1.8/thread.rb:133
| | | | | | | | + calling Mutex::lock
| | | | | | | | / def lock | /usr/lib/ruby/1.8/thread.rb:97
| | | | | | | | | while (Thread.critical = true; @locked) | /usr/lib/ruby/1.8/thread.rb:98
| | | | | | | | | @waiting.push Thread.current | /usr/lib/ruby/1.8/thread.rb:99
| | | | | | | | | Thread.stop | /usr/lib/ruby/1.8/thread.rb:100
| | | | | | | | | begin | /usr/lib/ruby/1.8/webrick/server.rb:90
| | | | | | | | | if svrs = IO.select(@listeners, nil, nil, 2.0) | /usr/lib/ruby/1.8/webrick/server.rb:91
| | | | | | | | | begin | /usr/lib/ruby/1.8/webrick/server.rb:90
| | | | | | | | | if svrs = IO.select(@listeners, nil, nil, 2.0) | /usr/lib/ruby/1.8/webrick/server.rb:91
| | | | | | | | | begin | /usr/lib/ruby/1.8/webrick/server.rb:90
| | | | | | | | | if svrs = IO.select(@listeners, nil, nil, 2.0) | /usr/lib/ruby/1.8/webrick/server.rb:91
| | | | | | | | | begin | /usr/lib/ruby/1.8/webrick/server.rb:90
| | | | | | | | | if svrs = IO.select(@listeners, nil, nil, 2.0) | /usr/lib/ruby/1.8/webrick/server.rb:91
| | | | | | | | | begin | /usr/lib/ruby/1.8/webrick/server.rb:90
| | | | | | | | | if svrs = IO.select(@listeners, nil, nil, 2.0) | /usr/lib/ruby/1.8/webrick/server.rb:91
| | | | | | | | | begin | /usr/lib/ruby/1.8/webrick/server.rb:90
| | | | | | | | | if svrs = IO.select(@listeners, nil, nil, 2.0) | /usr/lib/ruby/1.8/webrick/server.rb:91
| | | | | | | | | block.call | ...ith_extensions-0.0.13/lib/qualitysmith_extensions/kernel/trap_chain.rb:16
| | | | | | | | | trap_chain("INT") { set_trace_func(nil) } | /home/tyler/code/gemables/code_unroller/lib/code_unroller.rb:57
[2007-04-11 12:11:32] INFO going to shutdown ...
deadlock 0xb767d240: sleep:- - /usr/lib/ruby/1.8/thread.rb:100
deadlock 0xb7f0d7d4: sleep:J(0xb767d240) (main) - /usr/lib/ruby/1.8/webrick/server.rb:113
My best guess -- although the trace doesn't really show this, unfortunately -- is that we get to somewhere that does a logger.info, which takes out a lock and then starts to log something, but before that call to logger.info returns (that is, while we are still inside of it), we generate another call to logger.info -- recursion! This call again tries to take out the lock but ends up blocking because the previous call to the same method already has the lock! So the inner method call blocks, waiting for the lock to be released. But it can't ever be released, because it is owned by the outer call and we can't return from the inner call because we're still waiting for the lock to be released. I guess this is what they call "deadlock".
That thread blocks, but it is apparently just one thread. Execution continues in /usr/lib/ruby/1.8/webrick/server.rb, which is running in another thread. This thread, however, has nothing to do; it's just sitting there waiting for a web request.
It looks like the execution trace provides a hint as to what the problem might be, but it does not actually show the complete problem (recursion where there should not be recursion). I'm afraid that's because at the point we start the logging, the method has already been called once (higher up in the call stack) and the lock has already been obtained. The execution trace doesn't show that. It only shows us going up to the point where it tries to obtain the lock again and then blocks.
I'm pretty sure by now that this is the case, but I want to see evidence that the semaphore had already been locked.
So which method was being called recursively?? I was assuming it was log_with_rails_profiler... that's why I enabled tracing within that block. Because that would have showed us if another call to that method occurred while we were still in that method (before we had returned from it). However, the execution trace failed to show that this method is recursive. So did a backtrace, when I put a pp caller(0) at the top of the method.
Actually logging query: 'INSERT INTO application_log_entries ("message", "message_class", "level", "application", "created_at") VALUES('render_with_rails_profiler: 0.0196390151977539', 'String', 'INFO', 'Rails Profiler', '2007-04-11 14:04:31')'
["./script/../config/../../lib/rails_profiler.rb:43:in `log'",
"./script/../config/../vendor/rails/activesupport/lib/active_support/core_ext/object/misc.rb:23:in `returning'",
"./script/../config/../../lib/rails_profiler.rb:36:in `log'",
"./script/../config/../vendor/rails/activerecord/lib/active_record/connection_adapters/sqlite_adapter.rb:145:in `execute'",
"./script/../config/../vendor/rails/activerecord/lib/active_record/connection_adapters/sqlite_adapter.rb:346:in `catch_schema_changes'",
"./script/../config/../vendor/rails/activerecord/lib/active_record/connection_adapters/sqlite_adapter.rb:145:in `execute'",
"./script/../config/../vendor/rails/activerecord/lib/active_record/connection_adapters/sqlite_adapter.rb:160:in `insert'",
"./script/../config/../vendor/rails/activerecord/lib/active_record/base.rb:1811:in `create_without_callbacks'",
"./script/../config/../vendor/rails/activerecord/lib/active_record/callbacks.rb:254:in `create_without_timestamps'",
"./script/../config/../vendor/rails/activerecord/lib/active_record/timestamp.rb:39:in `create'",
"./script/../config/../vendor/rails/activerecord/lib/active_record/base.rb:1789:in `create_or_update_without_callbacks'",
"./script/../config/../vendor/rails/activerecord/lib/active_record/callbacks.rb:242:in `create_or_update'",
"./script/../config/../vendor/rails/activerecord/lib/active_record/base.rb:1551:in `save_without_validation!'",
"./script/../config/../vendor/rails/activerecord/lib/active_record/validations.rb:762:in `save_without_transactions!'",
"./script/../config/../vendor/rails/activerecord/lib/active_record/transactions.rb:133:in `save!'",
"./script/../config/../vendor/rails/activerecord/lib/active_record/connection_adapters/abstract/database_statements.rb:59:in `transaction'",
"./script/../config/../vendor/rails/activerecord/lib/active_record/transactions.rb:95:in `transaction'",
"./script/../config/../vendor/rails/activerecord/lib/active_record/transactions.rb:121:in `transaction'",
"./script/../config/../vendor/rails/activerecord/lib/active_record/transactions.rb:133:in `save!'",
"./script/../config/../vendor/plugins/database_log4r/lib/log4r/deferrable_database_outputter.rb:119:in `write_without_deferring'",
"./script/../config/../vendor/rails/activerecord/lib/active_record/callbacks.rb:226:in `initialize'",
"./script/../config/../vendor/plugins/database_log4r/lib/log4r/deferrable_database_outputter.rb:115:in `new'",
"./script/../config/../vendor/plugins/database_log4r/lib/log4r/deferrable_database_outputter.rb:115:in `write_without_deferring'",
"./script/../config/../vendor/rails/activerecord/lib/active_record/base.rb:867:in `silence'",
"./script/../config/../vendor/plugins/database_log4r/lib/log4r/deferrable_database_outputter.rb:114:in `write_without_deferring'",
"./script/../config/../vendor/plugins/database_log4r/lib/log4r/deferrable_database_outputter.rb:62:in `write'",
"/usr/lib/ruby/gems/1.8/gems/log4r-1.0.5/src/log4r/outputter/outputter.rb:108:in `canonical_log'",
"/usr/lib/ruby/gems/1.8/gems/log4r-1.0.5/src/log4r/outputter/outputter.rb:128:in `synch'",
"/usr/lib/ruby/1.8/thread.rb:135:in `synchronize'",
"/usr/lib/ruby/gems/1.8/gems/log4r-1.0.5/src/log4r/outputter/outputter.rb:128:in `synch'",
"/usr/lib/ruby/gems/1.8/gems/log4r-1.0.5/src/log4r/outputter/outputter.rb:108:in `canonical_log'",
"/usr/lib/ruby/gems/1.8/gems/log4r-1.0.5/src/log4r/outputter/outputterfactory.rb:50:in `info'",
"/usr/lib/ruby/gems/1.8/gems/log4r-1.0.5/src/log4r/loggerfactory.rb:83:in `info'",
"/usr/lib/ruby/gems/1.8/gems/log4r-1.0.5/src/log4r/loggerfactory.rb:83:in `each'",
"/usr/lib/ruby/gems/1.8/gems/log4r-1.0.5/src/log4r/loggerfactory.rb:83:in `info'",
"./script/../config/../../lib/rails_profiler.rb:22:in `render'",
"./script/../config/../vendor/rails/actionpack/lib/action_controller/base.rb:1096:in `perform_action_without_filters'",
"./script/../config/../vendor/rails/actionpack/lib/action_controller/filters.rb:632:in `call_filter'",
"./script/../config/../vendor/rails/actionpack/lib/action_controller/filters.rb:619:in `perform_action_without_benchmark'",
"./script/../config/../vendor/rails/actionpack/lib/action_controller/benchmarking.rb:66:in `perform_action_without_rescue'",
"/usr/lib/ruby/1.8/benchmark.rb:293:in `measure'",
"./script/../config/../vendor/rails/actionpack/lib/action_controller/benchmarking.rb:66:in `perform_action_without_rescue'",
"./script/../config/../vendor/rails/actionpack/lib/action_controller/rescue.rb:83:in `perform_action_without_rails_profiler'",
"./script/../config/../../lib/rails_profiler.rb:13:in `perform_action'",
...
There is no (logging-related) recursion to speak of here -- none. And yet the application seems to hang immediately after it gets there.
Where else could it be happening? Well, where is the call to synchronize? It looks like it is coming from canonical_log (which is called by logger.info -- aha!). So if I do a backtrace there and see that this method was called recursively, I will be content that I have found the actual problem.
/usr/lib/ruby/gems/1.8/gems/log4r-1.0.5/src/log4r/outputter/outputter.rb
def canonical_log(logevent)
pp caller(0)
synch { write(format(logevent)) }
end
Actually logging query: 'INSERT INTO application_log_entries ("message", "message_class", "level", "application", "created_at") VALUES('render_with_rails_profiler: 0.0194079875946045', 'String', 'INFO', 'Rails Profiler', '2007-04-11 14:09:19')'
["/usr/lib/ruby/gems/1.8/gems/log4r-1.0.5/src/log4r/outputter/outputter.rb:108:in `canonical_log'", # <----------
"/usr/lib/ruby/gems/1.8/gems/log4r-1.0.5/src/log4r/outputter/outputterfactory.rb:50:in `info'",
"/usr/lib/ruby/gems/1.8/gems/log4r-1.0.5/src/log4r/loggerfactory.rb:83:in `info'",
"/usr/lib/ruby/gems/1.8/gems/log4r-1.0.5/src/log4r/loggerfactory.rb:83:in `each'",
"/usr/lib/ruby/gems/1.8/gems/log4r-1.0.5/src/log4r/loggerfactory.rb:83:in `info'",
"./script/../config/../../lib/rails_profiler.rb:44:in `log'",
"./script/../config/../vendor/rails/activesupport/lib/active_support/core_ext/object/misc.rb:23:in `returning'",
"./script/../config/../../lib/rails_profiler.rb:36:in `log'",
"./script/../config/../vendor/rails/activerecord/lib/active_record/connection_adapters/sqlite_adapter.rb:145:in `execute'",
"./script/../config/../vendor/rails/activerecord/lib/active_record/connection_adapters/sqlite_adapter.rb:346:in `catch_schema_changes'",
"./script/../config/../vendor/rails/activerecord/lib/active_record/connection_adapters/sqlite_adapter.rb:145:in `execute'",
"./script/../config/../vendor/rails/activerecord/lib/active_record/connection_adapters/sqlite_adapter.rb:160:in `insert'",
"./script/../config/../vendor/rails/activerecord/lib/active_record/base.rb:1811:in `create_without_callbacks'",
"./script/../config/../vendor/rails/activerecord/lib/active_record/callbacks.rb:254:in `create_without_timestamps'",
"./script/../config/../vendor/rails/activerecord/lib/active_record/timestamp.rb:39:in `create'",
"./script/../config/../vendor/rails/activerecord/lib/active_record/base.rb:1789:in `create_or_update_without_callbacks'",
"./script/../config/../vendor/rails/activerecord/lib/active_record/callbacks.rb:242:in `create_or_update'",
"./script/../config/../vendor/rails/activerecord/lib/active_record/base.rb:1551:in `save_without_validation!'",
"./script/../config/../vendor/rails/activerecord/lib/active_record/validations.rb:762:in `save_without_transactions!'",
"./script/../config/../vendor/rails/activerecord/lib/active_record/transactions.rb:133:in `save!'",
"./script/../config/../vendor/rails/activerecord/lib/active_record/connection_adapters/abstract/database_statements.rb:59:in `transaction'",
"./script/../config/../vendor/rails/activerecord/lib/active_record/transactions.rb:95:in `transaction'",
"./script/../config/../vendor/rails/activerecord/lib/active_record/transactions.rb:121:in `transaction'",
"./script/../config/../vendor/rails/activerecord/lib/active_record/transactions.rb:133:in `save!'",
"./script/../config/../vendor/plugins/database_log4r/lib/log4r/deferrable_database_outputter.rb:119:in `write_without_deferring'",
"./script/../config/../vendor/rails/activerecord/lib/active_record/callbacks.rb:226:in `initialize'",
"./script/../config/../vendor/plugins/database_log4r/lib/log4r/deferrable_database_outputter.rb:115:in `new'",
"./script/../config/../vendor/plugins/database_log4r/lib/log4r/deferrable_database_outputter.rb:115:in `write_without_deferring'",
"./script/../config/../vendor/rails/activerecord/lib/active_record/base.rb:867:in `silence'",
"./script/../config/../vendor/plugins/database_log4r/lib/log4r/deferrable_database_outputter.rb:114:in `write_without_deferring'",
"./script/../config/../vendor/plugins/database_log4r/lib/log4r/deferrable_database_outputter.rb:62:in `write'",
"/usr/lib/ruby/gems/1.8/gems/log4r-1.0.5/src/log4r/outputter/outputter.rb:109:in `canonical_log'",
"/usr/lib/ruby/gems/1.8/gems/log4r-1.0.5/src/log4r/outputter/outputter.rb:129:in `synch'",
"/usr/lib/ruby/1.8/thread.rb:135:in `synchronize'",
"/usr/lib/ruby/gems/1.8/gems/log4r-1.0.5/src/log4r/outputter/outputter.rb:129:in `synch'",
"/usr/lib/ruby/gems/1.8/gems/log4r-1.0.5/src/log4r/outputter/outputter.rb:109:in `canonical_log'", # <----------
"/usr/lib/ruby/gems/1.8/gems/log4r-1.0.5/src/log4r/outputter/outputterfactory.rb:50:in `info'",
"/usr/lib/ruby/gems/1.8/gems/log4r-1.0.5/src/log4r/loggerfactory.rb:83:in `info'",
"/usr/lib/ruby/gems/1.8/gems/log4r-1.0.5/src/log4r/loggerfactory.rb:83:in `each'",
"/usr/lib/ruby/gems/1.8/gems/log4r-1.0.5/src/log4r/loggerfactory.rb:83:in `info'",
"./script/../config/../../lib/rails_profiler.rb:22:in `render'",
"./script/../config/../vendor/rails/actionpack/lib/action_controller/base.rb:1096:in `perform_action_without_filters'",
"./script/../config/../vendor/rails/actionpack/lib/action_controller/filters.rb:632:in `call_filter'",
"./script/../config/../vendor/rails/actionpack/lib/action_controller/filters.rb:619:in `perform_action_without_benchmark'",
"./script/../config/../vendor/rails/actionpack/lib/action_controller/benchmarking.rb:66:in `perform_action_without_rescue'",
"/usr/lib/ruby/1.8/benchmark.rb:293:in `measure'",
"./script/../config/../vendor/rails/actionpack/lib/action_controller/benchmarking.rb:66:in `perform_action_without_rescue'",
"./script/../config/../vendor/rails/actionpack/lib/action_controller/rescue.rb:83:in `perform_action_without_rails_profiler'",
"./script/../config/../../lib/rails_profiler.rb:13:in `perform_action'",
"/usr/lib/ruby/1.8/benchmark.rb:293:in `measure'",
"/usr/lib/ruby/1.8/benchmark.rb:307:in `realtime'",
"./script/../config/../../lib/rails_profiler.rb:12:in `perform_action'",
"./script/../config/../vendor/rails/actionpack/lib/action_controller/base.rb:430:in `send'",
"./script/../config/../vendor/rails/actionpack/lib/action_controller/base.rb:430:in `process_without_filters'",
"./script/../config/../vendor/rails/actionpack/lib/action_controller/filters.rb:624:in `process_without_session_management_support'",
"./script/../config/../vendor/rails/actionpack/lib/action_controller/session_management.rb:114:in `process'",
"./script/../config/../vendor/rails/actionpack/lib/action_controller/base.rb:330:in `process'",
"./script/../config/../vendor/rails/railties/lib/dispatcher.rb:41:in `dispatch'",
"./script/../config/../vendor/rails/railties/lib/webrick_server.rb:113:in `handle_dispatch'",
"./script/../config/../vendor/rails/railties/lib/webrick_server.rb:79:in `service'",
"/usr/lib/ruby/1.8/webrick/httpserver.rb:104:in `service'",
"/usr/lib/ruby/1.8/webrick/httpserver.rb:65:in `run'",
"/usr/lib/ruby/1.8/webrick/server.rb:173:in `start_thread'",
"/usr/lib/ruby/1.8/webrick/server.rb:162:in `start'",
"/usr/lib/ruby/1.8/webrick/server.rb:162:in `start_thread'",
"/usr/lib/ruby/1.8/webrick/server.rb:95:in `start'",
"/usr/lib/ruby/1.8/webrick/server.rb:92:in `each'",
"/usr/lib/ruby/1.8/webrick/server.rb:92:in `start'",
"/usr/lib/ruby/1.8/webrick/server.rb:23:in `start'",
"/usr/lib/ruby/1.8/webrick/server.rb:82:in `start'",
"./script/../config/../vendor/rails/railties/lib/webrick_server.rb:63:in `dispatch'",
"./script/../config/../vendor/rails/railties/lib/commands/servers/webrick.rb:59",
"/usr/lib/ruby/site_ruby/1.8/rubygems/custom_require.rb:27:in `gem_original_require'",
"/usr/lib/ruby/site_ruby/1.8/rubygems/custom_require.rb:27:in `require'",
"./script/../config/../vendor/rails/activesupport/lib/active_support/dependencies.rb:495:in `require'",
"./script/../config/../vendor/rails/activesupport/lib/active_support/dependencies.rb:342:in `new_constants_in'",
"./script/../config/../vendor/rails/activesupport/lib/active_support/dependencies.rb:495:in `require'",
"./script/../config/../vendor/rails/railties/lib/commands/server.rb:39",
"./script/server:4:in `require'",
"./script/server:4"]
[2007-04-11 14:09:30] INFO going to shutdown ...
deadlock 0xb7554120: sleep:- - /usr/lib/ruby/1.8/thread.rb:100
deadlock 0xb7554120: sleep:- - /usr/lib/ruby/1.8/thread.rb:100
deadlock 0xb7fca7d0: sleep:J(0xb7554120) (main) - /usr/lib/ruby/1.8/webrick/server.rb:113
fatal: Thread(0xb7fca7d0): deadlock
Oh man, I was totally right!
Cool, so now that I know logger.info was being called twice (recursively), how do we prevent it from being called recursively? Ideally, I think, I would just modify Log4r class itself to avoid trying to take out the lock if we (the current thread) is already within canonical_log. I think the synchronize is there to prevent other threads from running that code at the time as the current thread -- that is, to make it "thread-safe" -- but I don't think it takes into account at all the possibility of deadlock being caused by unintentionally calling this method recursively.
To do that, we'd need to add code to abort the current log attempt if we (the current thread) is already in the middle of one. To do that, we'd need a thread-local variable (or we could detect recursion by inspecting and parsing caller(0), but that seems kind of ugly!).
I bet something like this would work:
def canonical_log(logevent)
return if Thread.current[:already_attempting_to_log];
Thread.current[:already_attempting_to_log] = true
synch { write(format(logevent)) }
Thread.current[:already_attempting_to_log] = false
end
Anyway, that's not really an option, because that's a 3rd-party library, so I'll just have to work around this from within my own library. Here's how I prevented recursion:
class DeferrableDatabaseOutputter < Log4r::Outputter
@@prevent_logging = false
mattr_reader :prevent_logging
# This is to prevent recursion -- logging an event that happens while we're already logging an event.
def prevent_logging(&block)
@@prevent_logging = true
yield
@@prevent_logging = false
end
def write(data)
begin
prevent_logging do
write_without_deferring data
end
rescue Exception => error
defer data
end
end
def log_with_rails_profiler(sql, name, &block)
returning(return_value = nil) do
runtime = Benchmark.realtime do
return_value = log_without_rails_profiler(sql, name, &block)
end
unless DatabaseLog4r::DeferrableDatabaseOutputter::prevent_logging
RailsProfiler::logger.info "log_with_rails_profiler: #{runtime} (sql = #{sql.strip}"
end
end
end
The problem was apparently that we were calling some log method recursively, causing a deadlock. I should have foreseen that problem, or at least seen it a lot sooner than I did, but I did not.
It's frustrating that the code trace didn't seem to point to the real problem -- the code trace did not show that there was infinite loop at all.!