When you use ActiveRecord in Sinatra + Thin, you may run into a timeout like the following.

ActiveRecord::ConnectionTimeoutError: could not obtain a database connection
within 5.000 seconds (waited 5.002 seconds)

You may find the timeout even if you use middleware ConnectionManagement. This is a serious problem.

One possible reason for the timeout is that connections do not return to ActiveRecord’s connection pool after use. If you are not using ConnectionManagement or you want to try a solution right away, go to How do I release ActiveRecord connections?. If you are using ConnectionManagement, you may be running Thin in threaded mode and thus not closing or returning to the pool any connections. Keep reading for an explanation.

EDIT 2016-05-31

I followed up the issue with macournoyer and the problem is fixed in version 1.7.0 of Thin. The newsletter API example does not run out of connections with that version of Thin. Kudos to macournoyer!

ActiveRecord 4.2 and Thin 1.6 threaded mode do not get along

There are two reasons why ActiveRecord’s ConnectionManagement does not release database connections under Thin’s threaded mode. One reason is that ConnectionManagement releases only the one connection that is open for the current thread. The other reason is that for each HTTP request, Thin executes the corresponding Sinatra route handler in one thread and applies ConnectionManagement in another thread.

To illustrate the situation, consider the following newsletter API.

  1 #!/usr/bin/env ruby
  2 
  3 require 'sinatra/base'
  4 require 'active_record'
  5 
  6 ActiveRecord::Base.establish_connection(adapter:  'sqlite3',
  7                                         database: 'newsletter.db')
  8 
  9 class Subscriber < ActiveRecord::Base
 10   validates :email, presence: true
 11 end
 12 
 13 class Newsletter < Sinatra::Base
 14   set :server, :thin
 15   use ActiveRecord::ConnectionAdapters::ConnectionManagement
 16 
 17   put '/subscribers/:email' do
 18     Subscriber.create(email: params[:email])
 19     puts Kernel.caller
 20   end
 21 end
 22 
 23 Newsletter.run!

To run the API, copy paste the contents in file newsletter.rb, give execution permissions, and execute newsletter.rb like so.

ruslan$ ./newsletter.rb
== Sinatra (v1.4.7) has taken the stage on 4567 for development with backup from Thin
Thin web server (v1.6.4 codename Gob Bluth)
Maximum connections set to 1024
Listening on localhost:4567, CTRL+C to stop

When the API is running, register subscribers by putting to path /subscribers/:email like so.

