Fix wrong method lookup cache used when class is prepended#4581
Merged
headius merged 1 commit intojruby:masterfrom May 3, 2017
ivoanjo:fix-wrong-method-lookup-cache
Merged
Fix wrong method lookup cache used when class is prepended#4581headius merged 1 commit intojruby:masterfrom ivoanjo:fix-wrong-method-lookup-cache
headius merged 1 commit intojruby:masterfrom
ivoanjo:fix-wrong-method-lookup-cache
Conversation
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).
Member
|
Awesome! I'll review. Should be fine for 9.1.9.0. |
Member
|
Looks great, and thank you for such a detailed analysis and commit message! |
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
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:
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 iton the cache, and then not finding it the next time around?
Every instance of the
RubyModuleclass keeps a method lookup cache inthe
myCachedMethodsand normally reads and writes to it. Butadditionally, every
RubyModuleinstance keeps a reference calledmethodLocationto the object where it keeps its methods.Usually,
methodLocationis set tothis(e.g. theRubyModulestoresits own methods), but in some cases, e.g. when a class is prepended,
methodLocationchanges, and points elsewhere.The problem here is that when looking up on the
myCachedMethods, thecacheHitmethod always checks the localmyCachedMethodsreference,while the
addToCachewrites to the cache inside themethodLocationreference. This means that normally the method cache works fine as
this.myCachedMethodsandthis.methodLocation.myCachedMethodsare thesame, but when
methodLocationchanges, the cache reads will never findthe correct cached method.
As a fix, I updated the
cacheHitmethod to also read fromthis.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:
Before fix:
After fix:
Multi-threaded contention test case:
Thread state in VisualVM, without fix, without prepending
Array:(All ok)
Thread state in VisualVM, without fix, prepending
Array:(Heavy contention)
Thread state in VisualVM, with fix, prepending
Array:(Back to normal)