JRuby

jruby-1.7.0.preview2 much slower jruby-1.6.3 (192s vs.60s)

Details

  • Type: Test Test
  • Status: Open Open
  • Priority: Major Major
  • Resolution: Unresolved
  • Affects Version/s: JRuby 1.7.0.pre2
  • Fix Version/s: None
  • Component/s: Performance
  • Labels:
  • Environment:
    Windows 7 x64
    java.runtime.version=1.7.0_07-b10
  • Number of attachments :
    1

Description

Here is the durations of execution of CRC calculator test (attached) for different versions of RUBY/JRUBY.
Note that
1.7.0+1.9.3 gets 192.291 secs
1.6.3+1.8.7 gets 56.72 secs

java.runtime.version=1.7.0_07-b10
RUBY_VERSION=1.8.7
JRUBY_VERSION=1.6.3
..........Duration 56.72 secs

java.runtime.version=1.7.0_07-b10
RUBY_VERSION=1.9.2
JRUBY_VERSION=1.6.3
..........Duration 60.21 secs

java.runtime.version=1.7.0_07-b10
RUBY_VERSION=1.8.7
JRUBY_VERSION=1.7.0.preview2
..........Duration 75.19 secs

java.runtime.version=1.7.0_07-b10
RUBY_VERSION=1.9.3
JRUBY_VERSION=1.7.0.preview2
..........Duration 192.291 secs

Activity

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

Confirmed! At least some of this seems to be specific to 1.9 mode, but even in 1.8 mode we're still slower than 1.6.7. Will investigate.

system ~/projects/jruby/tmp $ rvm jruby-1.6.7.2 do ruby -v crctest.rb 
jruby 1.6.7.2 (ruby-1.8.7-p357) (2012-05-01 26e08ba) (Java HotSpot(TM) 64-Bit Server VM 1.7.0_06) [darwin-x86_64-java]
java.runtime.version=1.7.0_06-b24
RUBY_VERSION=1.8.7
JRUBY_VERSION=1.6.7.2
..........Duration 7.851 secs
..........Duration 7.245 secs
..........Duration 7.233 secs
..........Duration 7.296 secs
..........Duration 7.25 secs

system ~/projects/jruby/tmp $ jruby -v crctest.rb 
jruby 1.7.0.preview2 (1.9.3p203) 2012-08-29 017d9b4 on Java HotSpot(TM) 64-Bit Server VM 1.7.0_06-b24 [darwin-x86_64]
java.runtime.version=1.7.0_06-b24
RUBY_VERSION=1.9.3
JRUBY_VERSION=1.7.0.preview2
.......Now using system ruby.
...Duration 27.042 secs
..........Duration 26.901 secs
..........Duration 26.897 secs
..........Duration 26.854 secs
..........Duration 26.909 secs

system ~/projects/jruby/tmp $ jruby --1.8 -v crctest.rb 
jruby 1.7.0.preview2 (ruby-1.8.7p370) 2012-08-29 017d9b4 on Java HotSpot(TM) 64-Bit Server VM 1.7.0_06-b24 [darwin-x86_64]
java.runtime.version=1.7.0_06-b24
RUBY_VERSION=1.8.7
JRUBY_VERSION=1.7.0.preview2
..........Duration 10.7 secs
..........Duration 10.247 secs
..........Duration 10.288 secs
..........Duration 10.23 secs
..........Duration 10.266 secs

