I have a simple Rails 3.2.13 business application with only one user base with very small Postgres DB tables and very simple Active Record DB queries. I run it on two speakers, zero working, on a Unicorn web server. The root page of an application usually loads in about 150 ms during development and in less than 1 second in production at Heroku.
EXCEPT when it randomly expires. I see the timeouts in the log, but NOT the typical R12 request timeout. Timeouts are as follows:
2013-05-28T16:04:28.004290+00:00 app[web.2]: Started GET "/" for 72.28.209.197 at 2013-05-28 16:04:28 +0000 2013-05-28T16:04:44.225643+00:00 app[web.2]: E, [2013-05-28T16:04:44.225444 #2] ERROR -- : worker=2 PID:87 timeout (16s > 15s), killing 2013-05-28T16:04:44.238422+00:00 heroku[router]: at=error code=H13 desc="Connection closed without response" method=GET path=/ host=[REDACTED].herokuapp.com fwd="72.28.209.197" dyno=web.2 connect=7ms service=16240ms status=503 bytes=0 2013-05-28T16:04:44.255813+00:00 app[web.2]: E, [2013-05-28T16:04:44.255554 #2] ERROR -- : reaped #<Process::Status: pid 87 SIGKILL (signal 9)> worker=2 2013-05-28T16:04:44.298023+00:00 app[web.2]: I, [2013-05-28T16:04:44.297643 #103] INFO -- : worker=2 ready
When this request works, it looks like this:
2013-05-28T16:03:36.965507+00:00 app[web.1]: sequenceId="102642"] Started GET "/" for 72.28.209.197 at 2013-05-28 16:03:36 +0000 2013-05-28T16:03:37.388261+00:00 app[web.1]: sequenceId="102690"] Processing by OverviewController#index as HTML 2013-05-28T16:03:38.238877+00:00 app[web.1]: sequenceId="102707"] Rendered overview/index.html.erb within layouts/application (315.8ms) 2013-05-28T16:03:38.311974+00:00 app[web.1]: sequenceId="102710"] Completed 200 OK in 924ms (Views: 432.4ms | ActiveRecord: 92.1ms) 2013-05-28T16:03:38.322786+00:00 heroku[router]: at=info method=GET path=/ host=[REDACTED].herokuapp.com fwd="72.28.209.197" dyno=web.1 connect=2ms service=1375ms status=200 bytes=136795 2013-05-28T16:03:42.625787+00:00 app[web.1]: sequenceId="102940"] Started GET "/assets/favicon.ico" for 72.28.209.197 at 2013-05-28 16:03:42 +0000 2013-05-28T16:03:58.753408+00:00 app[web.1]: sequenceId="104359"] E, [2013-05-28T16:03:58.753173 #2] ERROR -- : worker=2 PID:66 timeout (16s > 15s), killing 2013-05-28T16:03:58.801152+00:00 app[web.1]: sequenceId="104362"] E, [2013-05-28T16:03:58.800993 #2] ERROR -- : reaped #<Process::Status: pid 66 SIGKILL (signal 9)> worker=2 2013-05-28T16:03:58.798722+00:00 heroku[router]: at=error code=H13 desc="Connection closed without response" method=GET path=/assets/favicon.ico host=[REDACTED].herokuapp.com fwd="72.28.209.197" dyno=web.1 connect=3ms service=16175ms status=503 bytes=0 2013-05-28T16:03:59.127150+00:00 app[web.1]: sequenceId="104397"] I, [2013-05-28T16:03:59.126795 #84] INFO -- : worker=2 ready
Remarks: The response time of the request was 924 ms. But after that some strange error occurred.
Here is what this query looks like in terms of database queries . Nothing interesting happens there, and these database tables contain only a few hundred rows of data. There is no reason why the answer should take 1 second, and sometimes 15 seconds. Here is the code for an extremely simple controller action:
class OverviewController < ApplicationController def index @current_event = Event.recent @areas = Area.order(:position) @reservations = Reservation.find(:all, :conditions => { :event_id => @current_event.id }, :order => 'created_at DESC', :limit => 5) end end
Here's the Event # Recent method, so you can see that it is not doing anything, which can take 15+ seconds:
def self.recent Event.last || Event.create end
I do not understand how to make this application stabilize, except that you disconnect it from Heroku. I do not know how to solve the problem, and I think Heroku will not help. Am I just stuck? Do I have any troubleshooting options other than moving the application to Engine Yard?