ruby-on-rails - Rails 3.2、Ruby 1.9 和 Unicorn - 第一个请求很慢 - 如何调试？

Question

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

第一个请求:在 2771.8 毫秒内完成 304 未修改(ActiveRecord:98.6 毫秒)

第二个请求:在 94.4 毫秒内完成 304 未修改(ActiveRecord:26.9 毫秒)

我确实有 preload_app true 并且我正在 after-fork 中重新建立数据库连接。

我不知道如何解释这两个值之间的 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)

Answer 1

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

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

一些想法:

1. 检查 rails 日志，看看是否有任何奇怪的事情发生

2. 这是否只发生在 Unicorn 或其他服务器上？

3. 添加带有时间戳的日志语句，以了解应用的哪个部分花费了很长时间

4. 尝试使用 ruby​​ prof