system ~/projects/jruby/tmp $ jruby --1.8 -Xcompile.invokedynamic=true -v crctest.rb 
jruby 1.7.0.preview2 (ruby-1.8.7p370) 2012-08-29 017d9b4 on Java HotSpot(TM) 64-Bit Server VM 1.7.0_06-b24 +indy [darwin-x86_64]
java.runtime.version=1.7.0_06-b24
RUBY_VERSION=1.8.7
JRUBY_VERSION=1.7.0.preview2
..........Duration 7.707 secs
..........Duration 7.804 secs
..........Duration 7.724 secs
..........Duration 7.71 secs
..........Duration 7.843 secs
Show
Charles Oliver Nutter added a comment - Confirmed! At least some of this seems to be specific to 1.9 mode, but even in 1.8 mode we're still slower than 1.6.7. Will investigate. system ~/projects/jruby/tmp $ rvm jruby-1.6.7.2 do ruby -v crctest.rb jruby 1.6.7.2 (ruby-1.8.7-p357) (2012-05-01 26e08ba) (Java HotSpot(TM) 64-Bit Server VM 1.7.0_06) [darwin-x86_64-java] java.runtime.version=1.7.0_06-b24 RUBY_VERSION=1.8.7 JRUBY_VERSION=1.6.7.2 ..........Duration 7.851 secs ..........Duration 7.245 secs ..........Duration 7.233 secs ..........Duration 7.296 secs ..........Duration 7.25 secs system ~/projects/jruby/tmp $ jruby -v crctest.rb jruby 1.7.0.preview2 (1.9.3p203) 2012-08-29 017d9b4 on Java HotSpot(TM) 64-Bit Server VM 1.7.0_06-b24 [darwin-x86_64] java.runtime.version=1.7.0_06-b24 RUBY_VERSION=1.9.3 JRUBY_VERSION=1.7.0.preview2 .......Now using system ruby. ...Duration 27.042 secs ..........Duration 26.901 secs ..........Duration 26.897 secs ..........Duration 26.854 secs ..........Duration 26.909 secs system ~/projects/jruby/tmp $ jruby --1.8 -v crctest.rb jruby 1.7.0.preview2 (ruby-1.8.7p370) 2012-08-29 017d9b4 on Java HotSpot(TM) 64-Bit Server VM 1.7.0_06-b24 [darwin-x86_64] java.runtime.version=1.7.0_06-b24 RUBY_VERSION=1.8.7 JRUBY_VERSION=1.7.0.preview2 ..........Duration 10.7 secs ..........Duration 10.247 secs ..........Duration 10.288 secs ..........Duration 10.23 secs ..........Duration 10.266 secs system ~/projects/jruby/tmp $ jruby --1.8 -Xcompile.invokedynamic=true -v crctest.rb jruby 1.7.0.preview2 (ruby-1.8.7p370) 2012-08-29 017d9b4 on Java HotSpot(TM) 64-Bit Server VM 1.7.0_06-b24 +indy [darwin-x86_64] java.runtime.version=1.7.0_06-b24 RUBY_VERSION=1.8.7 JRUBY_VERSION=1.7.0.preview2 ..........Duration 7.707 secs ..........Duration 7.804 secs ..........Duration 7.724 secs ..........Duration 7.71 secs ..........Duration 7.843 secs
Hide
Permalink
Charles Oliver Nutter added a comment -

A quick sampling profile shows these as the top offenders. The conversion logic is most suspect; probably doing some conversions we don't need to in 1.9 mode:

     Compiled + native   Method                        
 67.5%  3547  +     0    org.jruby.util.TypeConverter.convertToType
 17.1%   899  +     0    crctest$block_2$RUBY$calc.call
Show
Charles Oliver Nutter added a comment - A quick sampling profile shows these as the top offenders. The conversion logic is most suspect; probably doing some conversions we don't need to in 1.9 mode: Compiled + native Method 67.5% 3547 + 0 org.jruby.util.TypeConverter.convertToType 17.1% 899 + 0 crctest$block_2$RUBY$calc.call
Hide
Permalink
Charles Oliver Nutter added a comment -

Ok, this was actually a great find.

The problem is that some time last summer, in furtherance of 1.9 compatibility, I disabled "fast ops" for math functions. The problem was that fast math operators were only wired up properly for Ruby 1.8, and Ruby 1.9 differed behaviorally in a number of cases. Because of the complexity of bifurcating the compiler and optimization logic for 1.9 mode, I opted to just turn fast ops off temporarily.

And then I forgot about it.

Turning fast ops back on brings performance well ahead of JRuby 1.6, but required me to finally address the bifurcation of Fixnum logic between 1.8 and 1.9 mode. I'm doing that now, and things are looking much better.

I also made a few modifications to your script that speed things up substantially. Some are due to avoiding areas that JRuby doesn't optimize well (and might some day) and others are just better practices in general.

Almost there.

Show
Charles Oliver Nutter added a comment - Ok, this was actually a great find. The problem is that some time last summer, in furtherance of 1.9 compatibility, I disabled "fast ops" for math functions. The problem was that fast math operators were only wired up properly for Ruby 1.8, and Ruby 1.9 differed behaviorally in a number of cases. Because of the complexity of bifurcating the compiler and optimization logic for 1.9 mode, I opted to just turn fast ops off temporarily. And then I forgot about it. Turning fast ops back on brings performance well ahead of JRuby 1.6, but required me to finally address the bifurcation of Fixnum logic between 1.8 and 1.9 mode. I'm doing that now, and things are looking much better. I also made a few modifications to your script that speed things up substantially. Some are due to avoiding areas that JRuby doesn't optimize well (and might some day) and others are just better practices in general. Almost there.
Hide
Permalink
Charles Oliver Nutter added a comment -

I have pushed changes to master that bring performance much closer to matching 1.6 in both language modes, and beating it handily with invokedynamic enabled.

