Question: What is causing my Rack middleware to spike?

Question

What is causing my Rack middleware to spike?

Answers 0
Added at 2016-12-19 16:12
Tags
Question

The Rack Middleware and Heroku Request Queue occasionally spike in my Ruby/Sinatra app, which causes the app to hang until I manually restart the servers. I have made tweaks to the Rack::Timeout, Postgres Timeout, and updated the Postgres calls so that they mostly run for under 100ms. Typically, when the Request Queue increases, the servers will automatically restart and then continue without issue, but when the Middleware spikes, the app is unable to recover and the app continues to hang in the request queue until it times out. What is causing that to happen?

Here is a screenshot of New Relic showing the spike in Middleware:

New Relic chart showing time spent in Request Queuing increase to 20s, Middleware increase to 40s, and Ruby increase to 14s, then crashing. After that, time spent in Request Queue is always 20s

And here are the files where I set the middleware and database connections:

config/puma.rb

threads_count = Integer(5)
threads threads_count, threads_count

preload_app!

rackup      DefaultRackup
port        ENV['PORT']     || 3000
environment ENV['RACK_ENV'] || 'development'

on_worker_boot do
    ActiveSupport.on_load(:active_record) do
        db = URI.parse(ENV['DATABASE_URL'])
        ActiveRecord::Base.establish_connection(
            :adapter  => db.scheme == 'postgres' ? 'postgresql' : db.scheme,
            :host     => db.host,
            :username => db.user,
            :password => db.password,
            :database => db.path[1..-1],
            :port => db.port,
            :encoding => 'utf8',
            :reaping_frequency => 10
            :pool => 5
            :timeout => 11
        )
    end
end

config.ru

require "rack-timeout"
use Rack::Timeout, service_timeout: 16, wait_timeout: 23

require './web'

run Sinatra::Application
use ActiveRecord::ConnectionAdapters::ConnectionManagement

rakefile.rb

require "./web"
require "sinatra/activerecord/rake"

Gemfile

source 'https://rubygems.org'
ruby '2.3.1'
gem 'rack-timeout'
gem 'rake'
gem 'sinatra'
gem 'puma', "~> 2.16.0"
gem 'pg'
gem "activerecord", "< 5.0.0" # h/t https://github.com/janko-m/sinatra-activerecord/pull/66
gem 'activesupport'
gem 'sinatra-activerecord'
gem 'redis'
gem 'tilt'

Logfile from a time when the app crashed

app/web.2:  Rack app error: #<Rack::Timeout::RequestTimeoutError: Request waited 783ms, then ran for longer than 15000ms> 
app/web.2: /app/vendor/bundle/ruby/2.3.0/gems/activerecord-4.2.7.1/lib/active_record/connection_adapters/postgresql/database_statements.rb:155:in `async_exec' 
app/web.2:  #<Rack::Timeout::RequestExpiryError: Request older than 30000ms.> 

Additional Logfile with error that occasionally occurs before app crashes

app/web.2: /app/vendor/ruby-2.3.1/lib/ruby/2.3.0/monitor.rb:187:in `lock', deadlock; recursive locking
Answers
Source Show
◀ Wstecz