EventMachine.defer and ActiveRecord connection pool?

[Artūras Šlajus]

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:eriodicTimer.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?

 

[Chuck Remes]

Hello,

I'm writing a server with EM. I'm having some long-running tasks, so =20=

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 =3D [
['mysql', '>=3D2.7.0'],
['activerecord', '=3D2.3.4'],
['activesupport', '=3D2.3.4'],
['eventmachine', '=3D0.12.6'],
['json', '>=3D1.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 have a guess. I guess that your CONFIG['resources_manager.period'] =20
is set to 0 or quite close to it. If so, the PeriodicTimer is probably =20=

firing on every "crank" of the EM reactor which is deferring more and =20=

more of your singleton blocks. There isn't any time left over to clean =20=

up connections to the ActiveRecord connection pool and you are running =20=

out.

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

BTW, EM#defer uses a threadpool (size of 20). It enqueues each #defer =20=

request to a Queue (thread safe). As each thread in the pool completes =20=

its task it pops the next one off the queue.

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

cr

 

[Artūras Šlajus]

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.

 

[Chuck Remes]

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 =20
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 =20
clean
up connections to the ActiveRecord connection pool and you are =20
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...

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 =20
call to verify_connections! or something crazy when running with =20
threads. This is because each call opens its own connection to the =20
database but there is (or was) no automatic close. So it could be that =20=

your threaded calls are opening up db connections and never closing =20
them. You need to figure out how to close the connection or get AR to =20=

figure out that the others are stale or should be garbage collected.

cr

 

[Artūras Šlajus]

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 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
(http://coderrr.wordpress.com/2009/01/12/rails-22-activerecord-connection-cleanup/)

Thanks for ideas and help!

 

[Chuck Remes]

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


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
= (http://coderrr.wordpress.com/2009/01/12/rails-22-activerecord-connection-=
cleanup/=20
)

Thanks for ideas and help!

You are welcome. This made me curious so I looked a little deeper and =20=

found a better choice for you.

Look up #release_connection in =20
ActiveRecord::ConnectionAdapters::ConnectionPool. It does exactly what =20=

you need whereas that call to #clear_reloadable_connections! might be =20=

doing unnecessary work.

Good luck.

cr

 

[Artūras Šlajus]

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

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

 

[Pete Brumm]

Unfortunately that doesn't work

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

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.