Synchronize read and modification of @reserved_connections

[pmahoney]

I am running JRuby 1.6.7 (1.6.6 locally) on Glassfishv3, OpenJDK. I am running a Rack
application that uses ActiveRecord 3.0.12 and/or 3.2.3. Glassfish
maintains a thread pool which it uses to service HTTP requests in a
multithreaded fashion. I am running into concurrency problems.

I have created a small JRuby-only test script that, at least on my
machine, reliably triggers the error. The script sets up active
record and then in a thread pool with 32 threads acquires and releases
connections from the connection pool.

With activerecord 3.2.3 and master (2012-05-19) I see the following error:

Detected invalid hash contents due to unsynchronized modifications with concurrent users org/jruby/RubyHash.java:1356:in `keys'
  /home/pat/dev/ruby/rails/activerecord/lib/active_record/connection_adapters/abstract/connection_pool.rb:292:in `release'
  /home/pat/dev/ruby/rails/activerecord/lib/active_record/connection_adapters/abstract/connection_pool.rb:255:in `checkin'
  /home/pat/.rbenv/versions/jruby-1.6.6/lib/ruby/1.9/monitor.rb:201:in `mon_synchronize'
  /home/pat/.rbenv/versions/jruby-1.6.6/lib/ruby/1.9/monitor.rb:200:in `mon_synchronize'
  /home/pat/dev/ruby/rails/activerecord/lib/active_record/connection_adapters/abstract/connection_pool.rb:250:in `checkin'
  /home/pat/dev/ruby/rails/activerecord/lib/active_record/connection_adapters/abstract/connection_pool.rb:158:in `release_connection'
  /home/pat/.rbenv/versions/jruby-1.6.6/lib/ruby/1.9/monitor.rb:201:in `mon_synchronize'
  /home/pat/.rbenv/versions/jruby-1.6.6/lib/ruby/1.9/monitor.rb:200:in `mon_synchronize'
  /home/pat/dev/ruby/rails/activerecord/lib/active_record/connection_adapters/abstract/connection_pool.rb:156:in `release_connection'
  /home/pat/dev/ruby/rails/activerecord/lib/active_record/connection_adapters/abstract/connection_pool.rb:373:in `clear_active_connections!'
  org/jruby/RubyHash.java:1229:in `each_value'
  /home/pat/dev/ruby/rails/activerecord/lib/active_record/connection_adapters/abstract/connection_pool.rb:373:in `clear_active_connections!'
  /home/pat/dev/ruby/rails/activerecord/lib/active_record/connection_handling.rb:93:in `clear_active_connections!'
  ar_test.rb:85:in `(root)'
  org/jruby/RubyProc.java:258:in `call'

After applying my patch, I do not get the concurrency error. I am
also able to run the test suite for sqlite3 and postgresql.

$ bundle exec rake test_sqlite3
Finished tests in 189.794817s, 17.5242 tests/s, 53.2839 assertions/s.
3326 tests, 10113 assertions, 0 failures, 0 errors, 12 skips

$ bundle exec rake test_postgresql
Finished tests in 232.008693s, 14.8874 tests/s, 45.3517 assertions/s.
3454 tests, 10522 assertions, 0 failures, 0 errors, 32 skips

---

After this patch, I do get another error with connection timeouts that
I am also seeing on my Glassfish system:

took 135.078s to acquire and release
execution expired /home/pat/dev/ruby/rails/activerecord/lib/active_record/connection_adapters/abstract/connection_pool.rb:106:in `await'
...

I believe it happens because the connection pool queue does not grant
a newly available connection to the first waiter in the queue. But
I'll leave for a future bug report; I'm yet not sure if ActiveRecord
or JRuby is at fault.

---

Here is the test script. The expected output is nothing. It prints
any exceptions that are raised. It runs for a long time, and may or
may not be able to reproduce the concurrency error, but on my system
it does reproduce it reliably. I'm not sure how to turn this script into a useful unit test,
mostly since it needs to run for a "long time" to even trigger the bug.
Any suggestions?

Executed like this:

bundle exec jruby --1.9 ar_test.rb

The Gemfile:

source 'http://rubygems.org'

gem 'activerecord-jdbch2-adapter'

gem 'activerecord', :path => '../rails/activerecord'
gem 'activesupport', :path => '../rails/activesupport'
gem 'activemodel', :path => '../rails/activemodel'
gem 'active_record_deprecated_finders', :path => '../active_record_deprecated_finders'

The script itself:

require 'java'

require 'active_record'
require 'thread'

config = {
  'adapter' => 'jdbch2',
  'database' => 'mem:db'
}

ActiveRecord::Base.establish_connection(config)
ActiveRecord::Base.clear_active_connections!

executor = Java::java.util.concurrent.Executors.newFixedThreadPool(32)

task = proc do
  t0 = Time.now
  begin
    ActiveRecord::Base.connection_pool.connection
    sleep (rand(50) / 1000.0)
    ActiveRecord::Base.clear_active_connections!
  rescue => e
    [Time.now - t0, e]
  else
    [Time.now, nil]
  end
end

n = 100000
(1..n).map do
  executor.submit(task)
end.map do |future|
  time, err = future.get
  if err
    puts "took #{time}s to acquire and release"
    puts "#{err.message} #{err.backtrace.join("\n\t")}"
  end
end

executor.shutdown

[carlosantoniodasilva]

/cc @tenderlove

[rajesh-jangam]

We are using the activerecord 3.2.6 gem and still hitting the same issue:

Completed 200 OK in 109ms (Views: 109.0ms | ActiveRecord: 0.0ms)
[2012-07-10 13:15:46] ERROR ConcurrencyError: Detected invalid hash contents due to unsynchronized modifications with concurrent users
org/jruby/RubyHash.java:1356:in keys' c:/jruby-1.6.7.2/lib/ruby/gems/1.8/gems/activerecord-3.2.6/lib/active_record/connection_adapters/abstract/connection_pool.rb:299:inrelease'
c:/jruby-1.6.7.2/lib/ruby/1.9/monitor.rb:201:in mon_synchronize' c:/jruby-1.6.7.2/lib/ruby/1.9/monitor.rb:200:inmon_synchronize'
c:/jruby-1.6.7.2/lib/ruby/gems/1.8/gems/activerecord-3.2.6/lib/active_record/connection_adapters/abstract/connection_pool.rb:293:in release' c:/jruby-1.6.7.2/lib/ruby/gems/1.8/gems/activerecord-3.2.6/lib/active_record/connection_adapters/abstract/connection_pool.rb:286:incheckin'
c:/jruby-1.6.7.2/lib/ruby/1.9/monitor.rb:201:in mon_synchronize' c:/jruby-1.6.7.2/lib/ruby/1.9/monitor.rb:200:inmon_synchronize'
c:/jruby-1.6.7.2/lib/ruby/gems/1.8/gems/activerecord-3.2.6/lib/active_record/connection_adapters/abstract/connection_pool.rb:280:in checkin' c:/jruby-1.6.7.2/lib/ruby/gems/1.8/gems/activerecord-3.2.6/lib/active_record/connection_adapters/abstract/connection_pool.rb:114:inrelease_connection'
c:/jruby-1.6.7.2/lib/ruby/gems/1.8/gems/activerecord-3.2.6/lib/active_record/connection_adapters/abstract/connection_pool.rb:381:in clear_active_connections!' org/jruby/RubyHash.java:1229:ineach_value'
c:/jruby-1.6.7.2/lib/ruby/gems/1.8/gems/activerecord-3.2.6/lib/active_record/connection_adapters/abstract/connection_pool.rb:381:in clear_active_connections!' c:/jruby-1.6.7.2/lib/ruby/gems/1.8/gems/activerecord-3.2.6/lib/active_record/connection_adapters/abstract/connection_specification.rb:181:inclear_active_connections!'
c:/jruby-1.6.7.2/lib/ruby/gems/1.8/gems/activerecord-3.2.6/lib/active_record/connection_adapters/abstract/connection_pool.rb:462:in close' c:/jruby-1.6.7.2/lib/ruby/gems/1.8/gems/actionpack-3.2.6/lib/action_dispatch/middleware/body_proxy.rb:16:inclose'
c:/jruby-1.6.7.2/lib/ruby/gems/1.8/gems/actionpack-3.2.6/lib/action_dispatch/middleware/body_proxy.rb:15:in close' c:/jruby-1.6.7.2/lib/ruby/gems/1.8/gems/rack-1.4.1/lib/rack/handler/webrick.rb:75:inservice'
c:/jruby-1.6.7.2/lib/ruby/gems/1.8/gems/rack-1.4.1/lib/rack/handler/webrick.rb:60:in service' c:/jruby-1.6.7.2/lib/ruby/1.9/webrick/httpserver.rb:111:inservice'
c:/jruby-1.6.7.2/lib/ruby/1.9/webrick/httpserver.rb:70:in run' c:/jruby-1.6.7.2/lib/ruby/1.9/webrick/httpserver.rb:48:inrun'
c:/jruby-1.6.7.2/lib/ruby/1.9/webrick/server.rb:183:in start_thread' c:/jruby-1.6.7.2/lib/ruby/1.9/webrick/server.rb:173:instart_thread'

[Altonymous]

We're seeing this error as well, running jruby 1.7.1 and activerecord-jdbcmssql-adapter