First, numbers with your original script. Note that because this script uses a block and some methods that trigger deoptimization in JRuby, there's overhead unrelated to the algorithm bogging this down. I still want master to beat 1.6, but getting this close means most of the broken performance has been repaired:

system ~/projects/jruby $ rvm jruby-1.6.7.2 do ruby --1.8 tmp/crctest.rb 
java.runtime.version=1.7.0_06-b24
RUBY_VERSION=1.8.7
JRUBY_VERSION=1.6.7.2
..........Duration 7.691 secs
..........Duration 7.359 secs
..........Duration 7.414 secs
..........Duration 7.378 secs
..........Duration 7.34 secs

system ~/projects/jruby $ jruby --1.8 tmp/crctest.rb 
java.runtime.version=1.7.0_06-b24
RUBY_VERSION=1.8.7
JRUBY_VERSION=1.7.0.preview2
..........Duration 8.768 secs
..........Duration 8.343 secs
..........Duration 8.292 secs
..........Duration 8.305 secs
..........Duration 8.336 secs

system ~/projects/jruby $ jruby -Xcompile.invokedynamic=true --1.8 tmp/crctest.rb 
java.runtime.version=1.7.0_06-b24
RUBY_VERSION=1.8.7
JRUBY_VERSION=1.7.0.preview2
..........Duration 7.696 secs
..........Duration 7.486 secs
..........Duration 7.457 secs
..........Duration 7.467 secs
..........Duration 7.54 secs

My modified version of your script removes some of the overhead by avoiding the block iteration, avoiding the [] method (which triggers deoptimization for JRuby) and using a constant instead of a class variable (constants optimize much better in JRuby). Here's numbers for that (only works in 1.9 mode):

system ~/projects/jruby $ rvm jruby-1.6.7.2 do ruby --1.9 tmp/crctest.rb 
java.runtime.version=1.7.0_06-b24
RUBY_VERSION=1.9.2
JRUBY_VERSION=1.6.7.2
..........Duration 6.42 secs
..........Duration 6.313 secs
..........Duration 6.403 secs
..........Duration 6.421 secs
..........Duration 6.513 secs

system ~/projects/jruby $ jruby tmp/crctest.rb 
java.runtime.version=1.7.0_06-b24
RUBY_VERSION=1.9.3
JRUBY_VERSION=1.7.0.preview2
..........Duration 7.374 secs
..........Duration 7.382 secs
..........Duration 7.326 secs
..........Duration 7.462 secs
..........Duration 7.387 secs

system ~/projects/jruby $ jruby -Xcompile.invokedynamic=true tmp/crctest.rb 
java.runtime.version=1.7.0_06-b24
RUBY_VERSION=1.9.3
JRUBY_VERSION=1.7.0.preview2
..........Duration 4.381 secs
..........Duration 4.051 secs
..........Duration 4.071 secs
..........Duration 4.081 secs
..........Duration 4.074 secs

The modified version of the script is here: https://gist.github.com/1cd95cb6e0ab20535ac4

The commit is here:

commit 13057bcd31e3b843cc0e00c87dd3ceceed85b919
Author: Charles Oliver Nutter <headius@headius.com>
Date:   Fri Aug 31 15:23:21 2012 -0500

    Reenable fast math operations.
    
    Fast math ops had been disabled some time last year to further 1.9
    compatibility, since several Fixnum operators had differing
    behavior in 1.9 mode. The compiler complexities of making both the
    1.8 and 1.9 paths optimizable were too great at the time, and also
    introduce complexity that will eventually just go away once 1.9
    logic is the only logic.
    
    In order to reenable fast operators without breaking 1.9 mode, I
    opted to remove the bifurcated "19" versions of those Fixnum
    methods that have differing logic in favor of a boolean check to
    do the same. This adds a bit of overhead to all of the operators
    in question, but allows safely enabling fast operators, greatly
    improving the performance of math (as it did before).
    
    This commit also includes a small override for RubyFixnum's
    convertToInteger(String) method, since there's no good reason
    we should have have to do a hard redispatch back to Fixnum when
    all we need is an Integer, regardless of what method is specified.

:100644 100644 b7a1836... 3af9d35... M	src/org/jruby/RubyFixnum.java
:100644 100644 f9e842e... f9d0259... M	src/org/jruby/runtime/ThreadContext.java
:100644 100644 4564c61... 6caddfe... M	src/org/jruby/runtime/callsite/EqCallSite.java
:100644 100644 f5afe1f... e051afb... M	src/org/jruby/util/cli/Options.java

I'm going to do a bit more exploration as to why we're still not faster than JRuby 1.6, but the bulk of the issue is solved.

