Skip to content
This repository

[1.6.7-HEAD] ConcurrencyError in safe code #141

Closed
arturaz opened this Issue April 23, 2012 · 10 comments

2 participants

Artūras Šlajus Charles Oliver Nutter
Artūras Šlajus

Problem

I'm getting ConcurrencyError in monitor synchronized code (inside ActiveRecord).

Code

      # Check-in a database connection back into the pool, indicating that you
      # no longer need this connection.
      #
      # +conn+: an AbstractAdapter object, which was obtained by earlier by
      # calling +checkout+ on this pool.
      def checkin(conn)
        synchronize do
          conn.run_callbacks :checkin do
            conn.expire
            @queue.signal
          end

          release conn
        end
      end

      private

      # This method is only called from #checkin, which is synchronized by +MonitorMixin+.
      def release(conn)
        thread_id = nil

        if @reserved_connections[current_connection_id] == conn
          thread_id = current_connection_id
        else
          thread_id = @reserved_connections.keys.find { |k| # Error in this line
            @reserved_connections[k] == conn
          }
        end

        @reserved_connections.delete thread_id if thread_id
      end

Error

Server launched with: --1.9 -J-Dname=nebula_server -J-Djruby.jit.max=25000
--server -J-XX:+TieredCompilation -J-XX:-UseLoopPredicate
-Xbacktrace.style=raw -X+C -J-XX:MaxPermSize=256m

Server has encountered an error!

[2012-04-22 20:44:50.981|worker-world_2|main|error] Threading::Worker crashed!
ConcurrencyError: Detected invalid hash contents due to unsynchronized modifications with concurrent users
java/lang/Thread.java:1567:in `getStackTrace'
org/jruby/runtime/backtrace/TraceType.java:59:in `getBacktraceData'
org/jruby/runtime/backtrace/TraceType.java:111:in `getBacktraceData'
org/jruby/runtime/backtrace/TraceType.java:25:in `getBacktrace'
org/jruby/RubyException.java:160:in `prepareBacktrace'
org/jruby/exceptions/RaiseException.java:205:in `preRaise'
org/jruby/exceptions/RaiseException.java:195:in `preRaise'
org/jruby/exceptions/RaiseException.java:112:in `<init>'
org/jruby/Ruby.java:3381:in `newRaiseException'
org/jruby/Ruby.java:3206:in `newConcurrencyError'
org/jruby/RubyHash.java:1913:in `concurrentModification'
org/jruby/RubyHash.java:1356:in `keys'
org/jruby/RubyHash$i$0$0$keys.gen:65535:in `call'
org/jruby/runtime/callsite/CachingCallSite.java:133:in `call'
/home/spacegame/nebula-server/20120422201639/vendor/bundle/jruby/1.9/gems/activerecord-3.2.3/lib/active_record/connection_adapters/abstract/connection_pool.rb:294:in `release'
home$spacegame$nebula_minus_server$$20120422201639$vendor$bundle$jruby$$1_dot_9$gems$activerecord_minus_3_dot_2_dot_3$lib$active_record$connection_adapters$abstract$connection_pool$method__21$RUBY$release:65535:in `call'
home$spacegame$nebula_minus_server$$20120422201639$vendor$bundle$jruby$$1_dot_9$gems$activerecord_minus_3_dot_2_dot_3$lib$active_record$connection_adapters$abstract$connection_pool$method__21$RUBY$release:65535:in `call'
org/jruby/runtime/callsite/CachingCallSite.java:167:in `call'
/home/spacegame/nebula-server/20120422201639/vendor/bundle/jruby/1.9/gems/activerecord-3.2.3/lib/active_record/connection_adapters/abstract/connection_pool.rb:282:in `checkin'
home$spacegame$nebula_minus_server$$20120422201639$vendor$bundle$jruby$$1_dot_9$gems$activerecord_minus_3_dot_2_dot_3$lib$active_record$connection_adapters$abstract$connection_pool$block_19$RUBY$checkin:65535:in `call'
org/jruby/runtime/CompiledBlock19.java:121:in `yieldSpecificInternal'
org/jruby/runtime/CompiledBlock19.java:96:in `yieldSpecific'
org/jruby/runtime/Block.java:99:in `yieldSpecific'
/usr/local/rvm/rubies/jruby-head-n16/lib/ruby/1.9/monitor.rb:201:in `__ensure__'
/usr/local/rvm/rubies/jruby-head-n16/lib/ruby/1.9/monitor.rb:200:in `mon_synchronize'
usr$local$rvm$rubies$jruby_minus_head_minus_n16$lib$ruby$$1_dot_9$monitor$method__14$RUBY$mon_synchronize:65535:in `call'
org/jruby/internal/runtime/methods/AliasMethod.java:81:in `call'
org/jruby/runtime/callsite/CachingCallSite.java:142:in `callBlock'
org/jruby/runtime/callsite/CachingCallSite.java:153:in `callIter'
/home/spacegame/nebula-server/20120422201639/vendor/bundle/jruby/1.9/gems/activerecord-3.2.3/lib/active_record/connection_adapters/abstract/connection_pool.rb:276:in `checkin'
home$spacegame$nebula_minus_server$$20120422201639$vendor$bundle$jruby$$1_dot_9$gems$activerecord_minus_3_dot_2_dot_3$lib$active_record$connection_adapters$abstract$connection_pool$method__20$RUBY$checkin:65535:in `call'
home$spacegame$nebula_minus_server$$20120422201639$vendor$bundle$jruby$$1_dot_9$gems$activerecord_minus_3_dot_2_dot_3$lib$active_record$connection_adapters$abstract$connection_pool$method__20$RUBY$checkin:65535:in `call'
org/jruby/runtime/callsite/CachingCallSite.java:167:in `call'
/home/spacegame/nebula-server/20120422201639/vendor/bundle/jruby/1.9/gems/activerecord-3.2.3/lib/active_record/connection_adapters/abstract/connection_pool.rb:110:in `release_connection'
home$spacegame$nebula_minus_server$$20120422201639$vendor$bundle$jruby$$1_dot_9$gems$activerecord_minus_3_dot_2_dot_3$lib$active_record$connection_adapters$abstract$connection_pool$method__7$RUBY$release_connection:65535:in `call'
org/jruby/internal/runtime/methods/DynamicMethod.java:211:in `call'
org/jruby/internal/runtime/methods/CompiledMethod.java:260:in `call'
org/jruby/runtime/callsite/CachingCallSite.java:167:in `call'
/home/spacegame/nebula-server/20120422201639/vendor/bundle/jruby/1.9/gems/activerecord-3.2.3/lib/active_record/connection_adapters/abstract/connection_pool.rb:121:in `__ensure__'
home$spacegame$nebula_minus_server$$20120422201639$vendor$bundle$jruby$$1_dot_9$gems$activerecord_minus_3_dot_2_dot_3$lib$active_record$connection_adapters$abstract$connection_pool$method__8$RUBY$with_connection:65535:in `call'
org/jruby/internal/runtime/methods/AliasMethod.java:81:in `call'
org/jruby/runtime/callsite/CachingCallSite.java:142:in `callBlock'
org/jruby/runtime/callsite/CachingCallSite.java:153:in `callIter'
/home/spacegame/nebula-server/20120422201639/lib/server/monkey_squad.rb:42:in `with_connection'
home$spacegame$nebula_minus_server$$20120422201639$lib$server$monkey_squad$method__9$RUBY$with_connection:65535:in `call'
org/jruby/runtime/callsite/CachingCallSite.java:142:in `callBlock'
org/jruby/runtime/callsite/CachingCallSite.java:153:in `callIter'
/home/spacegame/nebula-server/20120422201639/lib/server/threading/director/task.rb:31:in `run'
home$spacegame$nebula_minus_server$$20120422201639$lib$server$threading$director$task$method__5$RUBY$run:65535:in `call'
home$spacegame$nebula_minus_server$$20120422201639$lib$server$threading$director$task$method__5$RUBY$run:65535:in `call'
org/jruby/runtime/callsite/CachingCallSite.java:167:in `call'
/home/spacegame/nebula-server/20120422201639/lib/server/threading/worker.rb:21:in `work'
home$spacegame$nebula_minus_server$$20120422201639$lib$server$threading$worker$block_1$RUBY$work:65535:in `call'
org/jruby/runtime/CompiledBlock19.java:121:in `yieldSpecificInternal'
org/jruby/runtime/CompiledBlock19.java:96:in `yieldSpecific'
org/jruby/runtime/Block.java:99:in `yieldSpecific'
/home/spacegame/nebula-server/20120422201639/lib/server/logging/logger.rb:57:in `block'
home$spacegame$nebula_minus_server$$20120422201639$lib$server$logging$logger$method__2$RUBY$block:65535:in `call'
org/jruby/internal/runtime/methods/DynamicMethod.java:219:in `call'
org/jruby/RubyClass.java:611:in `finvoke'
org/jruby/RubyBasicObject.java:1710:in `send19'
org/jruby/RubyKernel.java:2108:in `send19'
org/jruby/RubyKernel$s$send19.gen:65535:in `call'
org/jruby/runtime/callsite/CachingCallSite.java:244:in `callBlock'
org/jruby/runtime/callsite/CachingCallSite.java:250:in `call'
org/jruby/runtime/callsite/CachingCallSite.java:114:in `callVarargs'
/home/spacegame/nebula-server/20120422201639/lib/server/logging/thread_router.rb:7:in `method_missing'
home$spacegame$nebula_minus_server$$20120422201639$lib$server$logging$thread_router$method__1$RUBY$method_missing:65535:in `call'
org/jruby/javasupport/util/RuntimeHelpers.java:497:in `call'
org/jruby/internal/runtime/methods/DynamicMethod.java:219:in `call'
org/jruby/runtime/callsite/CachingCallSite.java:403:in `callMethodMissing'
org/jruby/runtime/callsite/CachingCallSite.java:339:in `cacheAndCall'
org/jruby/runtime/callsite/CachingCallSite.java:212:in `callBlock'
org/jruby/runtime/callsite/CachingCallSite.java:221:in `callIter'
/home/spacegame/nebula-server/20120422201639/lib/server/threading/worker.rb:20:in `work'
home$spacegame$nebula_minus_server$$20120422201639$lib$server$threading$worker$block_0$RUBY$work:65535:in `call'
org/jruby/runtime/CompiledBlock19.java:121:in `yieldSpecificInternal'
org/jruby/runtime/CompiledBlock19.java:96:in `yieldSpecific'
org/jruby/runtime/Block.java:99:in `yieldSpecific'
/home/spacegame/nebula-server/20120422201639/vendor/bundle/jruby/1.9/bundler/gems/celluloid-53b31cb209dd/lib/celluloid/actor.rb:122:in `__ensure__'
home$spacegame$nebula_minus_server$$20120422201639$vendor$bundle$jruby$$1_dot_9$bundler$gems$celluloid_minus_53b31cb209dd$lib$celluloid$actor$method__18$RUBY$exclusive:65535:in `call'
org/jruby/runtime/callsite/CachingCallSite.java:142:in `callBlock'
org/jruby/runtime/callsite/CachingCallSite.java:148:in `call'
/home/spacegame/nebula-server/20120422201639/vendor/bundle/jruby/1.9/bundler/gems/celluloid-53b31cb209dd/lib/celluloid.rb:270:in `exclusive'
home$spacegame$nebula_minus_server$$20120422201639$vendor$bundle$jruby$$1_dot_9$bundler$gems$celluloid_minus_53b31cb209dd$lib$celluloid$method__41$RUBY$exclusive:65535:in `call'
org/jruby/runtime/callsite/CachingCallSite.java:142:in `callBlock'
org/jruby/runtime/callsite/CachingCallSite.java:153:in `callIter'
/home/spacegame/nebula-server/20120422201639/lib/server/threading/worker.rb:19:in `work'
home$spacegame$nebula_minus_server$$20120422201639$lib$server$threading$worker$method__3$RUBY$work:65535:in `call'
org/jruby/RubyClass.java:592:in `finvoke'
org/jruby/RubyBasicObject.java:1704:in `send19'
org/jruby/RubyKernel.java:2104:in `send19'
org/jruby/RubyKernel$s$send19.gen:65535:in `call'
org/jruby/runtime/callsite/CachingCallSite.java:342:in `cacheAndCall'
org/jruby/runtime/callsite/CachingCallSite.java:212:in `callBlock'
org/jruby/runtime/callsite/CachingCallSite.java:216:in `call'
org/jruby/runtime/callsite/CachingCallSite.java:113:in `callVarargs'
/home/spacegame/nebula-server/20120422201639/vendor/bundle/jruby/1.9/bundler/gems/celluloid-53b31cb209dd/lib/celluloid/calls.rb:98:in `dispatch'
home$spacegame$nebula_minus_server$$20120422201639$vendor$bundle$jruby$$1_dot_9$bundler$gems$celluloid_minus_53b31cb209dd$lib$celluloid$calls$method__16$RUBY$dispatch:65535:in `call'
home$spacegame$nebula_minus_server$$20120422201639$vendor$bundle$jruby$$1_dot_9$bundler$gems$celluloid_minus_53b31cb209dd$lib$celluloid$calls$method__16$RUBY$dispatch:65535:in `call'
org/jruby/runtime/callsite/CachingCallSite.java:167:in `call'
/home/spacegame/nebula-server/20120422201639/vendor/bundle/jruby/1.9/bundler/gems/celluloid-53b31cb209dd/lib/celluloid/actor.rb:223:in `handle_message'
home$spacegame$nebula_minus_server$$20120422201639$vendor$bundle$jruby$$1_dot_9$bundler$gems$celluloid_minus_53b31cb209dd$lib$celluloid$actor$block_9$RUBY$handle_message:65535:in `call'
org/jruby/runtime/CompiledBlock19.java:121:in `yieldSpecificInternal'
org/jruby/runtime/CompiledBlock19.java:96:in `yieldSpecific'
org/jruby/runtime/Block.java:99:in `yieldSpecific'
/home/spacegame/nebula-server/20120422201639/vendor/bundle/jruby/1.9/bundler/gems/celluloid-53b31cb209dd/lib/celluloid/task.rb:45:in `initialize'
/home/spacegame/nebula-server/20120422201639/vendor/bundle/jruby/1.9/bundler/gems/celluloid-53b31cb209dd/lib/celluloid/task.rb:44:in `initialize'
home$spacegame$nebula_minus_server$$20120422201639$vendor$bundle$jruby$$1_dot_9$bundler$gems$celluloid_minus_53b31cb209dd$lib$celluloid$task$block_0$RUBY$initialize:65535:in `call'
org/jruby/runtime/CompiledBlock19.java:163:in `yield'
org/jruby/runtime/CompiledBlock19.java:149:in `yield'
org/jruby/runtime/Block.java:146:in `yieldArray'
org/jruby/ext/fiber/ThreadFiber.java:38:in `run'
java/util/concurrent/ThreadPoolExecutor.java:1110:in `runWorker'
java/util/concurrent/ThreadPoolExecutor.java:603:in `run'
java/lang/Thread.java:722:in `run'
Charles Oliver Nutter
Owner

Ok, so here's the deal. I see no synchronization of the reserved connections hash in the release method. That synchronization might be happening somewhere else, but if it's not this could certainly be a problem in AR.

Non-thread-safe resources need to be synchronized on read and write, since reading from a resource while it is being written can cause exactly the same problems as two writes at the same time.

You could try as a workaround the following code, which must run after the the specified resource is available (some time late in boot):

require 'jruby'

that_connection_pool.extend JRuby::Synchronized

This will wrap all methods with synchronization...which is a blunt tool, but it might prove there's some sync missing in AR itself.

Artūras Šlajus

Did you see the comment?

This method is only called from #checkin, which is synchronized by +MonitorMixin+

Charles Oliver Nutter
Owner

Ok, I missed that. However my point does still stand...the monitor should be guaranteeing only one thread is active at a time, which should prevent the concurrency error. But it does give me pause...we have cases where an internal exception was improperly masked as a concurrency error. I'll look into the code a bit more.

Charles Oliver Nutter
Owner

Ok, so far I see no clear indication that this would be a JRuby bug. I'd recommend trying the JRuby::Synchronized mechanism and opening a bug with Rails. I'll support you there.

Artūras Šlajus
Charles Oliver Nutter
Owner

Anything's possible, but that seems unlikely.

The synchronize method here is mon_synchronize from MonitorMixin. mon_synchronize acquires the lock (a mutex in @mon_mutex in mon_enter, and releases it in mon_exit. The code within that block should be guaranteed to only run in one thread at a time, and I see no obvious bugs in the library.

I also reviewed commit logs for monitor.rb. Within the past 4 years, almost no changes have been made other than formatting and style changes. The most recent substantive change was in 2007, but we're using files much newer than that and even then the changes were ok.

Mutex acquisition and release in JRuby is implemented in the Mutex class, which uses either Java synchronization (object monitors) or a ReentrantLock. The implementation is quite simple, and I would not expect there to be bugs.

So...it's certainly possible there's something I've missed, but I still tend to believe there's an issue in Rails where they're not controlling access to this cache everywhere they should be.

Artūras Šlajus
arturaz commented May 05, 2012

NameError: uninitialized constant JRuby::Synchronized

On 1.6.8-dev

Artūras Šlajus
arturaz commented May 09, 2012

Tossed this to Rails guys, no response so far...

Charles Oliver Nutter
Owner
headius commented May 09, 2012

Oops, I botched my example...you need to require 'jruby/synchronized' for JRuby::Synchronized.

Artūras Šlajus
arturaz commented May 26, 2012

Ok, it seems that this is rails bug afterall...

      def connection
        @reserved_connections[current_connection_id] ||= checkout
      end
      def release_connection(with_id = current_connection_id)
        conn = @reserved_connections.delete(with_id)
        checkin conn if conn
      end

No sync!

Artūras Šlajus arturaz closed this May 26, 2012
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Something went wrong with that request. Please try again.