ruslan$ curl --verbose -X PUT localhost:4567/subscribers/mrrusof@gmail.com
*   Trying ::1...
* Connected to localhost (::1) port 4567 (#0)
> PUT /subscribers/mrrusof@gmail.com HTTP/1.1
> Host: localhost:4567
> User-Agent: curl/7.43.0
> Accept: */*
>
< HTTP/1.1 200 OK
< Content-Type: text/html;charset=utf-8
< Content-Length: 0
< X-XSS-Protection: 1; mode=block
< X-Content-Type-Options: nosniff
< X-Frame-Options: SAMEORIGIN
< Connection: keep-alive
< Server: thin
<
* Connection #0 to host localhost left intact

When we register a subscriber, the call stack printed by line newsletter.rb:19 is the following.

ruslan$ ./newsletter.rb
== Sinatra (v1.4.7) has taken the stage on 4567 for development with backup from Thin
Thin web server (v1.6.4 codename Gob Bluth)
Maximum connections set to 1024
Listening on localhost:4567, CTRL+C to stop
/Users/ruslan/.rvm/gems/ruby-2.2.1/gems/sinatra-1.4.7/lib/sinatra/base.rb:1611:in `call'
/Users/ruslan/.rvm/gems/ruby-2.2.1/gems/sinatra-1.4.7/lib/sinatra/base.rb:1611:in `block in compile!'
/Users/ruslan/.rvm/gems/ruby-2.2.1/gems/sinatra-1.4.7/lib/sinatra/base.rb:975:in `[]'
/Users/ruslan/.rvm/gems/ruby-2.2.1/gems/sinatra-1.4.7/lib/sinatra/base.rb:975:in `block (3 levels) in route!'
/Users/ruslan/.rvm/gems/ruby-2.2.1/gems/sinatra-1.4.7/lib/sinatra/base.rb:994:in `route_eval'
/Users/ruslan/.rvm/gems/ruby-2.2.1/gems/sinatra-1.4.7/lib/sinatra/base.rb:975:in `block (2 levels) in route!'
/Users/ruslan/.rvm/gems/ruby-2.2.1/gems/sinatra-1.4.7/lib/sinatra/base.rb:1015:in `block in process_route'
/Users/ruslan/.rvm/gems/ruby-2.2.1/gems/sinatra-1.4.7/lib/sinatra/base.rb:1013:in `catch'
/Users/ruslan/.rvm/gems/ruby-2.2.1/gems/sinatra-1.4.7/lib/sinatra/base.rb:1013:in `process_route'
/Users/ruslan/.rvm/gems/ruby-2.2.1/gems/sinatra-1.4.7/lib/sinatra/base.rb:973:in `block in route!'
/Users/ruslan/.rvm/gems/ruby-2.2.1/gems/sinatra-1.4.7/lib/sinatra/base.rb:972:in `each'
/Users/ruslan/.rvm/gems/ruby-2.2.1/gems/sinatra-1.4.7/lib/sinatra/base.rb:972:in `route!'
/Users/ruslan/.rvm/gems/ruby-2.2.1/gems/sinatra-1.4.7/lib/sinatra/base.rb:1085:in `block in dispatch!'
/Users/ruslan/.rvm/gems/ruby-2.2.1/gems/sinatra-1.4.7/lib/sinatra/base.rb:1067:in `block in invoke'
/Users/ruslan/.rvm/gems/ruby-2.2.1/gems/sinatra-1.4.7/lib/sinatra/base.rb:1067:in `catch'
/Users/ruslan/.rvm/gems/ruby-2.2.1/gems/sinatra-1.4.7/lib/sinatra/base.rb:1067:in `invoke'
/Users/ruslan/.rvm/gems/ruby-2.2.1/gems/sinatra-1.4.7/lib/sinatra/base.rb:1082:in `dispatch!'
/Users/ruslan/.rvm/gems/ruby-2.2.1/gems/sinatra-1.4.7/lib/sinatra/base.rb:907:in `block in call!'
/Users/ruslan/.rvm/gems/ruby-2.2.1/gems/sinatra-1.4.7/lib/sinatra/base.rb:1067:in `block in invoke'
/Users/ruslan/.rvm/gems/ruby-2.2.1/gems/sinatra-1.4.7/lib/sinatra/base.rb:1067:in `catch'
/Users/ruslan/.rvm/gems/ruby-2.2.1/gems/sinatra-1.4.7/lib/sinatra/base.rb:1067:in `invoke'
/Users/ruslan/.rvm/gems/ruby-2.2.1/gems/sinatra-1.4.7/lib/sinatra/base.rb:907:in `call!'
/Users/ruslan/.rvm/gems/ruby-2.2.1/gems/sinatra-1.4.7/lib/sinatra/base.rb:895:in `call'
/Users/ruslan/.rvm/gems/ruby-2.2.1/gems/activerecord-4.2.6/lib/active_record/connection_adapters/abstract/connection_pool.rb:653:in `call'
/Users/ruslan/.rvm/gems/ruby-2.2.1/gems/rack-protection-1.5.3/lib/rack/protection/xss_header.rb:18:in `call'
/Users/ruslan/.rvm/gems/ruby-2.2.1/gems/rack-protection-1.5.3/lib/rack/protection/path_traversal.rb:16:in `call'
/Users/ruslan/.rvm/gems/ruby-2.2.1/gems/rack-protection-1.5.3/lib/rack/protection/json_csrf.rb:18:in `call'
/Users/ruslan/.rvm/gems/ruby-2.2.1/gems/rack-protection-1.5.3/lib/rack/protection/base.rb:49:in `call'
/Users/ruslan/.rvm/gems/ruby-2.2.1/gems/rack-protection-1.5.3/lib/rack/protection/base.rb:49:in `call'
/Users/ruslan/.rvm/gems/ruby-2.2.1/gems/rack-protection-1.5.3/lib/rack/protection/frame_options.rb:31:in `call'
/Users/ruslan/.rvm/gems/ruby-2.2.1/gems/rack-1.6.4/lib/rack/nulllogger.rb:9:in `call'
/Users/ruslan/.rvm/gems/ruby-2.2.1/gems/rack-1.6.4/lib/rack/head.rb:13:in `call'
/Users/ruslan/.rvm/gems/ruby-2.2.1/gems/sinatra-1.4.7/lib/sinatra/show_exceptions.rb:25:in `call'
/Users/ruslan/.rvm/gems/ruby-2.2.1/gems/sinatra-1.4.7/lib/sinatra/base.rb:182:in `call'
/Users/ruslan/.rvm/gems/ruby-2.2.1/gems/sinatra-1.4.7/lib/sinatra/base.rb:2013:in `call'
/Users/ruslan/.rvm/gems/ruby-2.2.1/gems/sinatra-1.4.7/lib/sinatra/base.rb:1487:in `block in call'
/Users/ruslan/.rvm/gems/ruby-2.2.1/gems/sinatra-1.4.7/lib/sinatra/base.rb:1787:in `synchronize'
/Users/ruslan/.rvm/gems/ruby-2.2.1/gems/sinatra-1.4.7/lib/sinatra/base.rb:1487:in `call'
/Users/ruslan/.rvm/gems/ruby-2.2.1/gems/thin-1.6.4/lib/thin/connection.rb:86:in `block in pre_process'
/Users/ruslan/.rvm/gems/ruby-2.2.1/gems/thin-1.6.4/lib/thin/connection.rb:84:in `catch'
/Users/ruslan/.rvm/gems/ruby-2.2.1/gems/thin-1.6.4/lib/thin/connection.rb:84:in `pre_process'
/Users/ruslan/.rvm/gems/ruby-2.2.1/gems/eventmachine-1.2.0.1/lib/eventmachine.rb:1076:in `call'
/Users/ruslan/.rvm/gems/ruby-2.2.1/gems/eventmachine-1.2.0.1/lib/eventmachine.rb:1076:in `block in spawn_threadpool'

The following line of the call stack indicates that the execution of route handler for /subscribers/:email is preceded by a call to method ConnectionManagement.call.

/Users/ruslan/.rvm/gems/ruby-2.2.1/gems/activerecord-4.2.6/lib/active_record/connection_adapters/abstract/connection_pool.rb:653:in `call'

We are using middleware ConnectionManagement because we asked for it in line newsletter.rb:15. The code of ConnectionManagement in file connection_pool.rb is the following.

645 class ConnectionManagement
646   def initialize(app)
647     @app = app
648   end
649
650   def call(env)
651     testing = env['rack.test']
652
653     response = @app.call(env)
654     response[2] = ::Rack::BodyProxy.new(response[2]) do
655       ActiveRecord::Base.clear_active_connections! unless testing
656     end
657
658     response
659   rescue Exception
660     ActiveRecord::Base.clear_active_connections! unless testing
661     raise
662   end
663 end

The route handler is executed during execution of line connection_pool.rb:653 and that is when a database connection is created for the current thread.

Line connnection_pool.rb:655 puportedly clears (releases) active connections, but only only for the current thread. The reason is that the sequence of calls that starts in that line eventually releases a default connection identified by a thread id. Consider the code for ActiveRecord::Base.clear_active_connections! in connection_pool.rb.

548 # Returns any connections in use by the current thread back to the pool,
549 # and also returns connections to the pool cached by threads that are no
550 # longer alive.
551 def clear_active_connections!
552   connection_pool_list.each(&:release_connection)
553 end

Line connection_pool.rb:552 calls ConnectionPool#release_connection for each existing thread. The code for ConnectionPool#release_connection is the following.

276 # Signal that the thread is finished with the current connection.
277 # #release_connection releases the connection-thread association
278 # and returns the connection to the pool.
279 def release_connection(with_id = current_connection_id)
280   synchronize do
281     conn = @reserved_connections.delete(with_id)
282     checkin conn if conn
283   end
284 end

The current connection id is the id of the current thread and is given by line connection_pool.rb:442.

441 def current_connection_id #:nodoc:
442   Base.connection_id ||= Thread.current.object_id
443 end

Thus, ConnectionPool#release_connection releases the connection that has the same id as the current thread id. When you take from a given pool p a connection in one thread and try to release that connection in another thread by a call to p.release_connection, you will not release anything.

Given the way ActiveRecord::Base.clear_active_connections! works, you may expect that lines 653 and 655 of connection_pool.rb execute in the same thread. They do not. You may verify this fact by inspecting the thread id and call stack for those lines in the following way.

class ConnectionManagement
  def initialize(app)
    @app = app
  end

  def call(env)
    testing = env['rack.test']

    puts '*******************************************************'
    puts 'ConnectionManagement.call'
    puts Kernel.caller
    puts "Thread.current.object_id = #{Thread.current.object_id}"
    puts '*******************************************************'
    response = @app.call(env)
    response[2] = ::Rack::BodyProxy.new(response[2]) do
      puts '*******************************************************'
      puts '::Rack::BodyProxy.new(response[2]) do'
      puts Kernel.caller
      puts "Thread.current.object_id = #{Thread.current.object_id}"
      puts '*******************************************************'
      ActiveRecord::Base.clear_active_connections! unless testing
    end

    response
  rescue Exception
    ActiveRecord::Base.clear_active_connections! unless testing
    raise
  end
end

The registration of the subscriber produces the following output.

ruslan$ ./newsletter.rb
== Sinatra (v1.4.7) has taken the stage on 4567 for development with backup from Thin
Thin web server (v1.6.4 codename Gob Bluth)
Maximum connections set to 1024
Listening on localhost:4567, CTRL+C to stop
*******************************************************************************
ConnectionManagement.call
/Users/ruslan/.rvm/gems/ruby-2.2.1/gems/rack-protection-1.5.3/lib/rack/protection/xss_header.rb:18:in `call'
/Users/ruslan/.rvm/gems/ruby-2.2.1/gems/rack-protection-1.5.3/lib/rack/protection/path_traversal.rb:16:in `call'
/Users/ruslan/.rvm/gems/ruby-2.2.1/gems/rack-protection-1.5.3/lib/rack/protection/json_csrf.rb:18:in `call'
/Users/ruslan/.rvm/gems/ruby-2.2.1/gems/rack-protection-1.5.3/lib/rack/protection/base.rb:49:in `call'
/Users/ruslan/.rvm/gems/ruby-2.2.1/gems/rack-protection-1.5.3/lib/rack/protection/base.rb:49:in `call'
/Users/ruslan/.rvm/gems/ruby-2.2.1/gems/rack-protection-1.5.3/lib/rack/protection/frame_options.rb:31:in `call'
/Users/ruslan/.rvm/gems/ruby-2.2.1/gems/rack-1.6.4/lib/rack/nulllogger.rb:9:in `call'
/Users/ruslan/.rvm/gems/ruby-2.2.1/gems/rack-1.6.4/lib/rack/head.rb:13:in `call'
/Users/ruslan/.rvm/gems/ruby-2.2.1/gems/sinatra-1.4.7/lib/sinatra/show_exceptions.rb:25:in `call'
/Users/ruslan/.rvm/gems/ruby-2.2.1/gems/sinatra-1.4.7/lib/sinatra/base.rb:182:in `call'
/Users/ruslan/.rvm/gems/ruby-2.2.1/gems/sinatra-1.4.7/lib/sinatra/base.rb:2013:in `call'
/Users/ruslan/.rvm/gems/ruby-2.2.1/gems/sinatra-1.4.7/lib/sinatra/base.rb:1487:in `block in call'
/Users/ruslan/.rvm/gems/ruby-2.2.1/gems/sinatra-1.4.7/lib/sinatra/base.rb:1787:in `synchronize'
/Users/ruslan/.rvm/gems/ruby-2.2.1/gems/sinatra-1.4.7/lib/sinatra/base.rb:1487:in `call'
/Users/ruslan/.rvm/gems/ruby-2.2.1/gems/thin-1.6.4/lib/thin/connection.rb:86:in `block in pre_process'
/Users/ruslan/.rvm/gems/ruby-2.2.1/gems/thin-1.6.4/lib/thin/connection.rb:84:in `catch'
/Users/ruslan/.rvm/gems/ruby-2.2.1/gems/thin-1.6.4/lib/thin/connection.rb:84:in `pre_process'
/Users/ruslan/.rvm/gems/ruby-2.2.1/gems/eventmachine-1.2.0.1/lib/eventmachine.rb:1076:in `call'
/Users/ruslan/.rvm/gems/ruby-2.2.1/gems/eventmachine-1.2.0.1/lib/eventmachine.rb:1076:in `block in spawn_threadpool'
Thread.current.object_id = 70307221466660
*******************************************************************************
...
*******************************************************************************
::Rack::BodyProxy.new(response[2]) do
/Users/ruslan/.rvm/gems/ruby-2.2.1/gems/rack-1.6.4/lib/rack/body_proxy.rb:18:in `call'
/Users/ruslan/.rvm/gems/ruby-2.2.1/gems/rack-1.6.4/lib/rack/body_proxy.rb:18:in `close'
/Users/ruslan/.rvm/gems/ruby-2.2.1/gems/thin-1.6.4/lib/thin/response.rb:83:in `close'
/Users/ruslan/.rvm/gems/ruby-2.2.1/gems/thin-1.6.4/lib/thin/connection.rb:142:in `close_request_response'
/Users/ruslan/.rvm/gems/ruby-2.2.1/gems/thin-1.6.4/lib/thin/connection.rb:154:in `terminate_request'
/Users/ruslan/.rvm/gems/ruby-2.2.1/gems/thin-1.6.4/lib/thin/connection.rb:130:in `post_process'
/Users/ruslan/.rvm/gems/ruby-2.2.1/gems/eventmachine-1.2.0.1/lib/eventmachine.rb:969:in `call'
/Users/ruslan/.rvm/gems/ruby-2.2.1/gems/eventmachine-1.2.0.1/lib/eventmachine.rb:969:in `run_deferred_callbacks'
/Users/ruslan/.rvm/gems/ruby-2.2.1/gems/eventmachine-1.2.0.1/lib/eventmachine.rb:194:in `run_machine'
/Users/ruslan/.rvm/gems/ruby-2.2.1/gems/eventmachine-1.2.0.1/lib/eventmachine.rb:194:in `run'
/Users/ruslan/.rvm/gems/ruby-2.2.1/gems/thin-1.6.4/lib/thin/backends/base.rb:73:in `start'
/Users/ruslan/.rvm/gems/ruby-2.2.1/gems/thin-1.6.4/lib/thin/server.rb:162:in `start'
/Users/ruslan/.rvm/gems/ruby-2.2.1/gems/rack-1.6.4/lib/rack/handler/thin.rb:19:in `run'
/Users/ruslan/.rvm/gems/ruby-2.2.1/gems/sinatra-1.4.7/lib/sinatra/base.rb:1506:in `start_server'
/Users/ruslan/.rvm/gems/ruby-2.2.1/gems/sinatra-1.4.7/lib/sinatra/base.rb:1444:in `run!'
./example.rb:37:in `<main>'
Thread.current.object_id = 70307218276860
*******************************************************************************

The thread ids and the call stacks are different, thus the call to ActiveRecord::Base.clear_active_connections! does not return the connection that was created in thread 70307221466660. We reach the default maximum count of active connections after registering the fifth subscriber. The API times out in subsequent requests.

To split or not to split hairs

I think that ActiveRecord’s ConnectionManagement and Thin should work together in threaded mode. I can think of three approaches for reconciling them.

However, reconciliation seems to be easier said than done for two reasons. One is that after raising the problem to macournoyer, I am not sure that Thin is responsible for accomodating to ActiveRecord’s ConnectionManagement approach to releasing connections. The other reason is that I am not sure that the recent elimination of ConnectionManagement from ActiveRecord takes the problem in consideration and thus raising the problem to ActiveRecord may be complicated.

How do I release ActiveRecord connections?

Whether Sinatra, ActiveRecord, and Thin reconcile or not, you will still want to clear active connections. For Sinatra 1.4, ActiveRecord 4.2, and Thin 1.6 running in threaded mode, one way of releasing connections is calling ActiveRecord::Base.clear_active_connections! in an after filter, like so.

after do
  ActiveRecord::Base.clear_active_connections!
end

Some people suggest closing all connections altogether by calling ActiveRecord::Base.connection.close, but that’s not always necessary.

Comments