Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Fix wrong method lookup cache used when class is prepended #4581

Merged
merged 1 commit into from
May 3, 2017
Merged

Fix wrong method lookup cache used when class is prepended #4581

merged 1 commit into from
May 3, 2017

Conversation

ivoanjo
Copy link
Contributor

@ivoanjo ivoanjo commented Apr 30, 2017

While benchmarking a @Talkdesk JRuby application during our recent
hackaton, I noticed quite a lot of thread contention in a workload where
there should be no shared data.

Stack traces showed that there was contention while performing writes to
the method lookup cache:

java.lang.Thread.State: BLOCKED (on object monitor)
     at java.util.concurrent.ConcurrentHashMap.putVal(ConcurrentHashMap.java:1027)
     - waiting to lock <0x00000000e1565058> (a java.util.concurrent.ConcurrentHashMap$Node)
     at java.util.concurrent.ConcurrentHashMap.put(ConcurrentHashMap.java:1006)
     at org.jruby.RubyModule.addToCache(RubyModule.java:1467)
     at org.jruby.RubyModule.searchWithCache(RubyModule.java:1315)
     at org.jruby.RubyModule.searchWithCache(RubyModule.java:1269)
     at org.jruby.RubyModule.searchMethod(RubyModule.java:1258)
     at org.jruby.RubyModule.respondsToMethod(RubyModule.java:1829)

I ended up instrumenting the JRuby code and noticed that this kept
happening (on this workload) for calls to Array.respond_to?(:to_ary)
which happened quite often and never seemed to be cached.

But why were threads repeatedly failing to lookup #to_ary, saving it
on the cache, and then not finding it the next time around?

Every instance of the RubyModule class keeps a method lookup cache in
the myCachedMethods and normally reads and writes to it. But
additionally, every RubyModule instance keeps a reference called
methodLocation to the object where it keeps its methods.

Usually, methodLocation is set to this (e.g. the RubyModule stores
its own methods), but in some cases, e.g. when a class is prepended,
methodLocation changes, and points elsewhere.

The problem here is that when looking up on the myCachedMethods, the
cacheHit method always checks the local myCachedMethods reference,
while the addToCache writes to the cache inside the methodLocation
reference. This means that normally the method cache works fine as
this.myCachedMethods and this.methodLocation.myCachedMethods are the
same, but when methodLocation changes, the cache reads will never find
the correct cached method.

As a fix, I updated the cacheHit method to also read from
this.methodLocation.myCachedMethods.

I believe this is enough to fix the issue (and is a correct fix), but feedback is
very welcome as I'm still rather noob in the codebase.

Thanks go to @Talkdesk for letting me work on making JRuby kick even
more ass.

Included below are my test cases and results from executing them.

Single-threaded performance impact test-case:

require 'benchmark/ips'

module Foo; end

mode = ARGV.first

if mode == 'prepend'
  Array.prepend(Foo)
elsif mode == 'no-prepend'
  # do nothing
else
  fail 'no mode supplied'
end

Benchmark.ips do |benchmark|
  benchmark.time = 15
  benchmark.warmup = 15

  benchmark.report(mode) { [1, 2, 3].respond_to?(:to_ary) }

  benchmark.compare!
end

Before fix:

$ jruby singlethreaded-bug-bench.rb no-prepend
Warming up --------------------------------------
          no-prepend   265.802k i/100ms
Calculating -------------------------------------
          no-prepend     14.619M (± 5.1%) i/s -    218.489M in
14.993450s

$ jruby singlethreaded-bug-bench.rb prepend
Warming up --------------------------------------
             prepend   222.863k i/100ms
Calculating -------------------------------------
             prepend      6.879M (± 3.1%) i/s -    103.186M in
15.017267s

After fix:

$ jruby singlethreaded-bug-bench.rb no-prepend
Warming up --------------------------------------
          no-prepend   272.227k i/100ms
Calculating -------------------------------------
          no-prepend     14.229M (± 4.1%) i/s -    212.882M in
14.990837s

$ jruby singlethreaded-bug-bench.rb prepend
Warming up --------------------------------------
             prepend   271.436k i/100ms
Calculating -------------------------------------
             prepend     14.095M (± 4.2%) i/s -    210.906M in
14.996117s

Multi-threaded contention test case:

module Foo; end

mode = ARGV.first

if mode == 'prepend'
  Array.prepend(Foo)
elsif mode == 'no-prepend'
  # do nothing
else
  fail 'no mode supplied'
end

Integer(ENV['THREADS'] || 16).times do
  Thread.new { [1, 2, 3].respond_to?(:to_ary) while true }
end

sleep

Thread state in VisualVM, without fix, without prepending Array:

no-prepend
(All ok)

Thread state in VisualVM, without fix, prepending Array:

prepended-broken
(Heavy contention)

Thread state in VisualVM, with fix, prepending Array:

prepend-fixed
(Back to normal)

While benchmarking a @Talkdesk JRuby application during our recent
hackaton, I noticed quite a lot of thread contention in a workload where
there should be no shared data.

Stack traces showed that there was contention while performing writes to
the method lookup cache:

```
java.lang.Thread.State: BLOCKED (on object monitor)
     at java.util.concurrent.ConcurrentHashMap.putVal(ConcurrentHashMap.java:1027)
     - waiting to lock <0x00000000e1565058> (a java.util.concurrent.ConcurrentHashMap$Node)
     at java.util.concurrent.ConcurrentHashMap.put(ConcurrentHashMap.java:1006)
     at org.jruby.RubyModule.addToCache(RubyModule.java:1467)
     at org.jruby.RubyModule.searchWithCache(RubyModule.java:1315)
     at org.jruby.RubyModule.searchWithCache(RubyModule.java:1269)
     at org.jruby.RubyModule.searchMethod(RubyModule.java:1258)
     at org.jruby.RubyModule.respondsToMethod(RubyModule.java:1829)
```

I ended up instrumenting the JRuby code and noticed that this kept
happening (on this workload) for calls to `Array.respond_to?(:to_ary)`
which happened quite often and never seemed to be cached.

But why were threads repeatedly failing to lookup `#to_ary`, saving it
on the cache, and then not finding it the next time around?

Every instance of the `RubyModule` class keeps a method lookup cache in
the `myCachedMethods` and normally reads and writes to it. But
additionally, every `RubyModule` instance keeps a reference called
`methodLocation` to the object where it keeps its methods.

Usually, `methodLocation` is set to `this` (e.g. the `RubyModule` stores
its own methods), but in some cases, e.g. when a class is prepended,
`methodLocation` changes, and points elsewhere.

The problem here is that when looking up on the `myCachedMethods`, the
`cacheHit` method always checks the local `myCachedMethods` reference,
while the `addToCache` writes to the cache inside the `methodLocation`
reference. This means that normally the method cache works fine as
`this.myCachedMethods` and `this.methodLocation.myCachedMethods` are the
same, but when `methodLocation` changes, the cache reads will never find
the correct cached method.

As a fix, I updated the `cacheHit` method to also read from
`this.methodLocation.myCachedMethods`.

Included below are my test cases and results from executing them.

Thanks go to @Talkdesk for letting me work on making JRuby kick even
more ass.

Single-threaded performance impact test-case:

```ruby
require 'benchmark/ips'

module Foo; end

mode = ARGV.first

if mode == 'prepend'
  Array.prepend(Foo)
elsif mode == 'no-prepend'
  # do nothing
else
  fail 'no mode supplied'
end

Benchmark.ips do |benchmark|
  benchmark.time = 15
  benchmark.warmup = 15

  benchmark.report(mode) { [1, 2, 3].respond_to?(:to_ary) }

  benchmark.compare!
end
```

Before fix:

```
$ jruby singlethreaded-bug-bench.rb no-prepend
Warming up --------------------------------------
          no-prepend   265.802k i/100ms
Calculating -------------------------------------
          no-prepend     14.619M (± 5.1%) i/s -    218.489M in
14.993450s

$ jruby singlethreaded-bug-bench.rb prepend
Warming up --------------------------------------
             prepend   222.863k i/100ms
Calculating -------------------------------------
             prepend      6.879M (± 3.1%) i/s -    103.186M in
15.017267s
```

After fix:

```
$ jruby singlethreaded-bug-bench.rb no-prepend
Warming up --------------------------------------
          no-prepend   272.227k i/100ms
Calculating -------------------------------------
          no-prepend     14.229M (± 4.1%) i/s -    212.882M in
14.990837s

$ jruby singlethreaded-bug-bench.rb prepend
Warming up --------------------------------------
             prepend   271.436k i/100ms
Calculating -------------------------------------
             prepend     14.095M (± 4.2%) i/s -    210.906M in
14.996117s
```

Multi-threaded contention test case:

```ruby
module Foo; end

mode = ARGV.first

if mode == 'prepend'
  Array.prepend(Foo)
elsif mode == 'no-prepend'
  # do nothing
else
  fail 'no mode supplied'
end

Integer(ENV['THREADS'] || 16).times do
  Thread.new { [1, 2, 3].respond_to?(:to_ary) while true }
end

sleep
```

(See VisualVM screenshots attached to PR for results).
@headius
Copy link
Member

headius commented May 3, 2017

Awesome! I'll review. Should be fine for 9.1.9.0.

@headius headius merged commit 903728b into jruby:master May 3, 2017
@headius
Copy link
Member

headius commented May 3, 2017

Looks great, and thank you for such a detailed analysis and commit message!

@ivoanjo ivoanjo deleted the fix-wrong-method-lookup-cache branch May 3, 2017 21:23
@enebo enebo added this to the JRuby 9.1.9.0 milestone May 11, 2017
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

None yet

3 participants