JRuby

org.jruby.util.Sprintf.rubySprintfToBuffer causing thread locks

Details

  • Number of attachments :
    0

Description

Why there is a lock here, got me...

java.lang.Thread.State: BLOCKED (on object monitor)
at java.util.Hashtable.get(Hashtable.java:333)

  • locked <0x00000005e0162170> (a java.util.Hashtable)
    at java.text.NumberFormat.getInstance(NumberFormat.java:742)
    at java.text.NumberFormat.getNumberInstance(NumberFormat.java:390)
    at org.jruby.util.Sprintf.rubySprintfToBuffer(Sprintf.java:815)
    at org.jruby.util.Sprintf.rubySprintfToBuffer(Sprintf.java:240)
    at org.jruby.util.Sprintf.sprintf(Sprintf.java:214)
    at org.jruby.RubyString.opFormatCommon(RubyString.java:1157)
    at org.jruby.RubyString.op_format(RubyString.java:1136)
    at org.jruby.RubyString$i$1$0$op_format.call(RubyString$i$1$0$op_format.gen:65535)
    at org.jruby.internal.runtime.methods.JavaMethod$JavaMethodOneOrN.call(JavaMethod.java:728)
    at org.jruby.internal.runtime.methods.AliasMethod.call(AliasMethod.java:86)
    at org.jruby.RubyClass.finvoke(RubyClass.java:576)
    at org.jruby.RubyBasicObject.send(RubyBasicObject.java:2778)
    at org.jruby.RubyKernel.send(RubyKernel.java:2084)
    at org.jruby.RubyKernel$s$send.call(RubyKernel$s$send.gen:65535)
    at org.jruby.internal.runtime.methods.JavaMethod$JavaMethodZeroOrOneOrTwoOrNBlock.call(JavaMethod.java:283)
    at org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:201)
    at rubyjit.String#%E980BE3DE7F9B6C8EEDF9D9120045507924ECC51.file_(/home/tomcat/tomcat10/webapps/ROOT/WEB-INF/gems/gems/i18n-0.5.0/lib/i18n/core_ext/string/interpolate.rb:101)

Activity

Ascending order - Click to sort in descending order
Hide
Permalink
Charles Oliver Nutter added a comment -

Yeah, pretty silly. The table it's synchronizing against basically just caches the format strings for a given locale. Because that cache might be used across threads, it's a Hashtable...which is unconditionally synchronized.

I'm sure there's a potential OpenJDK patch here, but for now I'm going to look into how we can just avoid calling the default methods.

Show
Charles Oliver Nutter added a comment - Yeah, pretty silly. The table it's synchronizing against basically just caches the format strings for a given locale. Because that cache might be used across threads, it's a Hashtable...which is unconditionally synchronized. I'm sure there's a potential OpenJDK patch here, but for now I'm going to look into how we can just avoid calling the default methods.
Hide
Permalink
Charles Oliver Nutter added a comment -

This one is pretty sickening. I added a thread-local map from Local to NumberFormat, since any given thread's only going to be using one at a time (unlike MessageDigest), and the improvement is pretty gross:

before:

system ~/projects/jruby $ jruby bench/bench_sprintf.rb 
          '%g' % 1.0   641602.5 (±7.2%) i/s -    3178900 in   4.987003s (cycle=9575)
4x contended '%g' % 1.0
                       144650.4 (±33.7%) i/s -     586908 in   4.908971s (cycle=137)

system ~/projects/jruby $ jruby bench/bench_sprintf.rb 
          '%g' % 1.0   641014.2 (±6.8%) i/s -    3183627 in   4.995059s (cycle=10303)
4x contended '%g' % 1.0
                       143091.6 (±33.9%) i/s -     581298 in   4.908607s (cycle=139)

after:

system ~/projects/jruby $ jruby bench/bench_sprintf.rb 
          '%g' % 1.0  1835549.1 (±9.1%) i/s -    9061846 in   4.985225s (cycle=8306)
4x contended '%g' % 1.0
                       248249.2 (±20.8%) i/s -    1086442 in   4.904267s (cycle=142)

system ~/projects/jruby $ jruby bench/bench_sprintf.rb 
          '%g' % 1.0  1628054.7 (±9.8%) i/s -    8017965 in   4.986371s (cycle=18955)
4x contended '%g' % 1.0
                       253320.0 (±29.5%) i/s -    1015344 in   4.892082s (cycle=144)

Will commit to master. Keep these coming, they're great!

Show
Charles Oliver Nutter added a comment - This one is pretty sickening. I added a thread-local map from Local to NumberFormat, since any given thread's only going to be using one at a time (unlike MessageDigest), and the improvement is pretty gross: before: system ~/projects/jruby $ jruby bench/bench_sprintf.rb '%g' % 1.0 641602.5 (±7.2%) i/s - 3178900 in 4.987003s (cycle=9575) 4x contended '%g' % 1.0 144650.4 (±33.7%) i/s - 586908 in 4.908971s (cycle=137) system ~/projects/jruby $ jruby bench/bench_sprintf.rb '%g' % 1.0 641014.2 (±6.8%) i/s - 3183627 in 4.995059s (cycle=10303) 4x contended '%g' % 1.0 143091.6 (±33.9%) i/s - 581298 in 4.908607s (cycle=139) after: system ~/projects/jruby $ jruby bench/bench_sprintf.rb '%g' % 1.0 1835549.1 (±9.1%) i/s - 9061846 in 4.985225s (cycle=8306) 4x contended '%g' % 1.0 248249.2 (±20.8%) i/s - 1086442 in 4.904267s (cycle=142) system ~/projects/jruby $ jruby bench/bench_sprintf.rb '%g' % 1.0 1628054.7 (±9.8%) i/s - 8017965 in 4.986371s (cycle=18955) 4x contended '%g' % 1.0 253320.0 (±29.5%) i/s - 1015344 in 4.892082s (cycle=144) Will commit to master. Keep these coming, they're great!
Hide
Permalink
Charles Oliver Nutter added a comment -

Committed to master...we're close to 1.6.7 so it won't go in that release, but feel free to lobby for it to go into 1.6.8. Otherwise, it will be in 1.7 soon.

commit 5ca2c954e0bedf1ae9b7a9fce7ed0389c2944039
Author: Charles Oliver Nutter <headius@headius.com>
Date:   Mon Feb 20 18:09:03 2012 -0600

    Fix JRUBY-6476: org.jruby.util.Sprintf.rubySprintfToBuffer causing thread locks
    
    The OpenJDK impl of NumberFormat has a Hashtable it uses to cache
    per-locale format strings. Unfortunately, this represents a
    bottleneck if you have many threads all hitting NumberFormat at
    once. My fix is to set up thread-local map from Locale to
    NumberFormat, saving an instance and avoiding the locks and lookup
    logic.
    
    The numbers say it all:
    
    before:
    
    system ~/projects/jruby $ jruby bench/bench_sprintf.rb
              '%g' % 1.0   641602.5 (±7.2%) i/s -    3178900 in   4.987003s (cycle=9575)
    4x contended '%g' % 1.0
                           144650.4 (±33.7%) i/s -     586908 in   4.908971s (cycle=137)
    
    system ~/projects/jruby $ jruby bench/bench_sprintf.rb
              '%g' % 1.0   641014.2 (±6.8%) i/s -    3183627 in   4.995059s (cycle=10303)
    4x contended '%g' % 1.0
                           143091.6 (±33.9%) i/s -     581298 in   4.908607s (cycle=139)
    after:
    
    system ~/projects/jruby $ jruby bench/bench_sprintf.rb
              '%g' % 1.0  1835549.1 (±9.1%) i/s -    9061846 in   4.985225s (cycle=8306)
    4x contended '%g' % 1.0
                           248249.2 (±20.8%) i/s -    1086442 in   4.904267s (cycle=142)
    
    system ~/projects/jruby $ jruby bench/bench_sprintf.rb
              '%g' % 1.0  1628054.7 (±9.8%) i/s -    8017965 in   4.986371s (cycle=18955)
    4x contended '%g' % 1.0
                           253320.0 (±29.5%) i/s -    1015344 in   4.892082s (cycle=144)
Show
Charles Oliver Nutter added a comment - Committed to master...we're close to 1.6.7 so it won't go in that release, but feel free to lobby for it to go into 1.6.8. Otherwise, it will be in 1.7 soon. commit 5ca2c954e0bedf1ae9b7a9fce7ed0389c2944039 Author: Charles Oliver Nutter <headius@headius.com> Date: Mon Feb 20 18:09:03 2012 -0600 Fix JRUBY-6476: org.jruby.util.Sprintf.rubySprintfToBuffer causing thread locks The OpenJDK impl of NumberFormat has a Hashtable it uses to cache per-locale format strings. Unfortunately, this represents a bottleneck if you have many threads all hitting NumberFormat at once. My fix is to set up thread-local map from Locale to NumberFormat, saving an instance and avoiding the locks and lookup logic. The numbers say it all: before: system ~/projects/jruby $ jruby bench/bench_sprintf.rb '%g' % 1.0 641602.5 (±7.2%) i/s - 3178900 in 4.987003s (cycle=9575) 4x contended '%g' % 1.0 144650.4 (±33.7%) i/s - 586908 in 4.908971s (cycle=137) system ~/projects/jruby $ jruby bench/bench_sprintf.rb '%g' % 1.0 641014.2 (±6.8%) i/s - 3183627 in 4.995059s (cycle=10303) 4x contended '%g' % 1.0 143091.6 (±33.9%) i/s - 581298 in 4.908607s (cycle=139) after: system ~/projects/jruby $ jruby bench/bench_sprintf.rb '%g' % 1.0 1835549.1 (±9.1%) i/s - 9061846 in 4.985225s (cycle=8306) 4x contended '%g' % 1.0 248249.2 (±20.8%) i/s - 1086442 in 4.904267s (cycle=142) system ~/projects/jruby $ jruby bench/bench_sprintf.rb '%g' % 1.0 1628054.7 (±9.8%) i/s - 8017965 in 4.986371s (cycle=18955) 4x contended '%g' % 1.0 253320.0 (±29.5%) i/s - 1015344 in 4.892082s (cycle=144)

People

  • Assignee:
    Charles Oliver Nutter
    Reporter:
    Chris Ochs
Vote (0)
Watch (0)

Dates

  • Created:
    Updated:
    Resolved: