waiting to lock <0x00000000e5b7a0f0> (a org.jruby.util.ClassCache$OneShotClassLoader)
at org.jruby.javasupport.util.RuntimeHelpers.constructSingletonMethod(RuntimeHelpers.java:1851)
at org.jruby.javasupport.util.RuntimeHelpers.defs(RuntimeHelpers.java:376)
at rubyjit.adapt_response_F74415CC503639C7FC52653D7CBFF09DABF3EBD9._file_(/opt/prod3.6.23/my_prod/3.6.0/tools/jruby/lib/ruby/gems/1.8/gems/rsolr-0.12.1/lib/rsolr/client.rb:109)
at rubyjit.adapt_response_F74415CC503639C7FC52653D7CBFF09DABF3EBD9._file_(/opt/prod3.6.23/my_prod/3.6.0/tools/jruby/lib/ruby/gems/1.8/gems/rsolr-0.12.1/lib/rsolr/client.rb)
at org.jruby.internal.runtime.methods.JittedMethod.call(JittedMethod.java:167)
at org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:167)
at rubyjit.request_1E5A19E2351C91975FDF3D07D7C107AA479CFBDD._file_(/opt/prod3.6.23/my_prod/3.6.0/tools/jruby/lib/ruby/gems/1.8/gems/rsolr-0.12.1/lib/rsolr/client.rb:35)
at rubyjit.request_1E5A19E2351C91975FDF3D07D7C107AA479CFBDD._file_(/opt/prod3.6.23/my_prod/3.6.0/tools/jruby/lib/ruby/gems/1.8/gems/rsolr-0.12.1/lib/rsolr/client.rb)
at org.jruby.ast.executable.AbstractScript._file_(AbstractScript.java:50)
at org.jruby.internal.runtime.methods.JittedMethod.call(JittedMethod.java:247)
at org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:235)
at rubyjit.update_49631488C89C161D2736DFDE1FE61EDA1FFF541B._file_(/opt/prod3.6.23/my_prod/3.6.0/tools/jruby/lib/ruby/gems/1.8/gems/rsolr-0.12.1/lib/rsolr/client.rb:22)
at rubyjit.update_49631488C89C161D2736DFDE1FE61EDA1FFF541B._file_(/opt/prod3.6.23/my_prod/3.6.0/tools/jruby/lib/ruby/gems/1.8/gems/rsolr-0.12.1/lib/rsolr/client.rb)
at org.jruby.ast.executable.AbstractScript._file_(AbstractScript.java:42)
at org.jruby.internal.runtime.methods.JittedMethod.call(JittedMethod.java:167)
at org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:167)
at rubyjit.add_DC0FF86FCF4B163E0AB7BC064665FD7CAF21BDDF._file_(/opt/prod3.6.23/my_prod/3.6.0/tools/jruby/lib/ruby/gems/1.8/gems/rsolr-0.12.1/lib/rsolr/client.rb:46)
at rubyjit.add_DC0FF86FCF4B163E0AB7BC064665FD7CAF21BDDF._file_(/opt/prod3.6.23/my_prod/3.6.0/tools/jruby/lib/ruby/gems/1.8/gems/rsolr-0.12.1/lib/rsolr/client.rb)
at org.jruby.internal.runtime.methods.JittedMethod.call(JittedMethod.java:167)
at org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:167)
at rubyjit.add_documents_4A13E586C0536A9EDAFC4958CBF4E1C41FEA8C6F._file_(/opt/prod3.6.23/my_prod/3.6.0/tools/jruby/lib/ruby/gems/1.8/gems/sunspot-1.2.1/lib/sunspot/indexer.rb:101)
at rubyjit.add_documents_4A13E586C0536A9EDAFC4958CBF4E1C41FEA8C6F._file_(/opt/prod3.6.23/my_prod/3.6.0/tools/jruby/lib/ruby/gems/1.8/gems/sunspot-1.2.1/lib/sunspot/indexer.rb)
at org.jruby.internal.runtime.methods.JittedMethod.call(JittedMethod.java:167)
at org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:167)
at rubyjit.add_836074011F8AD71CA3F752D55508807D54B3B99D._file_(/opt/prod3.6.23/my_prod/3.6.0/tools/jruby/lib/ruby/gems/1.8/gems/sunspot-1.2.1/lib/sunspot/indexer.rb:26)
at rubyjit.add_836074011F8AD71CA3F752D55508807D54B3B99D._file_(/opt/prod3.6.23/my_prod/3.6.0/tools/jruby/lib/ruby/gems/1.8/gems/sunspot-1.2.1/lib/sunspot/indexer.rb)
at org.jruby.internal.runtime.methods.JittedMethod.call(JittedMethod.java:167)
at org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:167)
at rubyjit.index_2758BE562EA19C95BEE781D5E8DDD83836027E1D._file_(/opt/prod3.6.23/my_prod/3.6.0/tools/jruby/lib/ruby/gems/1.8/gems/sunspot-1.2.1/lib/sunspot/session.rb:91)
at rubyjit.index_2758BE562EA19C95BEE781D5E8DDD83836027E1D._file_(/opt/prod3.6.23/my_prod/3.6.0/tools/jruby/lib/ruby/gems/1.8/gems/sunspot-1.2.1/lib/sunspot/session.rb)
at org.jruby.ast.executable.AbstractScript._file_(AbstractScript.java:42)
at org.jruby.internal.runtime.methods.JittedMethod.call(JittedMethod.java:187)
at org.jruby.runtime.callsite.CachingCallSite.callBlock(CachingCallSite.java:176)
at org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:182)
at org.jruby.runtime.callsite.CachingCallSite.callVarargs(CachingCallSite.java:112)
at rubyjit.index_A0DC255F75597C8B1B7C127E88E56820605233FE._file_(/opt/prod3.6.23/my_prod/3.6.0/tools/jruby/lib/ruby/gems/1.8/gems/sunspot-1.2.1/lib/sunspot/session_proxy/abstract_session_proxy.rb:15)
at rubyjit.index_A0DC255F75597C8B1B7C127E88E56820605233FE._file_(/opt/prod3.6.23/my_prod/3.6.0/tools/jruby/lib/ruby/gems/1.8/gems/sunspot-1.2.1/lib/sunspot/session_proxy/abstract_session_proxy.rb)
at org.jruby.ast.executable.AbstractScript._file_(AbstractScript.java:42)
at org.jruby.internal.runtime.methods.JittedMethod.call(JittedMethod.java:167)
at org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:167)
at org.jruby.runtime.callsite.CachingCallSite.callVarargs(CachingCallSite.java:102)
at rubyjit.index_29FE3C2DED1EB248BEA4475DD8DA1144D8CCA54B._file_(/opt/prod3.6.23/my_prod/3.6.0/tools/jruby/lib/ruby/gems/1.8/gems/sunspot-1.2.1/lib/sunspot.rb:175)
at rubyjit.index_29FE3C2DED1EB248BEA4475DD8DA1144D8CCA54B._file_(/opt/prod3.6.23/my_prod/3.6.0/tools/jruby/lib/ruby/gems/1.8/gems/sunspot-1.2.1/lib/sunspot.rb)
at org.jruby.ast.executable.AbstractScript._file_(AbstractScript.java:42)
at org.jruby.internal.runtime.methods.JittedMethod.call(JittedMethod.java:167)
at org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:167)
at rubyjit.solr_index_3AF6AE0A696EC8BCA5CD78D6E7AB6BFCB259638D._file_(/opt/prod3.6.23/my_prod/3.6.0/tools/jruby/lib/ruby/gems/1.8/gems/sunspot_rails-1.2.1/lib/sunspot/rails/searchable.rb:349)
at rubyjit.solr_index_3AF6AE0A696EC8BCA5CD78D6E7AB6BFCB259638D._file_(/opt/prod3.6.23/my_prod/3.6.0/tools/jruby/lib/ruby/gems/1.8/gems/sunspot_rails-1.2.1/lib/sunspot/rails/searchable.rb)
at org.jruby.internal.runtime.methods.JittedMethod.call(JittedMethod.java:127)
at org.jruby.internal.runtime.methods.DefaultMethod.call(DefaultMethod.java:166)
at org.jruby.internal.runtime.methods.AliasMethod.call(AliasMethod.java:56)
at org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:133)
at rubyjit.run_EA4C9BF8BC3C28226E7DF8508250102FBEC897B8._file_(/opt/prod3.6.23/my_prod/3.6.0/my_prod/lib/tasks/reindex.rake:44)
at rubyjit.run_EA4C9BF8BC3C28226E7DF8508250102FBEC897B8._file_(/opt/prod3.6.23/my_prod/3.6.0/my_prod/lib/tasks/reindex.rake)
at org.jruby.internal.runtime.methods.JittedMethod.call(JittedMethod.java:127)
at org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:133)
at rubyjit.run_9ADBCC0D0F6D8A699AB3D5069FD80A8953C8F966.chained_0_rescue_1$RUBY$SYNTHETIC_file_(/opt/prod3.6.23/my_prod/3.6.0/my_prod/lib/jm/job_manager.rb:41)
at rubyjit.run_9ADBCC0D0F6D8A699AB3D5069FD80A8953C8F966._file_(/opt/prod3.6.23/my_prod/3.6.0/my_prod/lib/jm/job_manager.rb:39)
at rubyjit.run_9ADBCC0D0F6D8A699AB3D5069FD80A8953C8F966._file_(/opt/prod3.6.23/my_prod/3.6.0/my_prod/lib/jm/job_manager.rb)
at rubyjit.run_9ADBCC0D0F6D8A699AB3D5069FD80A8953C8F966._file_(/opt/prod3.6.23/my_prod/3.6.0/my_prod/lib/jm/job_manager.rb)
at org.jruby.internal.runtime.methods.JittedMethod.call(JittedMethod.java:87)
at Jm$$JobManager$$JRubyRunnable_723747887.run(Jm$$JobManager$$JRubyRunnable_723747887.gen:13)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
at java.lang.Thread.run(Thread.java:662)

