EventMachine.defer and ActiveRecord connection pool?

Ruby
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?

2

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

REQUIRED_GEMS = [

[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 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

3

Chuck R. 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.

4

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

5

Chuck R. 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:

6

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

call to verify_connections! or something crazy when running with
It seems that ActiveRecord::Base.clear_reloadable_connections! in:
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:

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

7

Chuck R. 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:

8

Artūras Šlajus wrote:

Chuck R. 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.