CODEWITHSUNDEEP
ruby-on-railsherokuruby-on-rails-3.2timeout
Ryan Porter
Ryan Porter

Reputation: 2182

Intermittent timeouts from an app that should never timeout (NOT an "R12 Request Timeout" error)

I've got a simple business Rails 3.2.13 app with a base of only one user, with very small Postgres DB tables, and very simple Active Record DB queries. I'm running it on two dynos, zero workers, on the Unicorn web server. The root page of the app typically loads in about 150 ms in development, and in under 1 s in production at Heroku.

EXCEPT, when it randomly times out. I'm seeing timeouts in the log, but NOT the typical R12 Request Timeout. The timeouts look like this:

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 that 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

Things to note: The request response time was 924 ms. But then some kind of strange error happened after that.

This is what that request looks like in terms of DB queries. There is nothing exciting happening there, and those DB tables only contain a few hundred rows of data. There is no reason why the response should take 1 second sometimes, and 15+ seconds on other times. Here's the code for the 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, just so that you can see that it's not doing anything that could potentially take 15+ seconds:

def self.recent
  Event.last || Event.create
end

I'm at a loss for how to get this app stabilized, other than moving it off of Heroku. I don't know of any way to troubleshoot the problem, and I guess Heroku won't help. Am I simply stuck? Do I have any options for troubleshooting the problem other than moving the app to Engine Yard?

Upvotes: 1

Views: 941

Answers (1)

Ryan Porter
Ryan Porter

Reputation: 2182

Nothing here helped, and this site is Heroku's technical support. Paying $35/mo doesn't buy me any support, so I'm stuck and there is no way forward with Heroku.

So my answer to this problem is to move the app to Engine Yard. I don't see that I have any other options. Heroku is awesome when it works and it's a complete mystery with no technical support when it doesn't work.

Upvotes: 4

Related Questions