0

I am currently getting some awkward timeouts in my web application, and they are all pointing to my in my mongo database (I'm using MongoHQ). These timeouts happen during really quiet times (ie. 1 request per minute) and will happen for a few minutes and then stop.

So, I am trying to put in place some mongo monitoring. Does anyone have any suggestions? I'm thinking of writing a timer that just tests the following?

unless Mongo::Connection.from_uri(uri).ping['ok']
  # alert me  of db being down
end

My config settings are the following: 

@pool_size=1, @pool_timeout=5.0, @op_timeout=nil, @connect_timeout=nil,

Is there a better way to do this? or a better solution?

I am running ruby driver (mongo-1.6.2, since I use mongoid-2).

The exception I see is:

vendor/ruby-1.9.3/lib/ruby/1.9.1/thread.rb:71:in `sleep'
vendor/ruby-1.9.3/lib/ruby/1.9.1/thread.rb:71:in `wait'
vendor/bundle/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'
vendor/bundle/ruby/1.9.1/gems/mongo-1.6.2/lib/mongo/util/pool.rb:252:in `block in checkout'
vendor/bundle/ruby/1.9.1/gems/mongo-1.6.2/lib/mongo/util/pool.rb:245:in `loop'
vendor/bundle/ruby/1.9.1/gems/mongo-1.6.2/lib/mongo/util/pool.rb:245:in `checkout'
vendor/bundle/ruby/1.9.1/gems/mongo-1.6.2/lib/mongo/connection.rb:500:in `checkout_writer'
vendor/bundle/ruby/1.9.1/gems/mongo-1.6.2/lib/mongo/cursor.rb:524:in `checkout_socket_from_connection'
vendor/bundle/ruby/1.9.1/gems/mongo-1.6.2/lib/mongo/cursor.rb:466:in `send_initial_query'
vendor/bundle/ruby/1.9.1/gems/mongo-1.6.2/lib/mongo/cursor.rb:458:in `refresh'
vendor/bundle/ruby/1.9.1/gems/mongo-1.6.2/lib/mongo/cursor.rb:128:in `next'
vendor/bundle/ruby/1.9.1/gems/mongo-1.6.2/lib/mongo/collection.rb:288:in `find_one'
vendor/bundle/ruby/1.9.1/gems/mongoid-2.4.12/lib/mongoid/collections/master.rb:25:in `block in find_one'
vendor/bundle/ruby/1.9.1/gems/mongoid-2.4.12/lib/mongoid/collections/retry.rb:29:in `retry_on_connection_failure'
vendor/bundle/ruby/1.9.1/gems/mongoid-2.4.12/lib/mongoid/collections/master.rb:24:in `find_one'
vendor/bundle/ruby/1.9.1/gems/mongoid-2.4.12/lib/mongoid/collection.rb:60:in `find_one'
vendor/bundle/ruby/1.9.1/gems/mongoid-2.4.12/lib/mongoid/contexts/mongo.rb:205:in `first'
vendor/bundle/ruby/1.9.1/gems/mongoid-2.4.12/lib/mongoid/criteria.rb:45:in `first'
vendor/bundle/ruby/1.9.1/gems/mongoid-2.4.12/lib/mongoid/criterion/inclusion.rb:169:in `from_map_or_db'
vendor/bundle/ruby/1.9.1/gems/mongoid-2.4.12/lib/mongoid/criterion/inclusion.rb:149:in `execute_or_raise'
vendor/bundle/ruby/1.9.1/gems/mongoid-2.4.12/lib/mongoid/criterion/inclusion.rb:129:in `find'
vendor/bundle/ruby/1.9.1/gems/mongoid-2.4.12/lib/mongoid/finders.rb:84:in `find'
app/controllers/application_controller.rb:266:in `find_question'
vendor/bundle/ruby/1.9.1/gems/activesupport-3.2.11/lib/active_support/callbacks.rb:462:in `_run__469780332759358222__process_action__3401617144824505767__callbacks'
vendor/bundle/ruby/1.9.1/gems/activesupport-3.2.11/lib/active_support/callbacks.rb:405:in `__run_callback'
vendor/bundle/ruby/1.9.1/gems/activesupport-3.2.11/lib/active_support/callbacks.rb:385:in `_run_process_action_callbacks'
vendor/bundle/ruby/1.9.1/gems/activesupport-3.2.11/lib/active_support/callbacks.rb:81:in `run_callbacks'
vendor/bundle/ruby/1.9.1/gems/actionpack-3.2.11/lib/abstract_controller/callbacks.rb:17:in `process_action'
vendor/bundle/ruby/1.9.1/gems/actionpack-3.2.11/lib/action_controller/metal/rescue.rb:29:in `process_action'
vendor/bundle/ruby/1.9.1/gems/actionpack-3.2.11/lib/action_controller/metal/instrumentation.rb:30:in `block in process_action'
vendor/bundle/ruby/1.9.1/gems/activesupport-3.2.11/lib/active_support/notifications.rb:123:in `block in instrument'
vendor/bundle/ruby/1.9.1/gems/activesupport-3.2.11/lib/active_support/notifications/instrumenter.rb:20:in `instrument'
vendor/bundle/ruby/1.9.1/gems/activesupport-3.2.11/lib/active_support/notifications.rb:123:in `instrument'
vendor/bundle/ruby/1.9.1/gems/actionpack-3.2.11/lib/action_controller/metal/instrumentation.rb:29:in `process_action'
vendor/bundle/ruby/1.9.1/gems/actionpack-3.2.11/lib/action_controller/metal/params_wrapper.rb:207:in `process_action'
vendor/bundle/ruby/1.9.1/gems/newrelic_rpm-3.5.5.38/lib/new_relic/agent/instrumentation/rails3/action_controller.rb:34:in `block in process_action'
vendor/bundle/ruby/1.9.1/gems/newrelic_rpm-3.5.5.38/lib/new_relic/agent/instrumentation/controller_instrumentation.rb:268:in `block in perform_action_with_newrelic_trace'
vendor/bundle/ruby/1.9.1/gems/newrelic_rpm-3.5.5.38/lib/new_relic/agent/method_tracer.rb:240:in `trace_execution_scoped'
vendor/bundle/ruby/1.9.1/gems/newrelic_rpm-3.5.5.38/lib/new_relic/agent/instrumentation/controller_instrumentation.rb:263:in `perform_action_with_newrelic_trace'
vendor/bundle/ruby/1.9.1/gems/newrelic_rpm-3.5.5.38/lib/new_relic/agent/instrumentation/rails3/action_controller.rb:33:in `process_action'
vendor/bundle/ruby/1.9.1/gems/actionpack-3.2.11/lib/abstract_controller/base.rb:121:in `process'
vendor/bundle/ruby/1.9.1/gems/actionpack-3.2.11/lib/abstract_controller/rendering.rb:45:in `process'
vendor/bundle/ruby/1.9.1/gems/actionpack-3.2.11/lib/action_controller/metal.rb:203:in `dispatch'
vendor/bundle/ruby/1.9.1/gems/actionpack-3.2.11/lib/action_controller/metal/rack_delegation.rb:14:in `dispatch'
vendor/bundle/ruby/1.9.1/gems/actionpack-3.2.11/lib/action_controller/metal.rb:246:in `block in action'
vendor/bundle/ruby/1.9.1/gems/actionpack-3.2.11/lib/action_dispatch/routing/route_set.rb:73:in `call'
vendor/bundle/ruby/1.9.1/gems/actionpack-3.2.11/lib/action_dispatch/routing/route_set.rb:73:in `dispatch'
vendor/bundle/ruby/1.9.1/gems/actionpack-3.2.11/lib/action_dispatch/routing/route_set.rb:36:in `call'
vendor/bundle/ruby/1.9.1/gems/journey-1.0.4/lib/journey/router.rb:68:in `block in call'
vendor/bundle/ruby/1.9.1/gems/journey-1.0.4/lib/journey/router.rb:56:in `each'
vendor/bundle/ruby/1.9.1/gems/journey-1.0.4/lib/journey/router.rb:56:in `call'
vendor/bundle/ruby/1.9.1/gems/actionpack-3.2.11/lib/action_dispatch/routing/route_set.rb:601:in `call'
vendor/bundle/ruby/1.9.1/gems/rack-pjax-0.6.0/lib/rack/pjax.rb:12:in `call'
vendor/bundle/ruby/1.9.1/gems/omniauth-1.1.1/lib/omniauth/strategy.rb:177:in `call!'
vendor/bundle/ruby/1.9.1/gems/omniauth-1.1.1/lib/omniauth/strategy.rb:157:in `call'
vendor/bundle/ruby/1.9.1/gems/omniauth-1.1.1/lib/omniauth/strategy.rb:177:in `call!'
vendor/bundle/ruby/1.9.1/gems/omniauth-1.1.1/lib/omniauth/strategy.rb:157:in `call'
vendor/bundle/ruby/1.9.1/gems/omniauth-1.1.1/lib/omniauth/builder.rb:48:in `call'
vendor/bundle/ruby/1.9.1/gems/oink-0.10.1/lib/oink/middleware.rb:17:in `call'
vendor/bundle/ruby/1.9.1/gems/rack-timeout-0.0.3/lib/rack/timeout.rb:16:in `block in call'
vendor/bundle/ruby/1.9.1/gems/rack-timeout-0.0.3/lib/rack/timeout.rb:16:in `call'
vendor/bundle/ruby/1.9.1/gems/newrelic_rpm-3.5.5.38/lib/new_relic/rack/error_collector.rb:8:in `call'
vendor/bundle/ruby/1.9.1/gems/newrelic_rpm-3.5.5.38/lib/new_relic/rack/browser_monitoring.rb:12:in `call'
vendor/bundle/ruby/1.9.1/gems/mongoid-2.4.12/lib/rack/mongoid/middleware/identity_map.rb:33:in `block in call'
vendor/bundle/ruby/1.9.1/gems/mongoid-2.4.12/lib/mongoid.rb:133:in `unit_of_work'
vendor/bundle/ruby/1.9.1/gems/mongoid-2.4.12/lib/rack/mongoid/middleware/identity_map.rb:33:in `call'
vendor/bundle/ruby/1.9.1/gems/sass-3.2.6/lib/sass/plugin/rack.rb:54:in `call'
vendor/bundle/ruby/1.9.1/gems/exception_notification-2.6.1/lib/exception_notifier.rb:34:in `call'
vendor/bundle/ruby/1.9.1/gems/warden-1.2.1/lib/warden/manager.rb:35:in `block in call'
vendor/bundle/ruby/1.9.1/gems/warden-1.2.1/lib/warden/manager.rb:34:in `catch'
vendor/bundle/ruby/1.9.1/gems/warden-1.2.1/lib/warden/manager.rb:34:in `call'
vendor/bundle/ruby/1.9.1/gems/actionpack-3.2.11/lib/action_dispatch/middleware/best_standards_support.rb:17:in `call'
vendor/bundle/ruby/1.9.1/gems/rack-1.4.4/lib/rack/etag.rb:23:in `call'
vendor/bundle/ruby/1.9.1/gems/rack-1.4.4/lib/rack/conditionalget.rb:25:in `call'
vendor/bundle/ruby/1.9.1/gems/actionpack-3.2.11/lib/action_dispatch/middleware/head.rb:14:in `call'
vendor/bundle/ruby/1.9.1/gems/remotipart-1.0.2/lib/remotipart/middleware.rb:30:in `call'
vendor/bundle/ruby/1.9.1/gems/actionpack-3.2.11/lib/action_dispatch/middleware/params_parser.rb:21:in `call'
vendor/bundle/ruby/1.9.1/gems/actionpack-3.2.11/lib/action_dispatch/middleware/flash.rb:242:in `call'
vendor/bundle/ruby/1.9.1/gems/rack-1.4.4/lib/rack/session/abstract/id.rb:210:in `context'
vendor/bundle/ruby/1.9.1/gems/rack-1.4.4/lib/rack/session/abstract/id.rb:205:in `call'
vendor/bundle/ruby/1.9.1/gems/actionpack-3.2.11/lib/action_dispatch/middleware/cookies.rb:341:in `call'
vendor/bundle/ruby/1.9.1/gems/actionpack-3.2.11/lib/action_dispatch/middleware/callbacks.rb:28:in `block in call'
vendor/bundle/ruby/1.9.1/gems/activesupport-3.2.11/lib/active_support/callbacks.rb:405:in `_run__1746387501225523832__call__2262895368653440085__callbacks'
vendor/bundle/ruby/1.9.1/gems/activesupport-3.2.11/lib/active_support/callbacks.rb:405:in `__run_callback'
vendor/bundle/ruby/1.9.1/gems/activesupport-3.2.11/lib/active_support/callbacks.rb:385:in `_run_call_callbacks'
vendor/bundle/ruby/1.9.1/gems/activesupport-3.2.11/lib/active_support/callbacks.rb:81:in `run_callbacks'
vendor/bundle/ruby/1.9.1/gems/actionpack-3.2.11/lib/action_dispatch/middleware/callbacks.rb:27:in `call'
vendor/bundle/ruby/1.9.1/gems/actionpack-3.2.11/lib/action_dispatch/middleware/remote_ip.rb:31:in `call'
vendor/bundle/ruby/1.9.1/gems/actionpack-3.2.11/lib/action_dispatch/middleware/debug_exceptions.rb:16:in `call'
vendor/bundle/ruby/1.9.1/gems/actionpack-3.2.11/lib/action_dispatch/middleware/show_exceptions.rb:56:in `call'
vendor/bundle/ruby/1.9.1/gems/railties-3.2.11/lib/rails/rack/logger.rb:32:in `call_app'
vendor/bundle/ruby/1.9.1/gems/railties-3.2.11/lib/rails/rack/logger.rb:16:in `block in call'
vendor/bundle/ruby/1.9.1/gems/activesupport-3.2.11/lib/active_support/tagged_logging.rb:22:in `tagged'
vendor/bundle/ruby/1.9.1/gems/railties-3.2.11/lib/rails/rack/logger.rb:16:in `call'
vendor/bundle/ruby/1.9.1/gems/actionpack-3.2.11/lib/action_dispatch/middleware/request_id.rb:22:in `call'
vendor/bundle/ruby/1.9.1/gems/rack-1.4.4/lib/rack/methodoverride.rb:21:in `call'
vendor/bundle/ruby/1.9.1/gems/rack-1.4.4/lib/rack/runtime.rb:17:in `call'
vendor/bundle/ruby/1.9.1/gems/rack-1.4.4/lib/rack/lock.rb:15:in `call'
vendor/bundle/ruby/1.9.1/gems/actionpack-3.2.11/lib/action_dispatch/middleware/static.rb:62:in `call'
vendor/bundle/ruby/1.9.1/gems/rack-cache-1.2/lib/rack/cache/context.rb:136:in `forward'
vendor/bundle/ruby/1.9.1/gems/rack-cache-1.2/lib/rack/cache/context.rb:245:in `fetch'
vendor/bundle/ruby/1.9.1/gems/rack-cache-1.2/lib/rack/cache/context.rb:185:in `lookup'
vendor/bundle/ruby/1.9.1/gems/rack-cache-1.2/lib/rack/cache/context.rb:66:in `call!'
vendor/bundle/ruby/1.9.1/gems/rack-cache-1.2/lib/rack/cache/context.rb:51:in `call'
vendor/bundle/ruby/1.9.1/gems/railties-3.2.11/lib/rails/engine.rb:479:in `call'
vendor/bundle/ruby/1.9.1/gems/railties-3.2.11/lib/rails/application.rb:223:in `call'
vendor/bundle/ruby/1.9.1/gems/railties-3.2.11/lib/rails/railtie/configurable.rb:30:in `method_missing'
vendor/bundle/ruby/1.9.1/gems/rack-1.4.4/lib/rack/deflater.rb:13:in `call'
vendor/bundle/ruby/1.9.1/gems/unicorn-4.3.1/lib/unicorn/http_server.rb:531:in `process_client'
vendor/bundle/ruby/1.9.1/gems/unicorn-4.3.1/lib/unicorn/http_server.rb:606:in `worker_loop'
vendor/bundle/ruby/1.9.1/gems/unicorn-4.3.1/lib/unicorn/http_server.rb:487:in `spawn_missing_workers'
vendor/bundle/ruby/1.9.1/gems/unicorn-4.3.1/lib/unicorn/http_server.rb:137:in `start'
vendor/bundle/ruby/1.9.1/gems/unicorn-4.3.1/bin/unicorn:121:in `<top (required)>'
vendor/bundle/ruby/1.9.1/bin/unicorn:23:in `load'
vendor/bundle/ruby/1.9.1/bin/unicorn:23:in `<main>'
Kamilski81
  • 14,409
  • 33
  • 108
  • 161
  • If you are making 1 or more requests a minute to your database why not just alert on request failure? – James Wahlin Apr 12 '13 at 21:02
  • What MongoDB driver & version are you using in your application? Also, what specific exception message are you getting? – Stennie Apr 13 '13 at 07:42
  • @JamesWahlin, are you suggesting to just catching that exception type in controller, the exception occurs very deep, and results in a high level timeout (which i already catch) – Kamilski81 Apr 14 '13 at 15:44
  • @Stennie, i added the details above, thanks for the help. – Kamilski81 Apr 14 '13 at 15:46

2 Answers2

2

10gen offers a Mongo monitoring service called MMS, which is included with all MongoHQ plans per their pricing page. I'd start there, since that will give you insight into what the database is doing and why it might be unresponsive.

Chris Heald
  • 61,439
  • 10
  • 123
  • 137
  • 1
    It's worth noting that the [MongoDB Monitoring Service (MMS)](https://mms.10gen.com/) is a **free** service hosted by 10gen. You can set up [metric-based alerts](http://blog.10gen.com/post/41442945582/announcing-new-mms-alerts) for specific error thresholds. Data collected by MMS will provide operational insight into ongoing database activity (and is definitely recommended), but will generally not help diagnose timeout errors relating to application connectivity to the database server. – Stennie Apr 13 '13 at 12:52
  • I'm reaching out to MongoHQ to try to get this setup, but I don't see anything about this on their pricing page. – Kamilski81 Apr 14 '13 at 16:03
2

If you are getting timeouts during periods of low activity that go away after a few minutes of requests, a likely cause is that you have stale connections in your connection pool that are discovered when you try to use the connections. A stale connection will result in a timeout error to your application and the database connection will be re-established. As your application makes new requests, the stale connections will be refreshed and the timeout errors will go away.

You may be able to fix this by reducing your timeout value, but you could also handle by retrying the query on a timeout exception. MongoHQ support may have some specific advice on setting your timeout value appropriately for their service.

Stennie
  • 63,885
  • 14
  • 149
  • 175