JRuby/RSolr - BLOCKED on org.jruby.internal.runtime.methods.InvocationMethodFactory.getCompiledMethod

Details

Type: Bug
Status: Resolved
Priority: Major
Resolution: Fixed
Affects Version/s: JRuby 1.6.5
Fix Version/s: JRuby 1.7.0.pre2
Component/s: None
Labels:
None
Environment:
jruby 1.6.5 (ruby-1.8.7-p330) (2011-10-25 9dcd388) (Java HotSpot(TM) 64-Bit Server VM 1.6.0_26) [linux-amd64-java]

Number of attachments :
0

Description

We have 50 threads writing into Solr server, using sunspot/rsolr gem. At peak we see 10-15 threads BLOCKED with exactly the same thread dump.

"pool-1-thread-6" prio=10 tid=0x00002aaab48ab000 nid=0x5ad8 waiting for monitor entry [0x0000000042540000]
java.lang.Thread.State: BLOCKED (on object monitor)
at org.jruby.internal.runtime.methods.InvocationMethodFactory.getCompiledMethod(InvocationMethodFactory.java:245)

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

Ascending order - Click to sort in descending order

Hide

Permalink

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.

Show

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.

Hide

Permalink

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.

Show

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.

Hide

Permalink

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.

Show

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.

Hide

Permalink

Charles Oliver Nutter added a comment - 02/Jul/12 4:46 PM

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

Show

Charles Oliver Nutter added a comment - 02/Jul/12 4:46 PM 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

Hide

Permalink

mv added a comment - 02/Jul/12 11:51 PM

Good to know this is fixed. In our tested we did not see any deadlock. Tests completed eventually. Thanks for the tip of upgrading rsolr gem.

Show

mv added a comment - 02/Jul/12 11:51 PM Good to know this is fixed. In our tested we did not see any deadlock. Tests completed eventually. Thanks for the tip of upgrading rsolr gem.

People

Assignee:

Charles Oliver Nutter

Reporter:

mv

Vote (0)

Watch (3)

Dates

Created:

25/May/12 8:01 PM

Updated:

02/Jul/12 11:51 PM

Resolved:

02/Jul/12 4:46 PM