Jobs stuck on mon_enter

[penso]

Hi,

I can't find the reason my jobs get stucked in mon_enter, I use connection_pool for delli and can't find how to fix it.

The stack looks like https://gist.github.com/penso/8c054b13c19123574bc1

2015-05-10T08:33:06.341Z 17056 TID-3lork WARN: /home/deploy/.rvm/rubies/ruby-2.1.5/lib/ruby/2.1.0/monitor.rb:185:in `lock'
/home/deploy/.rvm/rubies/ruby-2.1.5/lib/ruby/2.1.0/monitor.rb:185:in `mon_enter'
/home/deploy/.rvm/rubies/ruby-2.1.5/lib/ruby/2.1.0/monitor.rb:209:in `mon_synchronize'
/data/www/faast/shared/bundle/ruby/2.1.0/gems/activerecord-4.0.13/lib/active_record/connection_adapters/abstract/connection_pool.rb:271:in `active_connection?'
/data/www/faast/shared/bundle/ruby/2.1.0/gems/activerecord-4.0.13/lib/active_record/connection_adapters/abstract/connection_pool.rb:293:in `with_connection'
/data/www/faast/releases/20150509081300/app/worker/rss_parser_worker.rb:8:in `perform'
/data/www/faast/shared/bundle/ruby/2.1.0/gems/sidekiq-3.3.3/lib/sidekiq/processor.rb:75:in `execute_job'
/data/www/faast/shared/bundle/ruby/2.1.0/gems/sidekiq-3.3.3/lib/sidekiq/processor.rb:52:in `block (2 levels) in process'
/data/www/faast/shared/bundle/ruby/2.1.0/gems/sidekiq-3.3.3/lib/sidekiq/middleware/chain.rb:127:in `block in invoke'
/data/www/faast/shared/bundle/ruby/2.1.0/bundler/gems/sidekiq-throttler-f91a2c41a2f3/lib/sidekiq/throttler.rb:36:in `block in call'
/data/www/faast/shared/bundle/ruby/2.1.0/bundler/gems/sidekiq-throttler-f91a2c41a2f3/lib/sidekiq/throttler/rate_limit.rb:145:in `call'
/data/www/faast/shared/bundle/ruby/2.1.0/bundler/gems/sidekiq-throttler-f91a2c41a2f3/lib/sidekiq/throttler/rate_limit.rb:145:in `execute'
/data/www/faast/shared/bundle/ruby/2.1.0/bundler/gems/sidekiq-throttler-f91a2c41a2f3/lib/sidekiq/throttler.rb:43:in `call'
/data/www/faast/shared/bundle/ruby/2.1.0/gems/sidekiq-3.3.3/lib/sidekiq/middleware/chain.rb:129:in `block in invoke'
/data/www/faast/shared/bundle/ruby/2.1.0/gems/exception_notification-4.0.1/lib/exception_notification/sidekiq.rb:8:in `call'
/data/www/faast/shared/bundle/ruby/2.1.0/gems/sidekiq-3.3.3/lib/sidekiq/middleware/chain.rb:129:in `block in invoke'
/data/www/faast/shared/bundle/ruby/2.1.0/gems/sidekiq-3.3.3/lib/sidekiq/middleware/server/active_record.rb:6:in `call'
/data/www/faast/shared/bundle/ruby/2.1.0/gems/sidekiq-3.3.3/lib/sidekiq/middleware/chain.rb:129:in `block in invoke'
/data/www/faast/shared/bundle/ruby/2.1.0/gems/sidekiq-3.3.3/lib/sidekiq/middleware/server/retry_jobs.rb:74:in `call'
/data/www/faast/shared/bundle/ruby/2.1.0/gems/sidekiq-3.3.3/lib/sidekiq/middleware/chain.rb:129:in `block in invoke'
/data/www/faast/shared/bundle/ruby/2.1.0/gems/sidekiq-3.3.3/lib/sidekiq/middleware/server/logging.rb:11:in `block in call'
/data/www/faast/shared/bundle/ruby/2.1.0/gems/sidekiq-3.3.3/lib/sidekiq/logging.rb:24:in `with_context'
/data/www/faast/shared/bundle/ruby/2.1.0/gems/sidekiq-3.3.3/lib/sidekiq/middleware/server/logging.rb:7:in `call'
/data/www/faast/shared/bundle/ruby/2.1.0/gems/sidekiq-3.3.3/lib/sidekiq/middleware/chain.rb:129:in `block in invoke'
/data/www/faast/shared/bundle/ruby/2.1.0/gems/sidekiq-3.3.3/lib/sidekiq/middleware/chain.rb:132:in `call'
/data/www/faast/shared/bundle/ruby/2.1.0/gems/sidekiq-3.3.3/lib/sidekiq/middleware/chain.rb:132:in `invoke'
/data/www/faast/shared/bundle/ruby/2.1.0/gems/sidekiq-3.3.3/lib/sidekiq/processor.rb:51:in `block in process'
/data/www/faast/shared/bundle/ruby/2.1.0/gems/sidekiq-3.3.3/lib/sidekiq/processor.rb:98:in `stats'
/data/www/faast/shared/bundle/ruby/2.1.0/gems/sidekiq-3.3.3/lib/sidekiq/processor.rb:50:in `process'
/data/www/faast/shared/bundle/ruby/2.1.0/gems/celluloid-0.16.0/lib/celluloid/calls.rb:26:in `public_send'
/data/www/faast/shared/bundle/ruby/2.1.0/gems/celluloid-0.16.0/lib/celluloid/calls.rb:26:in `dispatch'
/data/www/faast/shared/bundle/ruby/2.1.0/gems/celluloid-0.16.0/lib/celluloid/calls.rb:122:in `dispatch'
/data/www/faast/shared/bundle/ruby/2.1.0/gems/celluloid-0.16.0/lib/celluloid/cell.rb:60:in `block in invoke'
/data/www/faast/shared/bundle/ruby/2.1.0/gems/celluloid-0.16.0/lib/celluloid/cell.rb:71:in `block in task'
/data/www/faast/shared/bundle/ruby/2.1.0/gems/celluloid-0.16.0/lib/celluloid/actor.rb:357:in `block in task'
/data/www/faast/shared/bundle/ruby/2.1.0/gems/celluloid-0.16.0/lib/celluloid/tasks.rb:57:in `block in initialize'
/data/www/faast/shared/bundle/ruby/2.1.0/gems/celluloid-0.16.0/lib/celluloid/tasks/task_fiber.rb:15:in `block in create'

And for information my Gemfile.lock is at https://gist.github.com/penso/f7ce18c92ee66d5cf96c - Any hint is appreciated.

[penso]

My perform method looks like the following, removing the ActiveRecord::Base.connection_pool.with_connection seems to fix it but I thought it was helping to make sure the connection was released.

def perform(id, method, *args)
ActiveRecord::Base.connection_pool.with_connection do
instance = RssFeedr.find(id)
instance.send(method, *args) if instance
end
rescue ActiveRecord::RecordNotFound
log "sidekiq: RssFeedr #{id} not found"
end

[mperham]

What's your AR pool size and Sidekiq concurrency?

On May 10, 2015, at 01:56, Fabien Penso notifications@github.com wrote:

My perform method looks like the following, removing the ActiveRecord::Base.connection_pool.with_connection seems to fix it but I thought it was helping to make sure the connection was released.

def perform(id, method, *args)
ActiveRecord::Base.connection_pool.with_connection do
instance = RssFeedr.find(id)
instance.send(method, *args) if instance
end
rescue ActiveRecord::RecordNotFound
log "sidekiq: RssFeedr #{id} not found"
end

—
Reply to this email directly or view it on GitHub.

[penso]

@mperham AR pool size is 60 and the Sidekiq concurrency is 2

[penso]

I should add it doesn't do this all the time, once a day maximum maybe.

[mperham]

I wonder if this isn't an AR pool bug. Can you upgrade Rails?

On May 10, 2015, at 05:25, Fabien Penso notifications@github.com wrote:

I should add it doesn't do this all the time, once a day maximum maybe.

—
Reply to this email directly or view it on GitHub.

[mperham]

Reopen if you have any more info that seems to implicate Sidekiq.