EventMachine.defer and ActiveRecord connection pool?

ruby-talk
1

Hello,

I'm writing a server with EM. I'm having some long-running tasks, so I'm
deferring those requests using EM.defer.

However, after 5 such deferred requests AR suddently stops working...
I'm using AR 2.3.4, so concurrency shouldn't be a problem. Gems
configuration:

REQUIRED_GEMS = [
  ['mysql', '>=2.7.0'],
  ['activerecord', '=2.3.4'],
  ['activesupport', '=2.3.4'],
  ['eventmachine', '=0.12.6'],
  ['json', '>=1.1.6'],
  "daemons"
]

Anyway, as you can see it happens after 5 requests (just simulated
action, one select query):

[2009-09-09 23:32:35|main|info ] Starting server...
[2009-09-09 23:32:36|main|info ] [Resources manager]
[Resources manager END] Time taken: 0.031 seconds
[2009-09-09 23:32:37|main|info ] [Resources manager]
[Resources manager END] Time taken: 0.016 seconds
[2009-09-09 23:32:38|main|info ] [Resources manager]
[Resources manager END] Time taken: 0.000 seconds
[2009-09-09 23:32:39|main|info ] [Resources manager]
[Resources manager END] Time taken: 0.016 seconds
[2009-09-09 23:32:40|main|info ] [Resources manager]
[Resources manager END] Time taken: 0.000 seconds
[2009-09-09 23:32:41|main|info ] [Resources manager]
[Resources manager END with EXCEPTION]
#<ActiveRecord::ConnectionTimeoutError: c
ould not obtain a database connection within 5 seconds. The max pool
size is cu
rrently 5; consider increasing it.>

I'm running this code:
EventMachine::run {
  EventMachine::start_server "0.0.0.0", 843, FlashPolicyServer
  EventMachine::start_server "0.0.0.0", CONFIG['port'], GameServer

  # Resources manager
  EventMachine::PeriodicTimer.new(CONFIG['resources_manager.period']) do
    SingletonBlock.run("Resources manager", nil, nil, :defer => true) do
      "Time taken: %4.3f seconds" % Benchmark.realtime {
ResourcesEntry.tick }
    end
  end
}

Where SingletonBlock is:
# Class for running one block of same name at a time
class SingletonBlock
  @@running = {}
  @@lock = Mutex.new

  class << self
    def run(name, operation=nil, callback=nil, options={}, &block)
      unless running?(name)
        operation ||= block

        options.reverse_merge!(:defer => true)
        if options[:defer]
          EventMachine.defer(
            proc do
              SingletonBlock.started(name)
              LOGGER.block(name) { operation.call }
            end,
            proc do
              LOGGER.block("#{name} CALLBACK") { callback.call } if
callback
              SingletonBlock.finished(name)
            end
          )
        else
          SingletonBlock.started(name)
          LOGGER.block(name) { operation.call }
          LOGGER.block("#{name} CALLBACK") { callback.call } if callback
          SingletonBlock.finished(name)
        end
      end
    end

    def running?(name)
      @@lock.synchronize do
        ! @@running[name].nil?
      end
    end

    def started(name)
      @@lock.synchronize do
        @@running[name] = true
      end
    end

    def finished(name)
      @@lock.synchronize do
        @@running.delete(name)
      end
    end
  end
end

If I don't use EM.defer - everything works fine.

Googled - nothing found. Any ideas?

···

--
Posted via http://www.ruby-forum.com/.

2

I have a guess. I guess that your CONFIG['resources_manager.period'] is set to 0 or quite close to it. If so, the PeriodicTimer is probably firing on every "crank" of the EM reactor which is deferring more and more of your singleton blocks. There isn't any time left over to clean up connections to the ActiveRecord connection pool and you are running out.

Trying making your 'resources_manager.period' 1 second and see if it still blows up.

BTW, EM#defer uses a threadpool (size of 20). It enqueues each #defer request to a Queue (thread safe). As each thread in the pool completes its task it pops the next one off the queue.

If you flood the queue (which I suspect) then the newest tasks are going to starve while waiting for the previous ones to complete. As each task completes, try outputting the number of tasks in your @@running hash and see if it is a large number.

cr

···

On Sep 9, 2009, at 3:37 PM, Artūras Šlajus wrote:

Hello,

