Ruby / Debugging some concurrency problems while writing RailsProfiler

From WhyNotWiki
Jump to: navigation, search

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.

Contents

Initial observations

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

What happens when there are no requests?

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.

What happens when there is 1 request?

Let's step things up a notch and actually do a request!

  • start server
    • 20070409132419_3e279c26e567002dc0685b372b800b2e.log appears
    • application_log_entries empty
  • request http://riblet:3000/slow/template
    • 20070409132419_3e279c26e567002dc0685b372b800b2e.log still there
    • application_log_entries still empty
  • interrupt server
    • 20070409132419_3e279c26e567002dc0685b372b800b2e.log still there
    • application_log_entries has 1 row (should have 2?)
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

Seems to be server specific

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

Getting closer...

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'",

The problem is the logging from ActiveRecord#log_with_rails_profiler

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!

Found the problem maybe

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


Bring out the big guns: set_trace_func

[set_trace_func (category)]

          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


Best guess

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.


Proving it

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!

Solution

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

Postmortem

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.!

Ads
Personal tools