ActiveRecord::ConnectionTimeoutError (could not get a database connection within 5.000 seconds (waited 5.000 seconds))答案

【问题标题】：ActiveRecord::ConnectionTimeoutError (could not obtain a database connection within 5.000 seconds (waited 5.000 seconds))ActiveRecord::ConnectionTimeoutError (could not get a database connection within 5.000 seconds (waited 5.000 seconds))
【发布时间】：2015-12-29 16:04:39
【问题描述】：

我在我的 Rails 4 应用程序中遇到了这个严重错误，因此我与数据库的连接丢失了。

F, [2015-12-23T18:06:22.875935 #13919] FATAL -- :
ActiveRecord::ConnectionTimeoutError (could not obtain a database connection within 5.000 seconds (waited 5.009 seconds)):
  activerecord (4.0.0) lib/active_record/connection_adapters/abstract/connection_pool.rb:190:in `block in wait_poll'
  activerecord (4.0.0) lib/active_record/connection_adapters/abstract/connection_pool.rb:181:in `loop'
  activerecord (4.0.0) lib/active_record/connection_adapters/abstract/connection_pool.rb:181:in `wait_poll'
  activerecord (4.0.0) lib/active_record/connection_adapters/abstract/connection_pool.rb:136:in `block in poll'
  /home/ubuntu/.rbenv/versions/2.1.2/lib/ruby/2.1.0/monitor.rb:211:in `mon_synchronize'
  activerecord (4.0.0) lib/active_record/connection_adapters/abstract/connection_pool.rb:146:in `synchronize'
  activerecord (4.0.0) lib/active_record/connection_adapters/abstract/connection_pool.rb:134:in `poll'
  activerecord (4.0.0) lib/active_record/connection_adapters/abstract/connection_pool.rb:423:in `acquire_connection'
  activerecord (4.0.0) lib/active_record/connection_adapters/abstract/connection_pool.rb:356:in `block in checkout'
  /home/ubuntu/.rbenv/versions/2.1.2/lib/ruby/2.1.0/monitor.rb:211:in `mon_synchronize'
  activerecord (4.0.0) lib/active_record/connection_adapters/abstract/connection_pool.rb:355:in `checkout'
  activerecord (4.0.0) lib/active_record/connection_adapters/abstract/connection_pool.rb:265:in `block in connection'
  /home/ubuntu/.rbenv/versions/2.1.2/lib/ruby/2.1.0/monitor.rb:211:in `mon_synchronize'
  activerecord (4.0.0) lib/active_record/connection_adapters/abstract/connection_pool.rb:264:in `connection'
  activerecord (4.0.0) lib/active_record/connection_adapters/abstract/connection_pool.rb:546:in `retrieve_connection'
  activerecord (4.0.0) lib/active_record/connection_handling.rb:79:in `retrieve_connection'
  activerecord (4.0.0) lib/active_record/connection_handling.rb:53:in `connection'
  activerecord (4.0.0) lib/active_record/query_cache.rb:51:in `restore_query_cache_settings'
  activerecord (4.0.0) lib/active_record/query_cache.rb:43:in `rescue in call'
  activerecord (4.0.0) lib/active_record/query_cache.rb:32:in `call'
  activerecord (4.0.0) lib/active_record/connection_adapters/abstract/connection_pool.rb:626:in `call'
  actionpack (4.0.0) lib/action_dispatch/middleware/callbacks.rb:29:in `block in call'
  activesupport (4.0.0) lib/active_support/callbacks.rb:373:in `_run__285615481658568074__call__callbacks'
  activesupport (4.0.0) lib/active_support/callbacks.rb:80:in `run_callbacks'
  actionpack (4.0.0) lib/action_dispatch/middleware/callbacks.rb:27:in `call'
  actionpack (4.0.0) lib/action_dispatch/middleware/remote_ip.rb:76:in `call'
  actionpack (4.0.0) lib/action_dispatch/middleware/debug_exceptions.rb:17:in `call'
  actionpack (4.0.0) lib/action_dispatch/middleware/show_exceptions.rb:30:in `call'
railties (4.0.0) lib/rails/rack/logger.rb:38:in `call_app'
  railties (4.0.0) lib/rails/rack/logger.rb:21:in `block in call'
  activesupport (4.0.0) lib/active_support/tagged_logging.rb:67:in `block in tagged'
  activesupport (4.0.0) lib/active_support/tagged_logging.rb:25:in `tagged'
  activesupport (4.0.0) lib/active_support/tagged_logging.rb:67:in `tagged'
  railties (4.0.0) lib/rails/rack/logger.rb:21:in `call'
  actionpack (4.0.0) lib/action_dispatch/middleware/request_id.rb:21:in `call'
  rack (1.5.2) lib/rack/methodoverride.rb:21:in `call'
  rack (1.5.2) lib/rack/runtime.rb:17:in `call'
  activesupport (4.0.0) lib/active_support/cache/strategy/local_cache.rb:83:in `call'
  railties (4.0.0) lib/rails/engine.rb:511:in `call'
  railties (4.0.0) lib/rails/application.rb:97:in `call'
  puma (2.10.1) lib/puma/configuration.rb:74:in `call'
  puma (2.10.1) lib/puma/server.rb:490:in `handle_request'
  puma (2.10.1) lib/puma/server.rb:361:in `process_client'
  puma (2.10.1) lib/puma/server.rb:254:in `block in run'
  puma (2.10.1) lib/puma/thread_pool.rb:96:in `call'
  puma (2.10.1) lib/puma/thread_pool.rb:96:in `block in spawn_thread'

我正在尝试调试它，但它非常复杂。我不知道问题出在哪里。

我在ActiveRecord::ConnectionTimeoutError: could not obtain a database connection within 5.000 seconds (waited 5.000 seconds) 之前读过这篇文章，@railsana 的回答符合我的一种可能情况。

我有某种批处理过程，它通过计划任务从模型（外部控制器）调用大量查询。我尝试按照他们的建议将此代码添加到此功能中，但问题仍然存在。

ActiveRecord::Base.connection_pool.with_connection do
  # your code
end

以防万一它是相关信息，我的 rails 应用程序在 Puma 服务器中运行，而我的数据库是 MySQL。

任何建议，可以是什么，或者如何调试它？这个错误真的很致命，因为我的应用程序无法处理任何查询。

更新： 回答问题： 1. 在生产中，我在 config/database.yml 中配置了一个有 5 个连接的池。 2.我的Puma服务器启动日志：

Puma starting in single mode...
* Version 2.10.1 (ruby 2.1.2-p95), codename: Robots on Comets
* Min threads: 0, max threads: 16
* Environment: production
* Daemonizing..

只启动一个工人。

更新 2：

检查 puma.stderr.log 我发现了这种错误日志：

{ 70238458077400 rufus-scheduler intercepted an error:
  70238458077400   job:
  70238458077400     Rufus::Scheduler::EveryJob "90s" {}
  70238458077400   error:
  70238458077400     70238458077400
  70238458077400     Net::ReadTimeout
  70238458077400     Net::ReadTimeout
  70238458077400       /home/ubuntu/.rbenv/versions/2.1.2/lib/ruby/2.1.0/net/protocol.rb:158:in `rescue in rbuf_fill'
  70238458077400       /home/ubuntu/.rbenv/versions/2.1.2/lib/ruby/2.1.0/net/protocol.rb:152:in `rbuf_fill'
  70238458077400       /home/ubuntu/.rbenv/versions/2.1.2/lib/ruby/2.1.0/net/protocol.rb:134:in `readuntil'
  70238458077400       /home/ubuntu/.rbenv/versions/2.1.2/lib/ruby/2.1.0/net/protocol.rb:144:in `readline'
  70238458077400       /home/ubuntu/.rbenv/versions/2.1.2/lib/ruby/2.1.0/net/http/response.rb:39:in `read_status_line'
  70238458077400       /home/ubuntu/.rbenv/versions/2.1.2/lib/ruby/2.1.0/net/http/response.rb:28:in `read_new'
  70238458077400       /home/ubuntu/.rbenv/versions/2.1.2/lib/ruby/2.1.0/net/http.rb:1408:in `block in transport_request'
  70238458077400       /home/ubuntu/.rbenv/versions/2.1.2/lib/ruby/2.1.0/net/http.rb:1405:in `catch'
  70238458077400       /home/ubuntu/.rbenv/versions/2.1.2/lib/ruby/2.1.0/net/http.rb:1405:in `transport_request'
  70238458077400       /home/ubuntu/.rbenv/versions/2.1.2/lib/ruby/2.1.0/net/http.rb:1378:in `request'
  70238458077400       /home/ubuntu/.rbenv/versions/2.1.2/lib/ruby/gems/2.1.0/gems/rest-client-1.6.7/lib/restclient/net_http_ext.rb:51:in `request'
  70238458077400       /home/ubuntu/.rbenv/versions/2.1.2/lib/ruby/gems/2.1.0/gems/httpi-2.4.1/lib/httpi/adapter/net_http.rb:65:in `perform'
  70238458077400       /home/ubuntu/.rbenv/versions/2.1.2/lib/ruby/gems/2.1.0/gems/httpi-2.4.1/lib/httpi/adapter/net_http.rb:42:in `block in request'
  70238458077400       /home/ubuntu/.rbenv/versions/2.1.2/lib/ruby/gems/2.1.0/gems/httpi-2.4.1/lib/httpi/adapter/net_http.rb:78:in `call'
  70238458077400       /home/ubuntu/.rbenv/versions/2.1.2/lib/ruby/gems/2.1.0/gems/httpi-2.4.1/lib/httpi/adapter/net_http.rb:78:in `block in do_request'
  70238458077400       /home/ubuntu/.rbenv/versions/2.1.2/lib/ruby/2.1.0/net/http.rb:853:in `start'
  70238458077400       /home/ubuntu/.rbenv/versions/2.1.2/lib/ruby/gems/2.1.0/gems/httpi-2.4.1/lib/httpi/adapter/net_http.rb:76:in `do_request'
  70238458077400       /home/ubuntu/.rbenv/versions/2.1.2/lib/ruby/gems/2.1.0/gems/httpi-2.4.1/lib/httpi/adapter/net_http.rb:33:in `request'
  70238458077400       /home/ubuntu/.rbenv/versions/2.1.2/lib/ruby/gems/2.1.0/gems/httpi-2.4.1/lib/httpi.rb:161:in `request'
  70238458077400       /home/ubuntu/.rbenv/versions/2.1.2/lib/ruby/gems/2.1.0/gems/httpi-2.4.1/lib/httpi.rb:133:in `post'
  70238458077400       /home/ubuntu/.rbenv/versions/2.1.2/lib/ruby/gems/2.1.0/gems/savon-2.11.1/lib/savon/operation.rb:94:in `block in call_with_logging'
  70238458077400       /home/ubuntu/.rbenv/versions/2.1.2/lib/ruby/gems/2.1.0/gems/savon-2.11.1/lib/savon/request_logger.rb:12:in `call'
  70238458077400       /home/ubuntu/.rbenv/versions/2.1.2/lib/ruby/gems/2.1.0/gems/savon-2.11.1/lib/savon/request_logger.rb:12:in `log'
  70238458077400       /home/ubuntu/.rbenv/versions/2.1.2/lib/ruby/gems/2.1.0/gems/savon-2.11.1/lib/savon/operation.rb:94:in `call_with_logging'
  70238458077400       /home/ubuntu/.rbenv/versions/2.1.2/lib/ruby/gems/2.1.0/gems/savon-2.11.1/lib/savon/operation.rb:54:in `call'
  70238458077400       /home/ubuntu/.rbenv/versions/2.1.2/lib/ruby/gems/2.1.0/gems/savon-2.11.1/lib/savon/client.rb:36:in `call'
  70238458077400       /home/ubuntu/env/production/www/yanpyapi/lib/mmk_service.rb:560:in `block (2 levels) in getAvailabilities'
  70238458077400       /home/ubuntu/env/production/www/yanpyapi/lib/mmk_service.rb:544:in `each'
  70238458077400       /home/ubuntu/env/production/www/yanpyapi/lib/mmk_service.rb:544:in `block in getAvailabilities'
  70238458077400       /home/ubuntu/.rbenv/versions/2.1.2/lib/ruby/gems/2.1.0/gems/activerecord-4.0.0/lib/active_record/relation/delegation.rb:13:in `each'
  70238458077400       /home/ubuntu/.rbenv/versions/2.1.2/lib/ruby/gems/2.1.0/gems/activerecord-4.0.0/lib/active_record/relation/delegation.rb:13:in `each'
  70238458077400       /home/ubuntu/env/production/www/yanpyapi/lib/mmk_service.rb:530:in `getAvailabilities'
  70238458077400       /home/ubuntu/env/production/www/yanpyapi/lib/mmk_service.rb:65:in `updateAvailabilities'
  70238458077400       /home/ubuntu/env/production/www/yanpyapi/app/models/secretary.rb:182:in `block in getBoatsAvailability'
  70238458077400       /home/ubuntu/.rbenv/versions/2.1.2/lib/ruby/gems/2.1.0/gems/activerecord-4.0.0/lib/active_record/connection_adapters/abstract/connection_pool.rb:294:in `with_connection'
  70238458077400       /home/ubuntu/env/production/www/yanpyapi/app/models/secretary.rb:181:in `getBoatsAvailability'
  70238458077400       /home/ubuntu/env/production/www/yanpyapi/config/initializers/task_scheduler.rb:29:in `block in <top (required)>'
  70238458077400       /home/ubuntu/.rbenv/versions/2.1.2/lib/ruby/gems/2.1.0/gems/rufus-scheduler-3.0.3/lib/rufus/scheduler/jobs.rb:224:in `call'
  70238458077400       /home/ubuntu/.rbenv/versions/2.1.2/lib/ruby/gems/2.1.0/gems/rufus-scheduler-3.0.3/lib/rufus/scheduler/jobs.rb:224:in `do_trigger'
  70238458077400       /home/ubuntu/.rbenv/versions/2.1.2/lib/ruby/gems/2.1.0/gems/rufus-scheduler-3.0.3/lib/rufus/scheduler/jobs.rb:269:in `block (3 levels) in start_work_thread'
  70238458077400       /home/ubuntu/.rbenv/versions/2.1.2/lib/ruby/gems/2.1.0/gems/rufus-scheduler-3.0.3/lib/rufus/scheduler/jobs.rb:272:in `call'
  70238458077400       /home/ubuntu/.rbenv/versions/2.1.2/lib/ruby/gems/2.1.0/gems/rufus-scheduler-3.0.3/lib/rufus/scheduler/jobs.rb:272:in `block (2 levels) in start_work_thread'
 70238458077400       /home/ubuntu/.rbenv/versions/2.1.2/lib/ruby/gems/2.1.0/gems/rufus-scheduler-3.0.3/lib/rufus/scheduler/jobs.rb:258:in `loop'
  70238458077400       /home/ubuntu/.rbenv/versions/2.1.2/lib/ruby/gems/2.1.0/gems/rufus-scheduler-3.0.3/lib/rufus/scheduler/jobs.rb:258:in `block in start_work_thread'
} 70238458077400 .

这是发送抛出此异常的代码部分（我认为未捕获异常）：

 # This method is in a model invoked by an scheduled task rufus-scheduler that is executed every 90 seconds.

 def self.getBoatsAvailability
    if Rails.env.production?      
      require 'service'
      # This line was added to try to fix this problem (I read this approach in another post link above)
      ActiveRecord::Base.connection_pool.with_connection do
        Service.getAvailabilities(false)
      end
    end
 end

def self.getAvailabilities(isMonthly)
    @logger.debug "Importing availabilities..." 

    # Savon is a service to communicate with SOAP web services    
    client = Savon.client(wsdl: "url", 
                          log_level: :debug,
                          log: true,
                          pretty_print_xml: true)
    mmkCompanies = Mmk::Company.select("id").where(loading: true).order("id") 
    createdAt = Time.now        
    @logger.debug "getAvailabilities Before each company."
    for mmkCompany in mmkCompanies do
      lastModifiedReq = Mmk::Availability.find_by_sql(["SELECT max(a.created_at) as max_date
                                                        FROM mmk_availabilities a, mmk_resources r 
                                                        WHERE a.resource_id = r.id
                                                        AND r.company_id = ?", mmkCompany.id]).first.max_date                
      (0..1).each do |i|
        year = Time.now.year + i        
        message = {'in0' => credentials, 
                   'in1' => credentials, 
                   'in2' => credentials,
                   'in3' => mmkCompany.id,
                   'in4' => year,
                   'in5' => true,              
                   'in6' => lastModifiedReq}

        @logger.debug "getAvailabilities Before client call."   
        response = client.call(:get_availability_info, message: message)
        @logger.debug "getAvailabilities After client call."    
        availabilitiesXML = response.to_hash[:get_availability_info_response][:out]
        availabilitiesParsed = Nokogiri::XML(availabilitiesXML)
        availabilities = availabilitiesParsed.xpath("//reservation") 
        @logger.debug "getAvailabilities Before transaction."             
        Mmk::Availability.transaction do
          @logger.debug "getAvailabilities Transaction opened."   
          for availability in availabilities do 
            id = availability["id"]           
            # More parse parameters unrelevant code              
            mmkAvailability = Mmk::Availability.find_or_initialize_by(id: id)                   
            mmkAvailability.update(resource_id: resourceId, status: status, blocks_availability: blocksAvailability,
                                   date_from: dateFrom, date_to: dateTo, base_from: baseFrom, base_to: baseTo, 
                                   option_expiry_date: optionExpiryDate, last_modified: lastModified, created_at: createdAt)
            mmkAvailability.save            
          end
        end
        @logger.debug "getAvailabilities After transaction (closed)?."
      end
    end
    @logger.debug "Availability imported successfully."
  end

这行异常：

`70238458077400       /home/ubuntu/env/production/www/yanpyapi/lib/mmk_service.rb:560:in `block (2 levels) in getAvailabilities'`

对应：

response = client.call(:get_availability_info, message: message)

我的分析（尽管并非所有内容都适合我）是： - getAvailabilities 方法正在向第三方系统发送 Web 服务 SOAP 请求。 - 有时由于某种原因，此连接丢失或第三方服务没有响应并引发 Net::ReadTimeout 异常。 - 未捕获此异常。并且数据库连接（这是我不明白的部分）保持打开状态。 - 当此问题发生 5 次时，池连接数为 0，我得到了主要问题。

【问题讨论】：

您是否在config/database.yml 中指定了连接数？ puma 运行了多少线程（你可以在运行 web 服务器后在控制台中看到这个）？
您是否在 MySQL 服务器中记录慢查询？ dev.mysql.com/doc/refman/5.7/en/slow-query-log.html。你也可以试试这个：stackoverflow.com/questions/1620662/… 看看它是否能说明哪些连接保持打开状态。
请看我的更新和答案。
@andrykonchin 请看我的更新。
当线程数 (16) 大于打开的数据库连接数 (5) 时，您可能会遇到此类问题。将连接数增加到 16 并再次检查。

标签： mysql ruby-on-rails ruby-on-rails-4 activerecord

【解决方案1】：

为了调试这个问题，我首先在self.getAvailabilities 方法中添加一个异常处理程序（rescue 子句）。

def self.getAvailabilities(isMonthly)
  ... # existing code goes here

rescue Net::ReadTimeout => err
  # I would use pry to put a breakpoint here and see what is keeping the DB connection open.
  binding.pry
end

使用pry gem 在处理程序中插入断点。一旦 Savon 调用超时，它应该会到达该断点。然后你可以使用 REPL 来确定谁在持有连接，并可能关闭它。见这里：How to find current connection pool size on heroku。

如果没有捕获到异常，我会将rescue 行更改为捕获StandardError 而不是Net::ReadTimeout，然后重试。

【讨论】：

嗨，我已经添加了异常处理程序。我以为只是捕获异常我不会失去连接。我不知道连接是在哪里创建的，但是如果捕获到异常，并且程序正常结束，连接应该不会丢失。我不手动创建连接，Rails 正在这样做。我很绝望，因为系统不断下降。我需要调试连接，但我不知道如何使用 pry。
Pry 是一个~~精彩的~~必备工具。您可以在此处了解更多信息：github.com/pry/pry。本质上，它会将您放入 Rails 控制台的 binding.pry 行，并允许您在此处执行代码。然后，您可以检查事物甚至改变事物。我将使用上面的 binding.pry 示例，然后从 mysql 控制台运行 SHOW PROCESSLIST 以了解活动连接。然后弄清楚如何关闭它们。当然，这是治标不治本，但它可以帮助您获得从源头解决问题所需的洞察力。