Rails 3.2、Ruby 1.9 和 Unicorn - 第一个请求非常慢 - 如何调试？答案

【问题标题】：Rails 3.2, Ruby 1.9 and Unicorn - The First Request is Very Slow - How to debug?Rails 3.2、Ruby 1.9 和 Unicorn - 第一个请求非常慢 - 如何调试？
【发布时间】：2014-07-05 09:49:07
【问题描述】：

我有一个在 Unicorn 上运行的大型 2.3 Rails 应用程序。我正在使用 Unicorn，这样我就可以进行零停机部署。但是，我注意到重启后的第一个请求非常很慢。

第一个请求： Completed 304 Not Modified in 2771.8ms (ActiveRecord: 98.6ms)

第二个请求： Completed 304 Not Modified in 94.4ms (ActiveRecord: 26.9ms)

我确实有preload_app true，并且我正在后叉中重新建立数据库连接。

我不知道如何解释这两个值之间的 2600 毫秒差异。

有人有什么想法吗？真的，我正在寻找的是调试这个问题的方法。

更新

这是我重启后的 unicorn.log：

I, [2014-05-16T13:46:26.529305 #11637]  INFO -- : executing ["/data/app/current/ey_bundler_binstubs/unicorn", "-E", "staging", "-c", "/data/app/shared/config/custom_unicorn.rb", "-D", "/data/app/current/config.ru", {12=>#<Kgio::UNIXServer:fd 12>}] (in /data/app/releases/20140516184210)
I, [2014-05-16T13:46:27.566115 #11637]  INFO -- : inherited addr=/var/run/engineyard/unicorn_afar.sock fd=12
I, [2014-05-16T13:46:27.566551 #11637]  INFO -- : Refreshing Gem list
I, [2014-05-16T13:47:13.036963 #8247]  INFO -- : reaped #<Process::Status: pid 8681 exit 0> worker=3
I, [2014-05-16T13:47:14.093196 #8247]  INFO -- : reaped #<Process::Status: pid 8670 exit 0> worker=2
I, [2014-05-16T13:47:14.100269 #12047]  INFO -- : worker=0 ready
I, [2014-05-16T13:47:15.105249 #12063]  INFO -- : worker=1 ready
I, [2014-05-16T13:47:15.114038 #8247]  INFO -- : reaped #<Process::Status: pid 8655 exit 0> worker=1
I, [2014-05-16T13:47:15.957970 #8247]  INFO -- : reaped #<Process::Status: pid 8638 exit 0> worker=0
I, [2014-05-16T13:47:15.958159 #8247]  INFO -- : master complete
I, [2014-05-16T13:47:16.087761 #12082]  INFO -- : worker=2 ready
I, [2014-05-16T13:47:16.876129 #11637]  INFO -- : master process ready
I, [2014-05-16T13:47:17.102994 #12095]  INFO -- : worker=3 ready

这是我的 rails 日志中的第一个请求：

Started GET "/" for 70.XX.XXX.XXX at 2014-05-16 13:47:51 -0700
Processing by HomeController#index as HTML
   (1.1ms)  SELECT ..... <regular controller/ActiveRecord queries> 
Completed 304 Not Modified in 2724.8ms (ActiveRecord: 98.9ms)

【问题讨论】：

我认为重启后是可以预期的：stackoverflow.com/questions/680302/…

标签： ruby-on-rails ruby unicorn

【解决方案1】：

First request to Rails app is very slow 可能是相关的。

也许有一个依赖项正在加载/在第一页加载时运行？

一些想法：

检查 rails 日志，看看是否有任何异常情况发生
这只是发生在 Unicorn 还是其他服务器上？
添加带有时间戳的日志语句，以了解应用程序的哪个部分花费了很长时间
尝试使用 ruby prof

【讨论】：

我已经用一些额外的日志更新了这个问题。似乎没有什么侥幸的事情发生。你认为哪里是记录器语句的好地方？控制器内部？还是……？
取决于您是否了解缓慢可能来自何处。如果它只是第一个请求，它可能在您的代码之外，所以像 ruby prof 这样的东西可能会提供更多信息。为了快速获取时间信息，您可以将日志语句放在控制器、视图或模型中，以了解什么占用了很多时间。一堆 'logger.info Time.now' 调用可以帮助揭示事情在哪里放缓。在这种情况下，我会说尝试使用 ruby-prof 来看看你是否可以更好地了解发生了什么。