Calling object_id on thread causes lock

dubstep · February 18, 2012, 3:41am

I’m running the latest from jruby-1_6, and rails 3.0.9 under tomcat 7.

I’m seeing the following lock, which a bunch of other threads are
waiting on.

“http-nio-8080-exec-130” daemon prio=10 tid=0x00007ff7894a0000
nid=0x4798 waiting for monitor entry [0x00007ff772ee7000]
java.lang.Thread.State: BLOCKED (on object monitor)
at
org.jruby.RubyBasicObject.getObjectId(RubyBasicObject.java:1005)
- locked <0x00000005e32121d0> (a org.jruby.RubyObject)
at org.jruby.RubyBasicObject.id(RubyBasicObject.java:993)
at org.jruby.RubyKernel.id(RubyKernel.java:1885)
at
org.jruby.RubyKernel$s$0$0$id.call(RubyKernel$s$0$0$id.gen:65535)
at
org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:133)
at
rubyjit.Module#instrumenter_BC6D93C9B6178F7575A4F7A8E8E9CAA45CB2250E.file(/home/tomcat/tomcat10/webapps/ROOT/WEB-INF/gems/gems/activesupport-3.0.9/lib/active_support/notifications.rb:74)
at
rubyjit.Module#instrumenter_BC6D93C9B6178F7575A4F7A8E8E9CAA45CB2250E.file(/home/tomcat/tomcat10/webapps/ROOT/WEB-INF/gems/gems/activesupport-3.0.9/lib/active_support/notifications.rb)

This code creates a global notifier, and calls object_id on it in all
the other threads, which appears to cause a lock when looking up the
object id. I imagine this is the right thing to do. Should I file a
bug against rails on this?

module Notifications
autoload :Instrumenter, ‘active_support/notifications/instrumenter’
autoload :Event, ‘active_support/notifications/instrumenter’
autoload :Fanout, ‘active_support/notifications/fanout’

@instrumenters = Hash.new { |h,k| h[k] = notifier.listening?(k) }

class << self
  attr_writer :notifier
  delegate :publish, :to => :notifier

  def instrument(name, payload = {})
    if @instrumenters[name]
      #instrumenter.instrument(name, payload) { yield payload if

block_given? }
yield payload if block_given?
else
yield payload if block_given?
end
end

  def subscribe(*args, &block)
    notifier.subscribe(*args, &block).tap do
      @instrumenters.clear
    end
  end

  def unsubscribe(*args)
    notifier.unsubscribe(*args)
    @instrumenters.clear
  end

  def notifier
    @notifier ||= Fanout.new
  end

  def instrumenter
    Thread.current[:"instrumentation_#{notifier.object_id}"] ||=

Instrumenter.new(notifier)
end
end
end

Chris

snacktime · February 18, 2012, 3:48am

Just found another gem that calls object_id on another thread, same
result it ends up in blocked threads. (net-http-persistent)

Chris

snacktime · February 19, 2012, 7:01am

So here’s the basic deal…

object_id in MRI is mostly free, because they basically just return
the object’s pointer address in memory. That means they’re not
really guaranteeing it’s unique…it’s only unique among live
objects.

In JRuby, we have to at least attempt to make it unique, but we don’t
have any unique identifier per-object provided by the JVM…so we use
a monotonically-increasing long to represent object_id. It’s not
guaranteed to be unique, but you’ll need to ask for something like
2^62 object_id’s for it to roll over (signed long / 2 for the
even-number Fixnum id’s). So that’s one lock to guarantee it’s
monotonically increasing, but I can (and will) replace that with an
AtomicLong.

Because object_id is rarely requested, we also lazily allocate space
for it on the object, stuffing it into the same table where we keep
instance variable values. That’s the second lock involved,
guaranteeing that we’re allocating one and only one slot for object_id
on this class of objects. That I think I can improve via some
double-checking trickery.

However, the bottom line is that in any modern VM, there is no unique
ID attached to every object unless we actively attach it, and so
object_id and its ilk are certainly not free and generally a lot
slower than MRI. So it’s not a great idea for them to be used heavily
on hot code paths.

If it’s possible to patch these uses of object_id to something else
without negatively impacting them, I’d say to go for it. I will also
try to reduce the cost of querying and allocating an object_id for an
object. But we’re never going to be able to make it as fast as MRI’s
ultra cheat of using a pointer, so a combination of fixes will be
necessary.

Open a bug, please.

Charlie

snacktime · February 19, 2012, 7:33am

Ok, no bug necessary anymore.

I’ve pushed to master@2c88a5b and jruby-1_6@a9e0ec1 fixes that defer
synchronization until it’s absolutely necessary. The performance
results are pretty impressive, especially in the contended case:

BEFORE:

                                           user     system

total real
1M calls to obj.object_id 0.131000 0.000000
0.131000 ( 0.131000)
1M calls to Object.new.object_id 0.232000 0.000000
0.232000 ( 0.232000)
1M * 8 threaded calls to obj.object_id 3.896000 0.000000
3.896000 ( 3.896000)

AFTER:

                                           user     system

total real
1M calls to obj.object_id 0.080000 0.000000
0.080000 ( 0.080000)
1M calls to Object.new.object_id 0.178000 0.000000
0.178000 ( 0.178000)
1M * 8 threaded calls to obj.object_id 0.465000 0.000000
0.465000 ( 0.465000)

It’s obvious the unconditional thread acquisition was causing a problem.

Charlie

On Sun, Feb 19, 2012 at 12:14 AM, Charles Oliver N.

snacktime · February 19, 2012, 9:55am

There was another unconditional synchronization in
RubyClass.getObjectIdAccessorForWrite(). It only really needed to
synchronize when the accessor had not been allocated for that ruby
class.

BEFORE:
1M calls to Object.new.object_id 0.307000 0.000000
0.307000 ( 0.307000)
1M * 8 threaded calls to Object.new.object_id 1.784000 0.000000
1.784000 ( 1.784000)

AFTER:
1M calls to Object.new.object_id 0.262000 0.000000
0.262000 ( 0.262000)
1M * 8 threaded calls to Object.new.object_id 1.277000 0.000000
1.277000 ( 1.277000)

snacktime · February 19, 2012, 7:15am

Ok, so I’m happily wrong about the ID allocation…it’s already an
AtomicLong. I’ve got some promising tweaks in progress for the space
allocation now.

Charlie

On Sat, Feb 18, 2012 at 11:59 PM, Charles Oliver N.

snacktime · February 19, 2012, 4:18pm

Nice, thanks Wayne!

snacktime · February 22, 2012, 5:57pm

Below…

On Sun, Feb 19, 2012 at 5:43 PM, snacktime [email protected] wrote:

You guys are great!

I’m running some load tests this weekend against jruby-1_6. Turns out
that quite a few little changes since 1.6.5 (what we were using) had a
major impact. Particularly in the socket/select code. In 1.6.5 I had
a lot of thread blocking there that’s now gone.

That’s excellent. Please keep tossing us any lock contention issues you
see!

Being that the jruby team is really responsive on things, I think we
are just going to cautiously track jruby-1_6 for our production code.
I’ve forked the repo so we can tag 1_6 whenever there is something we
need, or if we find and fix some things ourselves we already have
things setup to do a pull request.

That’s probably safe. jruby-1_6 branch is intended to be really
stable. That’s not to say we don’t occasionally break things, but we
have a lot of safeguards to keep it from staying that way for long.

Charlie

snacktime · February 20, 2012, 12:44am

You guys are great!

I’m running some load tests this weekend against jruby-1_6. Turns out
that quite a few little changes since 1.6.5 (what we were using) had a
major impact. Particularly in the socket/select code. In 1.6.5 I had
a lot of thread blocking there that’s now gone.

Being that the jruby team is really responsive on things, I think we
are just going to cautiously track jruby-1_6 for our production code.
I’ve forked the repo so we can tag 1_6 whenever there is something we
need, or if we find and fix some things ourselves we already have
things setup to do a pull request.

Chris

On Sun, Feb 19, 2012 at 7:16 AM, Charles Oliver N.