JRuby (please use github issues at http://bugs.jruby.org)
  1. JRuby (please use github issues at http://bugs.jruby.org)
  2. JRUBY-6686

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

    Details

    • Type: Bug Bug
    • Status: Resolved Resolved
    • Priority: Major 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

        Hide
        Charles Oliver Nutter added a comment -

        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 - 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
        Charles Oliver Nutter added a comment -

        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 - 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
        Charles Oliver Nutter added a comment -

        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 - 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
        Charles Oliver Nutter added a comment -
        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 - 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
        mv added a comment -

        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 - 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
          • Votes:
            0 Vote for this issue
            Watchers:
            3 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved: