Thread lock around org.jruby.MetaClass?

Ruby JRuby
1

Was curious why there is a lock here. This is from a visualvm thread
dump of tomcat running rails 3 under jruby 1.6.5.

Chris

java.lang.Thread.State: BLOCKED
at org.jruby.RubyModule.calculateName(RubyModule.java:393)

  • waiting to lock <58c3d9ac> (a org.jruby.MetaClass) owned by
    ““http-nio-8080”-exec-90” t@139
    at org.jruby.RubyModule.getName(RubyModule.java:383)
    at
    org.jruby.evaluator.ASTInterpreter.INTERPRET_BLOCK(ASTInterpreter.java:111)
    at
    org.jruby.runtime.InterpretedBlock.evalBlockBody(InterpretedBlock.java:374)
    at org.jruby.runtime.InterpretedBlock.yield(InterpretedBlock.java:328)
    at org.jruby.runtime.BlockBody.call(BlockBody.java:73)
    at org.jruby.runtime.Block.call(Block.java:89)
    at org.jruby.RubyProc.call(RubyProc.java:270)
    at org.jruby.RubyProc.call(RubyProc.java:220)
    at org.jruby.RubyProc$i$0$0$call.call(RubyProc$i$0$0$call.gen:65535)
    at
    org.jruby.internal.runtime.methods.DynamicMethod.call(DynamicMethod.java:181)
    at
    org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:69)
    at
    org.jruby.runtime.callsite.CachingCallSite.callVarargs(CachingCallSite.java:105)
    at
    rubyjit.publish_C42B827C11772BFA3316E5F1BEEF55966C62E0C8.file(/home/cochs/.rvm/gems/jruby-1.6.5/gems/activesupport-3.0.9/lib/active_support/notifications/fanout.rb:47)
    at
    rubyjit.publish_C42B827C11772BFA3316E5F1BEEF55966C62E0C8.file(/home/cochs/.rvm/gems/jruby-1.6.5/gems/activesupport-3.0.9/lib/active_support/notifications/fanout.rb)
    at
    org.jruby.internal.runtime.methods.JittedMethod.call(JittedMethod.java:107)
    at
    org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:69)
    at
    org.jruby.runtime.callsite.CachingCallSite.callVarargs(CachingCallSite.java:105)
    at
    rubyjit.publish_7BBAEF648A626BFED3BD34737C6C37A264430D18.block_0$RUBY$file(/home/cochs/.rvm/gems/jruby-1.6.5/gems/activesupport-3.0.9/lib/active_support/notifications/fanout.rb:25)
    at
    rubyjit$publish_7BBAEF648A626BFED3BD34737C6C37A264430D18$block_0$RUBY$file.call(rubyjit$publish_7BBAEF648A626BFED3BD34737C6C37A264430D18$block_0$RUBY$file:65535)
    at org.jruby.runtime.CompiledBlock.yield(CompiledBlock.java:112)
    at org.jruby.runtime.CompiledBlock.yield(CompiledBlock.java:95)
    at org.jruby.runtime.Block.yield(Block.java:130)
    at org.jruby.RubyArray.eachCommon(RubyArray.java:1605)
    at org.jruby.RubyArray.each(RubyArray.java:1612)
2

Is it deadlocking as a result? It should be a single lock used to
lazily calculate and cache a class’s name.

FWIW, JRuby master/1.7 removes the laziness, since it was a little
buggy and probably not really useful.

  • Charlie
3

On Mon, Nov 7, 2011 at 5:32 PM, Charles Oliver N.
[email protected] wrote:

Is it deadlocking as a result? It should be a single lock used to
lazily calculate and cache a class’s name.

It’s not deadlocking. Being somewhat new to java I’m not really sure
what’s normal and not normal when looking at thread dumps from
visualvm.

I’m seeing a lot of blocked threads. Looks like most of it has to do
with concurrent hashmaps/collections, and stuff like define_method.
At the same time the app is using all the cpu. I’m assuming that if
it’s using all the cpu then whatever blocking is going on is probably
somewhat normal. In this state the app seems to act normally.
Response times get longer as I push it hard, but there is very little
waiting going on.

Chris

4

On Tue, Nov 8, 2011 at 2:47 AM, snacktime [email protected] wrote:

waiting going on.
If you’re seeing a lot of thread dumps blocking at those particular
locks (related to classes that haven’t been named yet, new methods
being defined, etc) then there’s something peculiar going on like a
script that’s defining tons and tons of new classes and methods. Does
that sound likely?

  • Charlie
5

On Mon, Nov 7, 2011 at 7:18 PM, Charles Oliver N.
[email protected] wrote:

Response times get longer as I push it hard, but there is very little
waiting going on.

If you’re seeing a lot of thread dumps blocking at those particular
locks (related to classes that haven’t been named yet, new methods
being defined, etc) then there’s something peculiar going on like a
script that’s defining tons and tons of new classes and methods. Does
that sound likely?

  • Charlie

Ya all the dumps that have are blocking at those locks are defining
new modules/methods. Under moderate load it’s pretty minimal, it’s
only when I’m really pushing the cpu limits (load average around 50)
that stuff starts to block more.

Chris

6

What rails env is running? Is it dev?

7

On Tue, Nov 8, 2011 at 12:08 AM, James A. [email protected]
wrote:

What rails env is running? Is it dev?

Production.

Chris

8

Can you post a couple dumps? I’m curious now.

  • Charlie (mobile)
9

On Tue, Nov 8, 2011 at 1:11 PM, Charles Oliver N.
[email protected] wrote:

Can you post a couple dumps? I’m curious now.

  • Charlie (mobile)

Ya, I’m digging through them now to find the right one, visualvm takes
forever to load these things.

Chris

10

Here are dumps of two threads that represent the state of almost all
the blocking.

This is the code the first dump is hitting:

def self.method_missing(method, *args, &block)
config if @@config_obj.nil?
if @@config_obj.respond_to?(:method)
@@config_obj.send(method) # line 117
else
super
end
end

This is where @@config_obj is created. It’s created once at startup.
These methods are defined on Hash. So our global config hash can be
referenced using dot notation.

def to_mod
hash = self
Module.new do
hash.each_pair do |key, value|
define_method key do
value.to_obj
end
define_method(“#{key}=”) do |val|
hash[key] = val.to_obj
end
end
end
end

def to_obj
Object.new.extend self.to_mod
end