Rails 控制器动作挂起答案

【问题标题】：Rails controller action hangingRails 控制器动作挂起
【发布时间】：2015-06-11 16:29:17
【问题描述】：

我是 ruby/rails 的新手，在过去的 2 天里一直遇到一个问题，我希望这个论坛中的某个人可以帮助我解决这个问题。

我正在使用带有 Mysql 数据库（mysql2 适配器）的Passenger + Nginx 在生产中运行Rails 4 应用程序。我的 ProductsController.rb 中有以下代码（log_info 是我的自定义日志记录包装器，它只调用 Rails 记录器）：

def index
    log_info("ProductsController", "Getting Products...")
    @products = Product.get_products(params[:offset])
    log_info("ProductsController", "Got all Products...")

    # populate access_url before sending the data through
    update_products_with_access_url(@products)
end

下面是 Product 模型中 get_products 函数的定义：

def self.get_products(products_offset)
    products_offset ||= 0

    Product.includes(:categories, :suppliers).
            where(active: true).order(updated_at: :desc).
            limit(20).
            offset(products_offset * 20)
end

问题是当调用索引操作时，我的应用程序在生产中挂起（在开发中工作正常）几分钟。这种行为几乎有一半时间发生 - 另一半时间它工作正常。

我可以在日志中看到该操作已被调用但未执行。这是日志文件中的一个 sn-p：

I, [2015-06-10T13:31:01.802673 #14916]  INFO -- : Processing by ProductsController#index as HTML
I, [2015-06-10T13:33:09.718339 #14916]  INFO -- : [INFO][2015-06-10 13:33:09 UTC][ProductsController][Getting Products...]
I, [2015-06-10T13:33:09.719365 #14916]  INFO -- : [INFO][2015-06-10 13:33:09 UTC][ProductsController][Got all Products...]
D, [2015-06-10T13:33:09.720980 #14916] DEBUG -- :   Product Load (0.8ms)  SELECT  `products`.* FROM `products` WHERE `products`.`active` = 1  ORDER BY `products`.`updated_at` DESC LIMIT 12 OFFSET 0
D, [2015-06-10T13:33:09.725110 #14916] DEBUG -- :   ProductCategory Load (0.5ms)  SELECT `product_categories`.* FROM `product_categories` WHERE `product_categories`.`product_id` IN (30, 29, 28, 27, 26, 25, 24, 23, 22, 21, 20, 19)

如您所见，上述日志文件的前两行之间至少有 2 分钟的差异。日志显示索引操作已收到调用，但我不确定为什么执行该索引操作的第一行需要这么长时间（有时超过 5 分钟）。我怀疑发生了某种缓存。我早些时候认为电话可能在连接 MySQL 数据库时挂起，但现在不确定。我在这里错过了什么吗？

有人可以帮我解决这个应用程序挂起问题吗？

【问题讨论】：

生产数据库有多大？数据库是否正确索引？ get_products的定义是什么？
我已更新我的问题以显示产品模型中 get_products 方法的定义。关于数据库，它绝对是新的（只有少数记录 - 不到 50 条）并且已编入索引。
log_info 长什么样子？如果你也禁用它，它会挂起吗？
log_info 只有一行调用 Rails 记录器。这里是：Rails.logger.info "[INFO][#{Time.current}][#{module_name}][#{message}]"。我没有尝试禁用它，但我不怀疑它是问题，因为它只是一个记录器调用。我添加了对 log_info 的调用来调试问题。在添加这些对 log_info 的调用之前，问题就存在了。
看起来它在实际调用您的操作之前做了其他事情。您是否有任何前置过滤器，也许是身份验证？您还有任何外部会话/缓存存储...？我也会尝试使用探查器。通常它可以向您显示花费最多时间的确切位置...

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

【解决方案1】：

请检查是否有任何前置过滤器，通常它们可能是导致此类挂起的原因。

【讨论】：