ActiveRecord is slower on JRuby than on MRI

Details

  • Type: Bug Bug
  • Status: Closed Closed
  • Priority: Major Major
  • Resolution: Not A Bug
  • Affects Version/s: None
  • Fix Version/s: None
  • Component/s: None
  • Labels:
    None
  • Testcase included:
    yes

Description

Thanks to Radoslaw Bulat (radarek on #jruby channel) we've got a set of AR benchmarks under jruby.
He's running linux, bechmarks are performed with jdk6u4, and MRI 1.8.6 compiled from source, they have been run on trunk (1.1).

Here are the pasties (content copied below as noformat):

http://pastie.caboo.se/157185
http://pastie.caboo.se/157188
http://pastie.caboo.se/157193
http://pastie.caboo.se/157215 # with logger
http://pastie.caboo.se/157228 # without logger
http://pastie.caboo.se/157234 # logger itself
http://pastie.caboo.se/157237
http://pastie.caboo.se/157246
http://pastie.caboo.se/157272 # new empty AR
http://pastie.caboo.se/157266 # new AR with atts

For the following table:

-----------+------+-----+---------+-----------------+----------------+
| Field       | Type         | Null | Key | Default | Extra          |
+-------------+--------------+------+-----+---------+----------------+
| id          | int(11)      | NO   | PRI | NULL    | auto_increment |
| name        | varchar(255) | YES  |     | NULL    |                |
| description | text         | YES  |     | NULL    |                |
| created_at  | datetime     | YES  |     | NULL    |                |
| updated_at  | datetime     | YES  |     | NULL    |                |
+-------------+--------------+------+-----+---------+----------------+

Benchmark.bm do |make|
  10.times do
    make.report do
      100_000.times do
        Widget.new.valid?
      end
    end
  end
end

=== ruby18
$ ruby1.8 ./lib/script/db.rb 
      user     system      total        real
  4.010000   0.000000   4.010000 (  4.020835)
  3.990000   0.000000   3.990000 (  4.012227)
  3.980000   0.000000   3.980000 (  3.991904)
  4.000000   0.000000   4.000000 (  4.027158)
  4.000000   0.000000   4.000000 (  4.029483)
  3.990000   0.000000   3.990000 (  3.994495)
  4.010000   0.000000   4.010000 (  4.027560)
  4.000000   0.000000   4.000000 (  4.026101)
  4.020000   0.000000   4.020000 (  4.044257)
  3.990000   0.000000   3.990000 (  4.000114)

=== jruby
$ jruby -J-server -J-Djruby.compile.fastest=true -J-Djruby.compile.frameless=true ./lib/script/db.rb
      user     system      total        real
  6.999000   0.000000   6.999000 (  6.999000)
  4.622000   0.000000   4.622000 (  4.622000)
  4.636000   0.000000   4.636000 (  4.635000)
  4.571000   0.000000   4.571000 (  4.571000)
  4.573000   0.000000   4.573000 (  4.572000)
  4.569000   0.000000   4.569000 (  4.569000)
  4.574000   0.000000   4.574000 (  4.574000)
  4.583000   0.000000   4.583000 (  4.583000)
  4.577000   0.000000   4.577000 (  4.577000)
  4.572000   0.000000   4.572000 (  4.572000)

 
Benchmark.bm do |make|
  10.times do
    make.report do
      100_000.times do
        Widget.new
      end
    end
  end
end

radarek@radarek:~/language-shootout/benchmarks/rails/testapp$ ruby1.8 ./lib/script/db2.rb       user     system      total        real
  1.450000   0.010000   1.460000 (  1.477560)
  1.440000   0.000000   1.440000 (  1.452845)
  1.450000   0.000000   1.450000 (  1.455343)
  1.450000   0.000000   1.450000 (  1.468160)
  1.450000   0.000000   1.450000 (  1.467478)
  1.440000   0.000000   1.440000 (  1.449292)
  1.450000   0.000000   1.450000 (  1.449435)
  1.440000   0.000000   1.440000 (  1.466980)
  1.450000   0.000000   1.450000 (  1.456367)
  1.450000   0.000000   1.450000 (  1.449763)

radarek@radarek:~/language-shootout/benchmarks/rails/testapp$ jruby -J-server -J-Djruby.compile.fastest=true -J-Djruby.compile.frameless=true ./lib/script/db2.rb
      user     system      total        real
  3.463000   0.000000   3.463000 (  3.463000)
  2.077000   0.000000   2.077000 (  2.077000)
  2.069000   0.000000   2.069000 (  2.068000)
  2.039000   0.000000   2.039000 (  2.040000)
  2.042000   0.000000   2.042000 (  2.042000)
  2.052000   0.000000   2.052000 (  2.052000)
  2.035000   0.000000   2.035000 (  2.035000)
  2.055000   0.000000   2.055000 (  2.055000)
  2.036000   0.000000   2.036000 (  2.035000)
  2.043000   0.000000   2.043000 (  2.044000)

Benchmark.bm do |make|
  10.times do
    w = Widget.new
    make.report do
      100_000.times do
        w.valid?
      end
    end
  end
end
radarek@radarek:~/language-shootout/benchmarks/rails/testapp$ ruby1.8 ./lib/script/db3.rb 
      user     system      total        real
  2.110000   0.000000   2.110000 (  2.129940)
  2.080000   0.000000   2.080000 (  2.078367)
  2.100000   0.000000   2.100000 (  2.110602)
  2.100000   0.000000   2.100000 (  2.112235)
  2.060000   0.000000   2.060000 (  2.078087)
  2.110000   0.000000   2.110000 (  2.108611)
  2.090000   0.000000   2.090000 (  2.104657)
  2.070000   0.000000   2.070000 (  2.068924)
  2.090000   0.000000   2.090000 (  2.110685)
  2.100000   0.000000   2.100000 (  2.101212)
radarek@radarek:~/language-shootout/benchmarks/rails/testapp$ jruby -J-server -J-Djruby.compile.fastest=true -J-Djruby.compile.frameless=true ./lib/script/db3.rb
      user     system      total        real
  2.911000   0.000000   2.911000 (  2.911000)
  2.118000   0.000000   2.118000 (  2.119000)
  2.027000   0.000000   2.027000 (  2.027000)
  2.031000   0.000000   2.031000 (  2.031000)
  2.107000   0.000000   2.107000 (  2.106000)
  2.059000   0.000000   2.059000 (  2.060000)
  2.072000   0.000000   2.072000 (  2.072000)
  2.051000   0.000000   2.051000 (  2.052000)
  2.062000   0.000000   2.062000 (  2.062000)
  2.074000   0.000000   2.074000 (  2.073000)

With Logger ON

Benchmark.bm do |make|
  10.times do
    make.report do
      10_000.times do
        Widget.find(:all)
      end
    end
  end
end

radarek@radarek:~/language-shootout/benchmarks/rails/testapp$ ruby1.8 lib/script/db4.rb 
      user     system      total        real
  2.250000   0.150000   2.400000 (  2.562183)
  2.250000   0.140000   2.390000 (  2.545450)
  2.170000   0.200000   2.370000 (  2.552200)
  2.170000   0.200000   2.370000 (  2.533839)
  2.200000   0.180000   2.380000 (  2.553121)
  2.220000   0.160000   2.380000 (  2.544484)
  2.200000   0.180000   2.380000 (  2.552828)
  2.180000   0.160000   2.340000 (  2.538723)
  2.130000   0.210000   2.340000 (  2.554477)
  2.210000   0.150000   2.360000 (  2.538447)
radarek@radarek:~/language-shootout/benchmarks/rails/testapp$ jruby -J-server -J-Djruby.compile.fastest=true -J-Djruby.compile.frameless=true ./lib/script/db4.rb
      user     system      total        real
 11.654000   0.000000  11.654000 ( 11.653000)
  5.945000   0.000000   5.945000 (  5.944000)
  4.035000   0.000000   4.035000 (  4.035000)
  4.137000   0.000000   4.137000 (  4.138000)
  4.010000   0.000000   4.010000 (  4.010000)
  3.979000   0.000000   3.979000 (  3.980000)
  3.909000   0.000000   3.909000 (  3.910000)
  3.920000   0.000000   3.920000 (  3.921000)
  3.896000   0.000000   3.896000 (  3.896000)
  3.892000   0.000000   3.892000 (  3.892000)

With Logger OFF

Benchmark.bm do |make|
  10.times do
    make.report do
      10_000.times do
        Widget.find(:all)
      end
    end
  end
end
radarek@radarek:~/language-shootout/benchmarks/rails/testapp$ ruby1.8 lib/script/db5.rb       user     system      total        real
  1.590000   0.100000   1.690000 (  1.853620)
  1.590000   0.080000   1.670000 (  1.854516)
  1.550000   0.140000   1.690000 (  1.841983)
  1.600000   0.100000   1.700000 (  1.846823)
  1.610000   0.100000   1.710000 (  1.881888)
  1.580000   0.120000   1.700000 (  1.842732)
  1.550000   0.120000   1.670000 (  1.861359)
  1.550000   0.120000   1.670000 (  1.844078)
  1.580000   0.110000   1.690000 (  1.840608)
  1.530000   0.130000   1.660000 (  1.862033)
radarek@radarek:~/language-shootout/benchmarks/rails/testapp$ jruby -J-server -J-Djruby.compile.fastest=true -J-Djruby.compile.frameless=true ./lib/script/db5.rb
      user     system      total        real
  8.040000   0.000000   8.040000 (  8.040000)
  4.005000   0.000000   4.005000 (  4.005000)
  3.169000   0.000000   3.169000 (  3.169000)
  3.126000   0.000000   3.126000 (  3.125000)
  3.187000   0.000000   3.187000 (  3.188000)
  3.168000   0.000000   3.168000 (  3.168000)
  3.116000   0.000000   3.116000 (  3.116000)
  3.141000   0.000000   3.141000 (  3.141000)
  3.122000   0.000000   3.122000 (  3.122000)
  3.131000   0.000000   3.131000 (  3.131000)

Logger itself

Benchmark.bm do |make|
  10.times do
    logger = Logger.new("file.log")
    make.report do
      100_000.times do
        logger.debug("hello")
      end
    end
    logger.close
  end
end

radarek@radarek:~/language-shootout/benchmarks/rails/testapp/lib/script$ ruby1.8 logger.rb 
      user     system      total        real
  1.960000   0.460000   2.420000 (  2.430892)
  2.020000   0.420000   2.440000 (  2.445514)
  2.080000   0.360000   2.440000 (  2.460246)
  2.060000   0.400000   2.460000 (  2.453739)
  1.990000   0.450000   2.440000 (  2.456820)
  2.030000   0.420000   2.450000 (  2.446001)
  2.070000   0.370000   2.440000 (  2.465550)
  2.030000   0.400000   2.430000 (  2.446837)
  2.100000   0.360000   2.460000 (  2.463839)
  2.030000   0.420000   2.450000 (  2.448888)
radarek@radarek:~/language-shootout/benchmarks/rails/testapp/lib/script$ jruby -J-server -J-Djruby.compile.fastest=true -J-Djruby.compile.frameless=true logger.rb 
      user     system      total        real
  6.101000   0.000000   6.101000 (  6.101000)
  3.013000   0.000000   3.013000 (  3.013000)
  2.914000   0.000000   2.914000 (  2.914000)
  2.793000   0.000000   2.793000 (  2.792000)
  2.812000   0.000000   2.812000 (  2.813000)
  2.750000   0.000000   2.750000 (  2.751000)
  2.891000   0.000000   2.891000 (  2.890000)
  2.744000   0.000000   2.744000 (  2.744000)
  2.738000   0.000000   2.738000 (  2.737000)
  2.750000   0.000000   2.750000 (  2.749000)

Benchmark.bm do |make|
  10.times do
    logger = ActiveSupport::BufferedLogger.new("file.log")
    make.report do
      100_000.times do
        logger.add(ActiveSupport::BufferedLogger::DEBUG, "dupa")
      end
    end
    logger.close
  end
end

radarek@radarek:~/language-shootout/benchmarks/rails/testapp/lib/script$ ruby1.8 buffered_logger.rb 
      user     system      total        real
  0.570000   0.120000   0.690000 (  0.689881)
  0.540000   0.150000   0.690000 (  0.697821)
  0.510000   0.180000   0.690000 (  0.693132)
  0.530000   0.160000   0.690000 (  0.695423)
  0.530000   0.170000   0.700000 (  0.705588)
  0.520000   0.150000   0.670000 (  0.687026)
  0.540000   0.160000   0.700000 (  0.701501)
  0.530000   0.160000   0.690000 (  0.684573)
  0.550000   0.140000   0.690000 (  0.698574)
  0.520000   0.160000   0.680000 (  0.693477)
radarek@radarek:~/language-shootout/benchmarks/rails/testapp/lib/script$ jruby -J-server -J-Djruby.compile.fastest=true -J-Djruby.compile.frameless=true buffered_logger.rb 
      user     system      total        real
  1.887000   0.000000   1.887000 (  1.887000)
  0.991000   0.000000   0.991000 (  0.990000)
  0.945000   0.000000   0.945000 (  0.944000)
  0.793000   0.000000   0.793000 (  0.794000)
  0.834000   0.000000   0.834000 (  0.834000)
  0.818000   0.000000   0.818000 (  0.818000)
  0.804000   0.000000   0.804000 (  0.804000)
  0.808000   0.000000   0.808000 (  0.808000)
  0.801000   0.000000   0.801000 (  0.801000)
  0.803000   0.000000   0.803000 (  0.804000)

Benchmark.bm do |make|
  10.times do
    w = Widget.find(:first)
    make.report do
      10_000.times do
        w.attributes # rails makes copy for every call
      end
    end
  end
end
radarek@radarek:~/language-shootout/benchmarks/rails/testapp$ ruby1.8 ./lib/script/ar_attributes.rb 
      user     system      total        real
  0.600000   0.040000   0.640000 (  0.640588)
  0.600000   0.020000   0.620000 (  0.626348)
  0.630000   0.010000   0.640000 (  0.646735)
  0.620000   0.020000   0.640000 (  0.644046)
  0.610000   0.010000   0.620000 (  0.624194)
  0.630000   0.020000   0.650000 (  0.652418)
  0.620000   0.020000   0.640000 (  0.647553)
  0.600000   0.020000   0.620000 (  0.636091)
  0.630000   0.020000   0.650000 (  0.646214)
  0.630000   0.020000   0.650000 (  0.647887)
radarek@radarek:~/language-shootout/benchmarks/rails/testapp$ jruby -J-server -J-Djruby.compile.fastest=true -J-Djruby.compile.frameless=true ./lib/script/ar_attributes.rb 
      user     system      total        real
  3.925000   0.000000   3.925000 (  3.925000)
  1.048000   0.000000   1.048000 (  1.048000)
  1.009000   0.000000   1.009000 (  1.009000)
  0.938000   0.000000   0.938000 (  0.937000)
  0.969000   0.000000   0.969000 (  0.969000)
  0.926000   0.000000   0.926000 (  0.927000)
  0.935000   0.000000   0.935000 (  0.935000)
  0.931000   0.000000   0.931000 (  0.930000)
  0.939000   0.000000   0.939000 (  0.938000)
  0.931000   0.000000   0.931000 (  0.932000)

new empty AR instance

Benchmark.bm do |make|
  10.times do
    make.report do
      100_000.times do
        Widget.new
      end
    end
  end
end
radarek@radarek:~/language-shootout/benchmarks/rails/testapp$ ruby1.8 ./lib/script/ar_creating_new.rb       user     system      total        real
  1.450000   0.000000   1.450000 (  1.455953)
  1.460000   0.000000   1.460000 (  1.456910)
  1.460000   0.000000   1.460000 (  1.457109)
  1.450000   0.000000   1.450000 (  1.458126)
  1.470000   0.000000   1.470000 (  1.459992)
  1.460000   0.000000   1.460000 (  1.459783)
  1.460000   0.000000   1.460000 (  1.468527)
  1.460000   0.000000   1.460000 (  1.461333)
  1.470000   0.000000   1.470000 (  1.464491)
  1.460000   0.000000   1.460000 (  1.463433)
radarek@radarek:~/language-shootout/benchmarks/rails/testapp$ jruby -J-server -J-Djruby.compile.fastest=true -J-Djruby.compile.frameless=true ./lib/script/ar_creating_new.rb 
      user     system      total        real
  3.560000   0.000000   3.560000 (  3.559000)
  2.109000   0.000000   2.109000 (  2.110000)
  2.109000   0.000000   2.109000 (  2.109000)
  2.061000   0.000000   2.061000 (  2.061000)
  2.056000   0.000000   2.056000 (  2.056000)
  2.053000   0.000000   2.053000 (  2.054000)
  2.057000   0.000000   2.057000 (  2.057000)
  2.057000   0.000000   2.057000 (  2.057000)
  2.056000   0.000000   2.056000 (  2.056000)
  2.053000   0.000000   2.053000 (  2.054000)

New AR instance constructed with attributes

Benchmark.bm do |make|
  10.times do
    w = Widget.find(:first)
    params = w.attributes
    make.report do
      10_000.times do
        Widget.new(params)
      end
    end
  end
end
radarek@radarek:~/language-shootout/benchmarks/rails/testapp$ ruby1.8 ./lib/script/ar_creating.rb
      user     system      total        real
  0.760000   0.000000   0.760000 (  0.757167)
  0.730000   0.000000   0.730000 (  0.732888)
  0.760000   0.000000   0.760000 (  0.756183)
  0.760000   0.000000   0.760000 (  0.758768)
  0.730000   0.000000   0.730000 (  0.732527)
  0.750000   0.000000   0.750000 (  0.760008)
  0.760000   0.000000   0.760000 (  0.762963)
  0.730000   0.000000   0.730000 (  0.734364)
  0.760000   0.000000   0.760000 (  0.755586)
  0.750000   0.000000   0.750000 (  0.754439)
radarek@radarek:~/language-shootout/benchmarks/rails/testapp$ jruby -J-server -J-Djruby.compile.fastest=true -J-Djruby.compile.frameless=true ./lib/script/ar_creating.rb
      user     system      total        real
  3.241000   0.000000   3.241000 (  3.240000)
  1.349000   0.000000   1.349000 (  1.349000)
  0.791000   0.000000   0.791000 (  0.791000)
  0.781000   0.000000   0.781000 (  0.781000)
  0.828000   0.000000   0.828000 (  0.828000)
  0.784000   0.000000   0.784000 (  0.784000)
  0.758000   0.000000   0.758000 (  0.758000)
  0.754000   0.000000   0.754000 (  0.754000)
  0.754000   0.000000   0.754000 (  0.754000)
  0.758000   0.000000   0.758000 (  0.758000)

Activity

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

For the second benchmark (simple .new) on my Monkey model (which has no non-ID fields) I got the following numbers...

This is JRuby trunk, jdbcmysql adapter, soylatte Java 6 versus Ruby 1.8.6p111 with native mysql adapter.

Ruby:
      user     system      total        real
  2.380000   0.020000   2.400000 (  2.475780)
  2.370000   0.010000   2.380000 (  2.397260)
  2.370000   0.010000   2.380000 (  2.449795)
  2.370000   0.020000   2.390000 (  2.445653)
  2.360000   0.010000   2.370000 (  2.444433)
  2.380000   0.010000   2.390000 (  2.465965)
  2.360000   0.010000   2.370000 (  2.448068)
  2.440000   0.020000   2.460000 (  2.522087)
  2.360000   0.010000   2.370000 (  2.378655)
  2.370000   0.020000   2.390000 (  2.415232)

JRuby:
      user     system      total        real
  3.203000   0.000000   3.203000 (  3.203000)
  1.524000   0.000000   1.524000 (  1.524000)
  1.316000   0.000000   1.316000 (  1.316000)
  1.594000   0.000000   1.594000 (  1.593000)
  1.295000   0.000000   1.295000 (  1.295000)
  1.289000   0.000000   1.289000 (  1.289000)
  1.387000   0.000000   1.387000 (  1.387000)
  1.362000   0.000000   1.362000 (  1.362000)
  1.294000   0.000000   1.294000 (  1.294000)
  1.293000   0.000000   1.293000 (  1.293000)
Show
Charles Oliver Nutter added a comment - For the second benchmark (simple .new) on my Monkey model (which has no non-ID fields) I got the following numbers... This is JRuby trunk, jdbcmysql adapter, soylatte Java 6 versus Ruby 1.8.6p111 with native mysql adapter. 
Ruby:
      user     system      total        real
  2.380000   0.020000   2.400000 (  2.475780)
  2.370000   0.010000   2.380000 (  2.397260)
  2.370000   0.010000   2.380000 (  2.449795)
  2.370000   0.020000   2.390000 (  2.445653)
  2.360000   0.010000   2.370000 (  2.444433)
  2.380000   0.010000   2.390000 (  2.465965)
  2.360000   0.010000   2.370000 (  2.448068)
  2.440000   0.020000   2.460000 (  2.522087)
  2.360000   0.010000   2.370000 (  2.378655)
  2.370000   0.020000   2.390000 (  2.415232)

JRuby:
      user     system      total        real
  3.203000   0.000000   3.203000 (  3.203000)
  1.524000   0.000000   1.524000 (  1.524000)
  1.316000   0.000000   1.316000 (  1.316000)
  1.594000   0.000000   1.594000 (  1.593000)
  1.295000   0.000000   1.295000 (  1.295000)
  1.289000   0.000000   1.289000 (  1.289000)
  1.387000   0.000000   1.387000 (  1.387000)
  1.362000   0.000000   1.362000 (  1.362000)
  1.294000   0.000000   1.294000 (  1.294000)
  1.293000   0.000000   1.293000 (  1.293000)
Hide
Permalink
Christian Seiler added a comment -

MySQL, Ubuntu Java 1.6.0_06-b02, JRuby rev7134

script/generate model Testm t1:datetime t2:datetime t3:datetime t4:datetime t5:datetime t6:datetime t7:datetime t8:datetime t9:datetime t10:datetime

10.times {puts Benchmark.measure {10000.times {Testm.new }}.total}

JRuby rev7134 /jruby -J-server -J-Xshare:off script/console
2.3480000495910645
0.8380000591278076
0.8640000820159912
0.9789998531341553
0.875
0.8489999771118164
0.8600001335144043
0.8320000171661377
0.8639998435974121
0.8430001735687256

MRI:
0.76
0.71
0.79
0.71
0.7
0.700000000000001
0.699999999999999
0.72
0.700000000000001
0.7

further reading:
http://blog.huikau.com/2008/07/04/jruby-slowdown-from-rails-202-to-210/
http://www.nabble.com/JRuby-1.1.3-by-end-of-week...Nominate-problems-here...-td18448971.html

Show
Christian Seiler added a comment - MySQL, Ubuntu Java 1.6.0_06-b02, JRuby rev7134 script/generate model Testm t1:datetime t2:datetime t3:datetime t4:datetime t5:datetime t6:datetime t7:datetime t8:datetime t9:datetime t10:datetime 10.times {puts Benchmark.measure {10000.times {Testm.new }}.total} JRuby rev7134 /jruby -J-server -J-Xshare:off script/console 2.3480000495910645 0.8380000591278076 0.8640000820159912 0.9789998531341553 0.875 0.8489999771118164 0.8600001335144043 0.8320000171661377 0.8639998435974121 0.8430001735687256 MRI: 0.76 0.71 0.79 0.71 0.7 0.700000000000001 0.699999999999999 0.72 0.700000000000001 0.7 further reading: http://blog.huikau.com/2008/07/04/jruby-slowdown-from-rails-202-to-210/ http://www.nabble.com/JRuby-1.1.3-by-end-of-week...Nominate-problems-here...-td18448971.html
Hide
Permalink
Christian Seiler added a comment -

Played around with VisualVM, CPU profiles the benchmark I mentioned in my last comment. Don't know if it helps

Show
Christian Seiler added a comment - Played around with VisualVM, CPU profiles the benchmark I mentioned in my last comment. Don't know if it helps
Hide
Permalink
Christian Seiler added a comment -

why does object space show up in the list (though only 1.5%)? I thought it's deactivated by default

Show
Christian Seiler added a comment - why does object space show up in the list (though only 1.5%)? I thought it's deactivated by default
Hide
Permalink
Charles Oliver Nutter added a comment -

Christian: hey...that is odd. That's extremely odd. It is supposed to be off by default, which should mean add is never being called. But there it is. Hmmmm.

Show
Charles Oliver Nutter added a comment - Christian: hey...that is odd. That's extremely odd. It is supposed to be off by default, which should mean add is never being called. But there it is. Hmmmm.
Hide
Permalink
Charles Oliver Nutter added a comment -

Christian: Ok, either something's wrong in your environment, or there's something terribly wrong elsewhere. Could you set up a build of JRuby that dumps stack inside ObjectSpace.add and find out where it's happening? It absolutely should not be getting called unless ObjectSpace has been turned on.

Show
Charles Oliver Nutter added a comment - Christian: Ok, either something's wrong in your environment, or there's something terribly wrong elsewhere. Could you set up a build of JRuby that dumps stack inside ObjectSpace.add and find out where it's happening? It absolutely should not be getting called unless ObjectSpace has been turned on.
Hide
Permalink
Christian Seiler added a comment -

jirb is to blame. the script turns on ObjectSpace:

if defined?(JRUBY_VERSION)
require 'jruby'

  1. useful for code completion
    JRuby.objectspace = true
    end

Running script/server does not touch ObjectSpace

Show
Christian Seiler added a comment - jirb is to blame. the script turns on ObjectSpace: if defined?(JRUBY_VERSION) require 'jruby'
  1. useful for code completion JRuby.objectspace = true end
Running script/server does not touch ObjectSpace
Hide
Permalink
Christian Seiler added a comment -

... and now the "instantiation only" test runs twice as fast as MRI! So I can second Charles' numbers above. Querying the database is still 20-30% slower with AR-JDBC than with MRI/unix sockets, but that's not too bad IMO

Show
Christian Seiler added a comment - ... and now the "instantiation only" test runs twice as fast as MRI! So I can second Charles' numbers above. Querying the database is still 20-30% slower with AR-JDBC than with MRI/unix sockets, but that's not too bad IMO
Hide
Permalink
Charles Oliver Nutter added a comment -

With some recent changes, the first benchmark (new + valid?) appears to be faster on JRuby. I committed that test to ARJDBC as bench/bench_new_valid.rb. Continuing on to the next one.

Show
Charles Oliver Nutter added a comment - With some recent changes, the first benchmark (new + valid?) appears to be faster on JRuby. I committed that test to ARJDBC as bench/bench_new_valid.rb. Continuing on to the next one.
Hide
Permalink
Charles Oliver Nutter added a comment -

It's also worth mentioning that Rails version makes a huge difference. I ran the new/valid benchmark under Rails 1.2.x under MRI and the performance was vastly different. So anyone trying these benchmarks must make absolutely sure they're comparing the same Rails versions.

Show
Charles Oliver Nutter added a comment - It's also worth mentioning that Rails version makes a huge difference. I ran the new/valid benchmark under Rails 1.2.x under MRI and the performance was vastly different. So anyone trying these benchmarks must make absolutely sure they're comparing the same Rails versions.
Hide
Permalink
Charles Oliver Nutter added a comment -

The second benchmark (new only) also appears to be consistently faster in JRuby, by almost 2x.

Show
Charles Oliver Nutter added a comment - The second benchmark (new only) also appears to be consistently faster in JRuby, by almost 2x.
Hide
Permalink
Charles Oliver Nutter added a comment -

Third benchmark also faster in JRuby. I reworked the new/valid benchmark to match the original and added "new alone" and "valid alone" benchmarks.

Show
Charles Oliver Nutter added a comment - Third benchmark also faster in JRuby. I reworked the new/valid benchmark to match the original and added "new alone" and "valid alone" benchmarks.
Hide
Permalink
Charles Oliver Nutter added a comment -

The fourth benchmark appears to be faster but much more dependent on warmup time:

~/NetBeansProjects/trunk/activerecord-jdbc ➔ RAILS_ENV=production jruby --server bench/bench_find_all.rb 
      user     system      total        real
 12.825000   0.000000  12.825000 ( 12.825309)
  7.231000   0.000000   7.231000 (  7.230854)
  4.094000   0.000000   4.094000 (  4.093866)
  3.915000   0.000000   3.915000 (  3.915573)
  4.400000   0.000000   4.400000 (  4.400375)
~/NetBeansProjects/trunk/activerecord-jdbc ➔ RAILS_ENV=production /opt/local/bin/ruby bench/bench_find_all.rb 
      user     system      total        real
  4.660000   0.250000   4.910000 (  5.836791)
  4.630000   0.230000   4.860000 (  5.771809)
  4.720000   0.240000   4.960000 (  6.459771)
  4.640000   0.230000   4.870000 (  5.790948)
  4.630000   0.230000   4.860000 (  5.769214)

This could mean that the code in question is slower when interpreted and eventually JITs. Or it could mean something else. The other benchmarks appear to be faster in JRuby almost immediately, so there's something to look into on benchmark #4.

Show
Charles Oliver Nutter added a comment - The fourth benchmark appears to be faster but much more dependent on warmup time: 
~/NetBeansProjects/trunk/activerecord-jdbc ➔ RAILS_ENV=production jruby --server bench/bench_find_all.rb 
      user     system      total        real
 12.825000   0.000000  12.825000 ( 12.825309)
  7.231000   0.000000   7.231000 (  7.230854)
  4.094000   0.000000   4.094000 (  4.093866)
  3.915000   0.000000   3.915000 (  3.915573)
  4.400000   0.000000   4.400000 (  4.400375)
~/NetBeansProjects/trunk/activerecord-jdbc ➔ RAILS_ENV=production /opt/local/bin/ruby bench/bench_find_all.rb 
      user     system      total        real
  4.660000   0.250000   4.910000 (  5.836791)
  4.630000   0.230000   4.860000 (  5.771809)
  4.720000   0.240000   4.960000 (  6.459771)
  4.640000   0.230000   4.870000 (  5.790948)
  4.630000   0.230000   4.860000 (  5.769214)
This could mean that the code in question is slower when interpreted and eventually JITs. Or it could mean something else. The other benchmarks appear to be faster in JRuby almost immediately, so there's something to look into on benchmark #4.
Hide
Permalink
Charles Oliver Nutter added a comment -

Actually scratch that...with the native MySQL gem installed the Ruby times on benchmark #4 drop to more like 2.3-2.4s per iteration. So once we actually start hitting the database there's bottlenecks getting in the way. So benchmark #4 is the first place to start looking.

I'm running with an empty table, but we will also want to get results with different table sizes as well.

Show
Charles Oliver Nutter added a comment - Actually scratch that...with the native MySQL gem installed the Ruby times on benchmark #4 drop to more like 2.3-2.4s per iteration. So once we actually start hitting the database there's bottlenecks getting in the way. So benchmark #4 is the first place to start looking. I'm running with an empty table, but we will also want to get results with different table sizes as well.
Hide
Permalink
Thomas E Enebo added a comment -

This issue has led to the creation of several bench scripts and I have used at least bench_find_all.rb to get within 10-20% of MRI (improving perf over 20%) when MRI uses a network port (versus UDS). So it has definitely served a purpose. For future perf bugs in AR-JDBC we should probably concentrate on individual operations since they all seem to have different perf characteristics and it sucks to fix them all before the issue can be resolved

Show
Thomas E Enebo added a comment - This issue has led to the creation of several bench scripts and I have used at least bench_find_all.rb to get within 10-20% of MRI (improving perf over 20%) when MRI uses a network port (versus UDS). So it has definitely served a purpose. For future perf bugs in AR-JDBC we should probably concentrate on individual operations since they all seem to have different perf characteristics and it sucks to fix them all before the issue can be resolved

People

  • Assignee:
    Thomas E Enebo
    Reporter:
    Marcin Mielzynski
Vote (1)
Watch (2)

Dates

  • Created:
    Updated:
    Resolved: