mongo-ruby-driver 1.6.2 dying with execution expired

[dB.]

I just upgraded the mongo ruby driver from 1.5.2 to 1.6.2 and after a few simultaneous requests I am getting "execution expired" on all my queries. The only unusual thing about this environment is that we're testing with a higher connection_timeout. 

After a few app restarts the errors seem to have gone away. But I wanted to bring this up before I move the code to production. Anyone else seen this after a 1.6.2 upgrade?

Here's the mongoid config.

  connect_timeout: 60

  allow_dynamic_fields: true

  parameterize_keys: true

  persist_in_safe_mode: true

  raise_not_found_error: true

  max_retries_on_connection_failure: 5

This is not a replica set, in this environment it's a single DB on mongohq. The database seems to be operating normally. 

Thanks,

dB.

/usr/ruby1.9.2/lib/ruby/1.9.1/thread.rb:71:in `sleep'
/usr/ruby1.9.2/lib/ruby/1.9.1/thread.rb:71:in `wait'
/app/.bundle/gems/ruby/1.9.1/gems/mongo-1.6.2/lib/mongo/util/pool.rb:298:in `block (2 levels) in checkout'
<internal:prelude>:10:in `synchronize'
/app/.bundle/gems/ruby/1.9.1/gems/mongo-1.6.2/lib/mongo/util/pool.rb:252:in `block in checkout'
/app/.bundle/gems/ruby/1.9.1/gems/mongo-1.6.2/lib/mongo/util/pool.rb:245:in `loop'
/app/.bundle/gems/ruby/1.9.1/gems/mongo-1.6.2/lib/mongo/util/pool.rb:245:in `checkout'
/app/.bundle/gems/ruby/1.9.1/gems/mongo-1.6.2/lib/mongo/connection.rb:500:in `checkout_writer'
/app/.bundle/gems/ruby/1.9.1/gems/mongo-1.6.2/lib/mongo/cursor.rb:524:in `checkout_socket_from_connection'
/app/.bundle/gems/ruby/1.9.1/gems/mongo-1.6.2/lib/mongo/cursor.rb:466:in `send_initial_query'
/app/.bundle/gems/ruby/1.9.1/gems/mongo-1.6.2/lib/mongo/cursor.rb:458:in `refresh'
/app/.bundle/gems/ruby/1.9.1/gems/mongo-1.6.2/lib/mongo/cursor.rb:128:in `next'
/app/.bundle/gems/ruby/1.9.1/gems/mongo-1.6.2/lib/mongo/collection.rb:288:in `find_one'
/app/.bundle/gems/ruby/1.9.1/gems/mongoid-2.4.8/lib/mongoid/collections/master.rb:25:in `block in find_one'
/app/.bundle/gems/ruby/1.9.1/gems/mongoid-2.4.8/lib/mongoid/collections/retry.rb:29:in `retry_on_connection_failure'
/app/.bundle/gems/ruby/1.9.1/gems/mongoid-2.4.8/lib/mongoid/collections/master.rb:24:in `find_one'
/app/.bundle/gems/ruby/1.9.1/gems/mongoid-2.4.8/lib/mongoid/collection.rb:60:in `find_one'
/app/.bundle/gems/ruby/1.9.1/gems/newrelic_rpm-3.3.3/lib/new_relic/agent/method_tracer.rb:491:in `block in find_one_with_trace_ActiveRecord_klass_find_one'
/app/.bundle/gems/ruby/1.9.1/gems/newrelic_rpm-3.3.3/lib/new_relic/agent/method_tracer.rb:242:in `trace_execution_scoped'
/app/.bundle/gems/ruby/1.9.1/gems/newrelic_rpm-3.3.3/lib/new_relic/agent/method_tracer.rb:486:in `find_one_with_trace_ActiveRecord_klass_find_one'
/app/.bundle/gems/ruby/1.9.1/gems/mongoid-2.4.8/lib/mongoid/contexts/mongo.rb:203:in `first'
/app/.bundle/gems/ruby/1.9.1/gems/mongoid-2.4.8/lib/mongoid/criteria.rb:45:in `first'

[Tyler Brock]

Hey dB,

Sorry you are having trouble.

What is the text of the line that has the actual error (before the stack trace)? The ruby driver doesn't throw any errors which have the text "execution expired".

Let me know and I can take a look, there were some changes to the networking code in 1.6.2 so it very well could be a bug but I want to make sure I know exactly what error you are seeing and why.

Thanks!

-Tyler

[Daniel Doubrovkine]

Ok. I lost the stack trace and I don't see the error anymore :( I would imagine it was a plain query from mongoid 2.4.8. I'll reopen this thread if I get it again. Thank you for your prompt response.

--
You received this message because you are subscribed to the Google Groups "mongodb-user" group.

To view this discussion on the web visit https://groups.google.com/d/msg/mongodb-user/-/Ff9jKyknhlkJ.

To post to this group, send email to mongod...@googlegroups.com.
To unsubscribe from this group, send email to mongodb-user...@googlegroups.com.
For more options, visit this group at http://groups.google.com/group/mongodb-user?hl=en.

--

dB. | Moscow - Geneva - Seattle - New York
dblock.org - @dblockdotorg

[Daniel Doubrovkine]

Ok, we definitely have a problem.

Our test environment hasn't had the timeout issue, but we moved the code into production and started seeing the following pattern: all the indicators are green except that queries suddenly take increasingly longer, clearly at the Ruby level. Then eventually we reach the Heroku 30 second limit per transaction and the requests are being killed. I am sorry, I really don't have anything better than this. This is a replica set at MongoHQ.

Out of 3 deployments in the last 24 hours this happened 3 times right after a new deploy.

Here're some pretty graphs.

Everything running ok for 12 hours, then suddenly response time degrades, timeouts. A heroku restart fixes it immediately: http://cl.ly/0U2p0F3T3l3D2b2o063F

Two deploys in a row exhibiting this problem: http://cl.ly/3b1r3F0w3T1z170S1X13

We're rolling back to 1.5.2, but please do let me know if there's anything else I can do to help.

-dB.

[Daniel Doubrovkine]

Has anyone experienced anything similar? Should I create a JIRA for this?

[Justin Dossey]

I've seen this behavior when the application or the driver are leaking connection pool entries. Once there are no more spaces available in the (broken) pool, you get a connection timeout.  The database isn't busy, your application isn't (very) busy, but nothing can happen until you restart the application and begin the process anew.

Justin Dossey

See also the IRC channel -- freenode.net#mongodb