JRuby master (1.7) is LOT slower than jRuby 1.6.7 & MRI in generating tictactoe game tree

Details

Type: Bug
Status: Resolved
Priority: Major
Resolution: Won't Fix
Affects Version/s: JRuby 1.7.0.pre1
Fix Version/s: JRuby 1.7.0.pre2
Component/s: Performance
Labels:
None
Environment:

Hide
jRuby Master: Build directly from github, last commit #09e1090
java version "1.7.0_03"
OpenJDK Runtime Environment (IcedTea7 2.1.1pre) (7~u3-2.1.1~pre1-1ubuntu3)
OpenJDK Server VM (build 22.0-b10, mixed mode)
OS: Ubuntu 12.04 LTS

Show
jRuby Master: Build directly from github, last commit #09e1090 java version "1.7.0_03" OpenJDK Runtime Environment (IcedTea7 2.1.1pre) (7~u3-2.1.1~pre1-1ubuntu3) OpenJDK Server VM (build 22.0-b10, mixed mode) OS: Ubuntu 12.04 LTS

Number of attachments :
1

Description

Noticed that MRI & jRuby 1.6.7 are fast compared to jRuby master(1.7) while generating tictactoe game tree.

MRI: 18.83
1.6.7: 9.25
master: 23.65

#Ruby MRI

$ ruby --version
ruby 1.9.3p194 (2012-04-20 revision 35410) [i686-linux]
$ ruby tictactoe.rb 
18.830000   0.020000  18.850000 ( 18.910411)

#jRuby 1.6.7

$ ruby --version
jruby 1.6.7 (ruby-1.8.7-p357) (2012-02-22 3e82bc8) (OpenJDK Server VM 1.7.0_03) [linux-i386-java]
$ ruby tictactoe.rb 
  9.258000   0.000000   9.258000 (  9.171000)

#jRuby master(1.7.0)

$ ruby --version
jruby 1.7.0.preview1 (ruby-1.9.3-p203) (2012-06-06 09e1090) (OpenJDK Server VM 1.7.0_03) [linux-i386-java]
$ruby tictactoe.rb 
 23.650000   0.210000  23.860000 ( 21.600000)

Maybe its not a issue with jruby & the code is written wrong but still submitting as blog post here asked to submit reports in case we notice MRI or prior version of jruby are faster than jruby 1.7

Options
- Sort By Name
- Sort By Date
- Ascending
- Descending
- Download All

Attachments

tictactoe.rb

06/Jun/12 4:12 AM

4 kB

Gaurish Sharma

Activity

Ascending order - Click to sort in descending order

Hide

Permalink

Gaurish Sharma added a comment - 06/Jun/12 4:16 AM

The attached code is taken from here:
https://github.com/flyingmachine/minimax-tictactoe/blob/master/phase2/tictactoe.rb

Show

Gaurish Sharma added a comment - 06/Jun/12 4:16 AM The attached code is taken from here: https://github.com/flyingmachine/minimax-tictactoe/blob/master/phase2/tictactoe.rb

Hide

Permalink

Hiro Asari added a comment - 10/Jun/12 10:14 PM

Performance regression seems to exist from 1.6.7 to 1.7.0, but the performance difference between MRI and JRuby 1.7.0 is not that great.

If you run a rehearsal--that is, Benchmark.bmbm, rather than a simple Benchmark.measure, I get 7.7 seconds for MRI's rehearsal run, and 7.9 seconds for JRuby's second run. (Interestingly, MRI runs slower on the real run than the rehearsal; I am not sure why.)

ruby 2.0.0dev (2012-05-05 trunk 35540) [x86_64-darwin11.3.0]
Rehearsal ----------------------------------------------
initialize   7.770000   0.020000   7.790000 (  7.844972)
------------------------------------- total: 7.790000sec

                 user     system      total        real
initialize   8.990000   0.020000   9.010000 (  9.107190)

Show

Hiro Asari added a comment - 10/Jun/12 10:14 PM Performance regression seems to exist from 1.6.7 to 1.7.0, but the performance difference between MRI and JRuby 1.7.0 is not that great. If you run a rehearsal--that is, Benchmark.bmbm , rather than a simple Benchmark.measure , I get 7.7 seconds for MRI's rehearsal run, and 7.9 seconds for JRuby's second run. (Interestingly, MRI runs slower on the real run than the rehearsal; I am not sure why.) ruby 2.0.0dev (2012-05-05 trunk 35540) [x86_64-darwin11.3.0] Rehearsal ---------------------------------------------- initialize 7.770000 0.020000 7.790000 ( 7.844972) ------------------------------------- total: 7.790000sec user system total real initialize 8.990000 0.020000 9.010000 ( 9.107190)

Hide

Permalink

Charles Oliver Nutter added a comment - 12/Jun/12 2:47 PM

There's definitely a degradation here, and it appears to be related to invokedynamic.

system ~/projects/jruby $ (pickjdk 1 ; jruby bench/bench_tictactoe.rb)
New JDK: 1.6.0.jdk
  6.800000   0.140000   6.940000 (  4.587000)
  3.990000   0.110000   4.100000 (  3.661000)
  4.100000   0.100000   4.200000 (  3.696000)
  4.140000   0.120000   4.260000 (  3.774000)
  3.960000   0.110000   4.070000 (  3.717000)

system ~/projects/jruby $ (pickjdk 4 ; jruby bench/bench_tictactoe.rb)
New JDK: 1.7.0u.jdk
  8.360000   0.110000   8.470000 (  6.888000)
  6.100000   0.040000   6.140000 (  5.895000)
  6.140000   0.040000   6.180000 (  5.920000)
  6.910000   0.100000   7.010000 (  6.360000)
  6.290000   0.010000   6.300000 (  5.934000)

system ~/projects/jruby $ ruby1.9.3 bench/bench_tictactoe.rb
  5.190000   0.020000   5.210000 (  5.206695)
  5.580000   0.010000   5.590000 (  5.583369)
  5.920000   0.000000   5.920000 (  5.934210)
  6.280000   0.020000   6.300000 (  6.293913)
  6.640000   0.010000   6.650000 (  6.640099)

system ~/projects/jruby $ (pickjdk 4 ; jruby -Xcompile.invokedynamic=false bench/bench_tictactoe.rb)
New JDK: 1.7.0u.jdk
  5.850000   0.110000   5.960000 (  3.844000)
  2.860000   0.030000   2.890000 (  2.722000)
  2.820000   0.030000   2.850000 (  2.686000)
  3.440000   0.020000   3.460000 (  3.003000)
  3.060000   0.010000   3.070000 (  2.760000)

This may be something we need to punt over to the JVM JIT guys, but I will explore a bit.

Show

Charles Oliver Nutter added a comment - 12/Jun/12 2:47 PM There's definitely a degradation here, and it appears to be related to invokedynamic. system ~/projects/jruby $ (pickjdk 1 ; jruby bench/bench_tictactoe.rb) New JDK: 1.6.0.jdk 6.800000 0.140000 6.940000 ( 4.587000) 3.990000 0.110000 4.100000 ( 3.661000) 4.100000 0.100000 4.200000 ( 3.696000) 4.140000 0.120000 4.260000 ( 3.774000) 3.960000 0.110000 4.070000 ( 3.717000) system ~/projects/jruby $ (pickjdk 4 ; jruby bench/bench_tictactoe.rb) New JDK: 1.7.0u.jdk 8.360000 0.110000 8.470000 ( 6.888000) 6.100000 0.040000 6.140000 ( 5.895000) 6.140000 0.040000 6.180000 ( 5.920000) 6.910000 0.100000 7.010000 ( 6.360000) 6.290000 0.010000 6.300000 ( 5.934000) system ~/projects/jruby $ ruby1.9.3 bench/bench_tictactoe.rb 5.190000 0.020000 5.210000 ( 5.206695) 5.580000 0.010000 5.590000 ( 5.583369) 5.920000 0.000000 5.920000 ( 5.934210) 6.280000 0.020000 6.300000 ( 6.293913) 6.640000 0.010000 6.650000 ( 6.640099) system ~/projects/jruby $ (pickjdk 4 ; jruby -Xcompile.invokedynamic=false bench/bench_tictactoe.rb) New JDK: 1.7.0u.jdk 5.850000 0.110000 5.960000 ( 3.844000) 2.860000 0.030000 2.890000 ( 2.722000) 2.820000 0.030000 2.850000 ( 2.686000) 3.440000 0.020000 3.460000 ( 3.003000) 3.060000 0.010000 3.070000 ( 2.760000) This may be something we need to punt over to the JVM JIT guys, but I will explore a bit.

Hide

Permalink

Charles Oliver Nutter added a comment - 12/Jun/12 2:52 PM

Oddly enough, what I see in a sampled profile is excessive calls to System.identityHashCode:

         Stub + native   Method                        
 93.0%     0  +  2729    java.lang.System.identityHashCode
  0.3%     0  +     8    java.lang.Object.hashCode
  0.2%     0  +     5    java.lang.Thread.currentThread
  0.1%     0  +     4    java.lang.System.arraycopy

Need to figure out where these are coming from.

Show

Charles Oliver Nutter added a comment - 12/Jun/12 2:52 PM Oddly enough, what I see in a sampled profile is excessive calls to System.identityHashCode: Stub + native Method 93.0% 0 + 2729 java.lang.System.identityHashCode 0.3% 0 + 8 java.lang.Object.hashCode 0.2% 0 + 5 java.lang.Thread.currentThread 0.1% 0 + 4 java.lang.System.arraycopy Need to figure out where these are coming from.

Hide

Permalink

Charles Oliver Nutter added a comment - 29/Jun/12 7:48 PM

I have added this code as bench/bench_tictactoe.rb for future exploration. Have not found any additional information about why it's slower; it could simply be a case that invokedynamic does not yet optimize well...

Show

Charles Oliver Nutter added a comment - 29/Jun/12 7:48 PM I have added this code as bench/bench_tictactoe.rb for future exploration. Have not found any additional information about why it's slower; it could simply be a case that invokedynamic does not yet optimize well...