Show
Charles Oliver Nutter added a comment - I have pushed changes to master that bring performance much closer to matching 1.6 in both language modes, and beating it handily with invokedynamic enabled. First, numbers with your original script. Note that because this script uses a block and some methods that trigger deoptimization in JRuby, there's overhead unrelated to the algorithm bogging this down. I still want master to beat 1.6, but getting this close means most of the broken performance has been repaired: system ~/projects/jruby $ rvm jruby-1.6.7.2 do ruby --1.8 tmp/crctest.rb java.runtime.version=1.7.0_06-b24 RUBY_VERSION=1.8.7 JRUBY_VERSION=1.6.7.2 ..........Duration 7.691 secs ..........Duration 7.359 secs ..........Duration 7.414 secs ..........Duration 7.378 secs ..........Duration 7.34 secs system ~/projects/jruby $ jruby --1.8 tmp/crctest.rb java.runtime.version=1.7.0_06-b24 RUBY_VERSION=1.8.7 JRUBY_VERSION=1.7.0.preview2 ..........Duration 8.768 secs ..........Duration 8.343 secs ..........Duration 8.292 secs ..........Duration 8.305 secs ..........Duration 8.336 secs system ~/projects/jruby $ jruby -Xcompile.invokedynamic=true --1.8 tmp/crctest.rb java.runtime.version=1.7.0_06-b24 RUBY_VERSION=1.8.7 JRUBY_VERSION=1.7.0.preview2 ..........Duration 7.696 secs ..........Duration 7.486 secs ..........Duration 7.457 secs ..........Duration 7.467 secs ..........Duration 7.54 secs My modified version of your script removes some of the overhead by avoiding the block iteration, avoiding the [] method (which triggers deoptimization for JRuby) and using a constant instead of a class variable (constants optimize much better in JRuby). Here's numbers for that (only works in 1.9 mode): system ~/projects/jruby $ rvm jruby-1.6.7.2 do ruby --1.9 tmp/crctest.rb java.runtime.version=1.7.0_06-b24 RUBY_VERSION=1.9.2 JRUBY_VERSION=1.6.7.2 ..........Duration 6.42 secs ..........Duration 6.313 secs ..........Duration 6.403 secs ..........Duration 6.421 secs ..........Duration 6.513 secs system ~/projects/jruby $ jruby tmp/crctest.rb java.runtime.version=1.7.0_06-b24 RUBY_VERSION=1.9.3 JRUBY_VERSION=1.7.0.preview2 ..........Duration 7.374 secs ..........Duration 7.382 secs ..........Duration 7.326 secs ..........Duration 7.462 secs ..........Duration 7.387 secs system ~/projects/jruby $ jruby -Xcompile.invokedynamic=true tmp/crctest.rb java.runtime.version=1.7.0_06-b24 RUBY_VERSION=1.9.3 JRUBY_VERSION=1.7.0.preview2 ..........Duration 4.381 secs ..........Duration 4.051 secs ..........Duration 4.071 secs ..........Duration 4.081 secs ..........Duration 4.074 secs The modified version of the script is here: https://gist.github.com/1cd95cb6e0ab20535ac4 The commit is here: commit 13057bcd31e3b843cc0e00c87dd3ceceed85b919 Author: Charles Oliver Nutter <headius@headius.com> Date: Fri Aug 31 15:23:21 2012 -0500 Reenable fast math operations. Fast math ops had been disabled some time last year to further 1.9 compatibility, since several Fixnum operators had differing behavior in 1.9 mode. The compiler complexities of making both the 1.8 and 1.9 paths optimizable were too great at the time, and also introduce complexity that will eventually just go away once 1.9 logic is the only logic. In order to reenable fast operators without breaking 1.9 mode, I opted to remove the bifurcated "19" versions of those Fixnum methods that have differing logic in favor of a boolean check to do the same. This adds a bit of overhead to all of the operators in question, but allows safely enabling fast operators, greatly improving the performance of math (as it did before). This commit also includes a small override for RubyFixnum's convertToInteger(String) method, since there's no good reason we should have have to do a hard redispatch back to Fixnum when all we need is an Integer, regardless of what method is specified. :100644 100644 b7a1836... 3af9d35... M src/org/jruby/RubyFixnum.java :100644 100644 f9e842e... f9d0259... M src/org/jruby/runtime/ThreadContext.java :100644 100644 4564c61... 6caddfe... M src/org/jruby/runtime/callsite/EqCallSite.java :100644 100644 f5afe1f... e051afb... M src/org/jruby/util/cli/Options.java I'm going to do a bit more exploration as to why we're still not faster than JRuby 1.6, but the bulk of the issue is solved.

People

  • Assignee:
    Unassigned
    Reporter:
    Vyacheslav Frolov
Vote (0)
Watch (3)

Dates

  • Created:
    Updated: