What is causing my Rack middleware to spike?

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:

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

Answer 1

based on this line of the timeout error backtrace:

/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'

It would appear that at the moment the request was forcibly timed out (Rack::Timeout) that active record was in the midst of this async_exec call to your database.

Based on the other error you've posted:

/app/vendor/ruby-2.3.1/lib/ruby/2.3.0/monitor.rb:187:in `lock', deadlock; recursive locking

I would say it is apparent that the postgres connection adapter encountered a deadlock.

It isn't apparent whether the deadlock is occuring within postgres and bubbling up to active record or if the deadlock is occurring in the connection adapter code. Do you have any slow queries logged in postgres? The deadlock error could just be a symptom of using Rack::Timeout (or just the Timeout ruby class) while using threads. It could be that a thread reached a timeout because of a slow query, had a Timeout::Error raised and the connection / mutex in the connection management became unstable / mismanaged.