I'm writing a server with EM. I'm having some long-running tasks, so I'm
deferring those requests using EM.defer.

However, after 5 such deferred requests AR suddently stops working...
I'm using AR 2.3.4, so concurrency shouldn't be a problem. Gems
configuration:

REQUIRED_GEMS = [
['mysql', '>=2.7.0'],
['activerecord', '=2.3.4'],
['activesupport', '=2.3.4'],
['eventmachine', '=0.12.6'],
['json', '>=1.1.6'],
"daemons"
]

Anyway, as you can see it happens after 5 requests (just simulated
action, one select query):

[2009-09-09 23:32:35|main|info ] Starting server...
[2009-09-09 23:32:36|main|info ] [Resources manager]
[Resources manager END] Time taken: 0.031 seconds
[2009-09-09 23:32:37|main|info ] [Resources manager]
[Resources manager END] Time taken: 0.016 seconds
[2009-09-09 23:32:38|main|info ] [Resources manager]
[Resources manager END] Time taken: 0.000 seconds
[2009-09-09 23:32:39|main|info ] [Resources manager]
[Resources manager END] Time taken: 0.016 seconds
[2009-09-09 23:32:40|main|info ] [Resources manager]
[Resources manager END] Time taken: 0.000 seconds
[2009-09-09 23:32:41|main|info ] [Resources manager]
[Resources manager END with EXCEPTION]
#<ActiveRecord::ConnectionTimeoutError: c
ould not obtain a database connection within 5 seconds. The max pool
size is cu
rrently 5; consider increasing it.>

3

Chuck Remes wrote:

I have a guess. I guess that your CONFIG['resources_manager.period']
is set to 0 or quite close to it. If so, the PeriodicTimer is probably
firing on every "crank" of the EM reactor which is deferring more and
more of your singleton blocks. There isn't any time left over to clean
up connections to the ActiveRecord connection pool and you are running
out.

Nop, it's 1 second for testing. It happens even if you set it to 1
minute. Loads of time to clean up and still...

BTW, EM#defer uses a threadpool (size of 20). It enqueues each #defer
request to a Queue (thread safe). As each thread in the pool completes
its task it pops the next one off the queue.

If you flood the queue (which I suspect) then the newest tasks are
going to starve while waiting for the previous ones to complete. As
each task completes, try outputting the number of tasks in your
@@running hash and see if it is a large number.

The whole purpose of @@running hash is to ensure that same task won't be
running in parallel. I don't need two resource managers messing up
values with database, so it skips that block completely if same task is
still running.

···

--
Posted via http://www.ruby-forum.com/\.

4

Hmm, that is curious. Then here's another guess...

I haven't used rails in a long time, but I recall that AR required a call to verify_connections! or something crazy when running with threads. This is because each call opens its own connection to the database but there is (or was) no automatic close. So it could be that your threaded calls are opening up db connections and never closing them. You need to figure out how to close the connection or get AR to figure out that the others are stale or should be garbage collected.

cr

···

On Sep 9, 2009, at 4:14 PM, Artūras Šlajus wrote:

Chuck Remes wrote:

I have a guess. I guess that your CONFIG['resources_manager.period']
is set to 0 or quite close to it. If so, the PeriodicTimer is probably
firing on every "crank" of the EM reactor which is deferring more and
more of your singleton blocks. There isn't any time left over to clean
up connections to the ActiveRecord connection pool and you are running
out.

Nop, it's 1 second for testing. It happens even if you set it to 1
minute. Loads of time to clean up and still...

5

Chuck Remes wrote:

Nop, it's 1 second for testing. It happens even if you set it to 1
minute. Loads of time to clean up and still...

Hmm, that is curious. Then here's another guess...

I haven't used rails in a long time, but I recall that AR required a
call to verify_connections! or something crazy when running with
threads.

Tried this with no luck :slight_smile: Thou it gave me some idea for googling...

This is because each call opens its own connection to the
database but there is (or was) no automatic close. So it could be that
your threaded calls are opening up db connections and never closing
them. You need to figure out how to close the connection or get AR to
figure out that the others are stale or should be garbage collected.

