JRuby (please use github issues at http://bugs.jruby.org)
  1. JRuby (please use github issues at http://bugs.jruby.org)
  2. JRUBY-6707

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

    Details

    • Type: Bug Bug
    • Status: Resolved Resolved
    • Priority: Major 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:
    • 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

        Activity

        Hide
        Gaurish Sharma added a comment -
        Show
        Gaurish Sharma added a comment - The attached code is taken from here: https://github.com/flyingmachine/minimax-tictactoe/blob/master/phase2/tictactoe.rb
        Hide
        Hiro Asari added a comment -

        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 - 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
        Charles Oliver Nutter added a comment -

        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 - 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
        Charles Oliver Nutter added a comment -

        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 - 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
        Charles Oliver Nutter added a comment -

        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 - 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
        Uwe Kubosch added a comment -

        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 - 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
        Charles Oliver Nutter added a comment -

        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 - 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
          • Votes:
            0 Vote for this issue
            Watchers:
            4 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved: