2

I've got a large 2.3 Rails app running on Unicorn. I'm using Unicorn, so that I can have zero downtime deployments. However, I've noticed that the first request after a restart is very slow.

First request: Completed 304 Not Modified in 2771.8ms (ActiveRecord: 98.6ms)

Second request: Completed 304 Not Modified in 94.4ms (ActiveRecord: 26.9ms)

I do have preload_app true and I am re-establishing the db-connection in the after-fork.

I have no idea how to explain the 2600ms divergence between these two values.

Does anyone have any thoughts? Really, what I am looking for are ways to debug this issue.

UPDATE

Here is my unicorn.log after a restart: 

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

And here is the first request on my rails logs:

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)
earnold
  • 1,440
  • 1
  • 15
  • 26
  • I think it is to be expected after reboots: http://stackoverflow.com/questions/680302/how-can-i-find-out-why-my-app-is-slow – Mark Boulder Mar 30 '15 at 08:05

1 Answers1

0

First request to Rails app is very slow may be relevant.

Maybe there is a dependency that is loading / running on the first page load?

Some ideas:

  1. Check the rails log to see if there's anything funky going on

  2. Is this just happening for Unicorn or with other servers too?

  3. Add log statements with time stamps to get a sense for what part of the app is taking a long time

  4. Try using ruby prof

Community
  • 1
  • 1
Puhlze
  • 2,634
  • 18
  • 16
  • I've updated the question with some additional logs. There doesn't seem to be anything fluky going on. Where were you thinking would be good places for the logger statements? Inside of the controller? Or....? – earnold May 16 '14 at 20:52
  • Depends if you have a sense of where the slowness might be coming from. If it's just the first request it may be outside of your code, so something like ruby prof might give more information. For a fast way to gain timing info you can put log statements in controllers, views or models to get a sense what's taking up a lot of time. A bunch of 'logger.info Time.now' calls can help reveal where things are slowing down. In this case, I'd say try playing with ruby-prof a bit to see if you can get a better sense of what's going on. – Puhlze May 16 '14 at 23:59