It seems that ActiveRecord::Base.clear_reloadable_connections! in:

          EventMachine.defer(
            proc do
              SingletonBlock.started(name)
              LOGGER.block(name) { operation.call }
            end,
            proc do
              LOGGER.block("#{name} CALLBACK") { callback.call } if
callback
              SingletonBlock.finished(name)
              ActiveRecord::Base.clear_reloadable_connections!
            end
          )

actually helped :slight_smile:
(http://coderrr.wordpress.com/2009/01/12/rails-22-activerecord-connection-cleanup/\)

Thanks for ideas and help! :wink:

···

On Sep 9, 2009, at 4:14 PM, Artūras Šlajus wrote:

--
Posted via http://www.ruby-forum.com/\.

6

You are welcome. This made me curious so I looked a little deeper and found a better choice for you.

Look up #release_connection in ActiveRecord::ConnectionAdapters::ConnectionPool. It does exactly what you need whereas that call to #clear_reloadable_connections! might be doing unnecessary work.

Good luck.

cr

···

On Sep 9, 2009, at 4:43 PM, Artūras Šlajus wrote:

Chuck Remes wrote:

On Sep 9, 2009, at 4:14 PM, Artūras Šlajus wrote:

Nop, it's 1 second for testing. It happens even if you set it to 1
minute. Loads of time to clean up and still...

Hmm, that is curious. Then here's another guess...

I haven't used rails in a long time, but I recall that AR required a
call to verify_connections! or something crazy when running with
threads.

Tried this with no luck :slight_smile: Thou it gave me some idea for googling...

This is because each call opens its own connection to the
database but there is (or was) no automatic close. So it could be that
your threaded calls are opening up db connections and never closing
them. You need to figure out how to close the connection or get AR to
figure out that the others are stale or should be garbage collected.

It seems that ActiveRecord::Base.clear_reloadable_connections! in:

         EventMachine.defer(
           proc do
             SingletonBlock.started(name)
             LOGGER.block(name) { operation.call }
           end,
           proc do
             LOGGER.block("#{name} CALLBACK") { callback.call } if
callback
             SingletonBlock.finished(name)
             ActiveRecord::Base.clear_reloadable_connections!
           end
         )

actually helped :slight_smile:
(http://coderrr.wordpress.com/2009/01/12/rails-22-activerecord-connection-cleanup/\)

Thanks for ideas and help! :wink:

7

Chuck Remes wrote:

Look up #release_connection in
ActiveRecord::ConnectionAdapters::ConnectionPool. It does exactly what
you need whereas that call to #clear_reloadable_connections! might be
doing unnecessary work.

Unfortunately that doesn't work :slight_smile:

          EventMachine.defer(
            proc do
              SingletonBlock.started(name)
              LOGGER.block(name) { operation.call }
            end,
            proc do
              LOGGER.block("#{name} CALLBACK") { callback.call } if
callback
              SingletonBlock.finished(name)
              ActiveRecord::Base.connection_pool.release_connection
              #ActiveRecord::Base.clear_reloadable_connections!
            end
          )

Still hangs :slight_smile:

···

--
Posted via http://www.ruby-forum.com/\.

8

Artūras Šlajus wrote:

Chuck Remes wrote:

Look up #release_connection in
ActiveRecord::ConnectionAdapters::ConnectionPool. It does exactly what
you need whereas that call to #clear_reloadable_connections! might be
doing unnecessary work.

Unfortunately that doesn't work :slight_smile:

          EventMachine.defer(
            proc do
              SingletonBlock.started(name)
              LOGGER.block(name) { operation.call }
            end,
            proc do
              LOGGER.block("#{name} CALLBACK") { callback.call } if
callback
              SingletonBlock.finished(name)
              ActiveRecord::Base.connection_pool.release_connection
              #ActiveRecord::Base.clear_reloadable_connections!
            end
          )

Still hangs :slight_smile:

using
ActiveRecord::Base.connection_pool.release_connection
with jruby and with delayed_jobs running in same jvm

I was seeing hanging on long running methods with lots of queries.

I changed my invoke_job to the following and no more lockups

    def invoke_job
      begin
        payload_object.perform
      ensure
        ActiveRecord::Base.connection_pool.release_connection
      end
    end

Active Record's connection pool uses the thread_id to checkout
connections. if event machine is switching threads as it sees fit than
this probably won't work. you may have to rework the connection pool
to allow a better checkout checkin process.

···

--
Posted via http://www.ruby-forum.com/\.