Hide

Permalink

Uwe Kubosch added a comment - 30/Jun/12 7:24 PM

Just for fun, I added this benchmark to the Ruboto Benchmark app. I have run it once on an HTC Desire HD with a 1GHZ ARM CPU. It completed in 1098 seconds.

Show

Uwe Kubosch added a comment - 30/Jun/12 7:24 PM Just for fun, I added this benchmark to the Ruboto Benchmark app. I have run it once on an HTC Desire HD with a 1GHZ ARM CPU. It completed in 1098 seconds.

Hide

Permalink

Charles Oliver Nutter added a comment - 26/Jul/12 5:27 PM

This issue is squarely on OpenJDK's invokedynamic optimizer (as of 7u4 and probably 7u6), unfortunately. However, there's a light at the end of the tunnel...the rewritten optimizer slated for 8 (and probably 7u8) is already faster, without much optimization work:

New JDK: 1.6.0.jdk

system ~/projects/jruby $ jruby ../rubybench/bench/time/bench_tictactoe.rb 
  7.140000   0.150000   7.290000 (  4.778000)
  4.170000   0.130000   4.300000 (  3.855000)
  4.210000   0.120000   4.330000 (  3.822000)
  4.190000   0.140000   4.330000 (  3.842000)
  4.050000   0.130000   4.180000 (  3.821000)
^C
system ~/projects/jruby $ pickjdk 2
New JDK: 1.7.0.jdk

system ~/projects/jruby $ jruby ../rubybench/bench/time/bench_tictactoe.rb 
  8.770000   0.110000   8.880000 (  7.028000)
  6.040000   0.040000   6.080000 (  5.878000)
  6.090000   0.070000   6.160000 (  5.940000)
  6.150000   0.050000   6.200000 (  5.939000)
  6.150000   0.040000   6.190000 (  5.946000)
  7.630000   0.050000   7.680000 (  6.845000)
  6.230000   0.010000   6.240000 (  5.877000)
  6.610000   0.010000   6.620000 (  5.975000)
  7.350000   0.020000   7.370000 (  6.128000)
^C
system ~/projects/jruby $ pickjdk 3
New JDK: 1.8.0.mlvm.head

system ~/projects/jruby $ jruby ../rubybench/bench/time/bench_tictactoe.rb 
 14.370000   0.270000  14.640000 (  5.485000)
  3.180000   0.040000   3.220000 (  3.048000)
  3.180000   0.030000   3.210000 (  3.014000)
  3.220000   0.040000   3.260000 (  3.045000)
  3.230000   0.030000   3.260000 (  3.015000)
  4.620000   0.030000   4.650000 (  3.918000)
^C

Wait a bit.

Show

Charles Oliver Nutter added a comment - 26/Jul/12 5:27 PM This issue is squarely on OpenJDK's invokedynamic optimizer (as of 7u4 and probably 7u6), unfortunately. However, there's a light at the end of the tunnel...the rewritten optimizer slated for 8 (and probably 7u8) is already faster, without much optimization work: New JDK: 1.6.0.jdk system ~/projects/jruby $ jruby ../rubybench/bench/time/bench_tictactoe.rb 7.140000 0.150000 7.290000 ( 4.778000) 4.170000 0.130000 4.300000 ( 3.855000) 4.210000 0.120000 4.330000 ( 3.822000) 4.190000 0.140000 4.330000 ( 3.842000) 4.050000 0.130000 4.180000 ( 3.821000) ^C system ~/projects/jruby $ pickjdk 2 New JDK: 1.7.0.jdk system ~/projects/jruby $ jruby ../rubybench/bench/time/bench_tictactoe.rb 8.770000 0.110000 8.880000 ( 7.028000) 6.040000 0.040000 6.080000 ( 5.878000) 6.090000 0.070000 6.160000 ( 5.940000) 6.150000 0.050000 6.200000 ( 5.939000) 6.150000 0.040000 6.190000 ( 5.946000) 7.630000 0.050000 7.680000 ( 6.845000) 6.230000 0.010000 6.240000 ( 5.877000) 6.610000 0.010000 6.620000 ( 5.975000) 7.350000 0.020000 7.370000 ( 6.128000) ^C system ~/projects/jruby $ pickjdk 3 New JDK: 1.8.0.mlvm.head system ~/projects/jruby $ jruby ../rubybench/bench/time/bench_tictactoe.rb 14.370000 0.270000 14.640000 ( 5.485000) 3.180000 0.040000 3.220000 ( 3.048000) 3.180000 0.030000 3.210000 ( 3.014000) 3.220000 0.040000 3.260000 ( 3.045000) 3.230000 0.030000 3.260000 ( 3.015000) 4.620000 0.030000 4.650000 ( 3.918000) ^C Wait a bit.

People

Assignee:

Charles Oliver Nutter

Reporter:

Gaurish Sharma

Vote (0)

Watch (4)

Dates

Created:

06/Jun/12 4:12 AM

Updated:

26/Jul/12 5:27 PM

Resolved:

26/Jul/12 5:27 PM