Activity

So this is a concurrency bottleneck you're seeing, yes? Or is it a deadlock?

The code in question appears to be defining a method on an object (i.e. a singleton). The code surrounding it has been JIT compiled, so the method body has also been compiled and needs to use our binding logic in InvocationMethodFactory. However, after the initial creation of that stub we should be able to load the same one again and not bottleneck like this. I'll look in the getCompiledMethod handle logic to see if we're unnecessarily synchronizing or otherwise improperly loading the class in question.

Charles Oliver Nutter
added a comment - 02/Jul/12 4:23 PM So this is a concurrency bottleneck you're seeing, yes? Or is it a deadlock?
The code in question appears to be defining a method on an object (i.e. a singleton). The code surrounding it has been JIT compiled, so the method body has also been compiled and needs to use our binding logic in InvocationMethodFactory. However, after the initial creation of that stub we should be able to load the same one again and not bottleneck like this. I'll look in the getCompiledMethod handle logic to see if we're unnecessarily synchronizing or otherwise improperly loading the class in question.

Charles Oliver Nutter
added a comment - 02/Jul/12 4:24 PM FWIW, the most recent rsolr gem (1.0.8) uses .extend to pull in the method in question from a module, and probably doesn't run into this issue.

So my hunch was right...even when the "compiled method handle" can be acquired from the classloader, we are synchronizing. That could easily produce a nasty bottleneck in any code that's defining methods at runtime (which is a bad idea, btw) in a body of code that has been jit compiled.

I've modified all such cases to do double-checked locking against the classloader, so if it succeeds trivially there will be no locking (of our own). Running tests now.

Charles Oliver Nutter
added a comment - 02/Jul/12 4:33 PM So my hunch was right...even when the "compiled method handle" can be acquired from the classloader, we are synchronizing. That could easily produce a nasty bottleneck in any code that's defining methods at runtime (which is a bad idea, btw) in a body of code that has been jit compiled.
I've modified all such cases to do double-checked locking against the classloader, so if it succeeds trivially there will be no locking (of our own). Running tests now.

commit a364a87fdd48c011627381badbbdd338142581d5
Author: Charles Oliver Nutter <headius@headius.com>
Date: Mon Jul 2 16:43:16 2012 -0500
Fix JRUBY-6686
JRuby/RSolr - BLOCKED on org.jruby.internal.runtime.methods.InvocationMethodFactory.getCompiledMethod
Several of the sync blocks were unnecessary, and others were too
coarse, causing locking to happen for classes that had already
been loaded. This should reduce locking when loading handles that
have already been generated, as is the case in the bug.
:100644 100644 0e508c2... e30f5b1... M src/org/jruby/internal/runtime/methods/InvocationMethodFactory.java