File opening speed is slower than MRI

Details

  • Type: Bug Bug
  • Status: Open Open
  • Priority: Major Major
  • Resolution: Unresolved
  • Affects Version/s: JRuby 1.1.3
  • Fix Version/s: None
  • Component/s: Performance
  • Labels:
    None

Description

Some of this is due to Java libs just having more "open" overhead than e.g. open(2), but some of it is also excessive logic in our "open" call chain. It's pretty bad perf either way. Based on bench_io_open.rb in test/bench:

JRuby:
                            user     system      total        real
File.open(file, "r+")   0.617000   0.000000   0.617000 (  0.617008)
File.open(file, "r+")   0.608000   0.000000   0.608000 (  0.608075)
File.open(file, "r+")   0.608000   0.000000   0.608000 (  0.607263)
File.open(file, "r+")   0.605000   0.000000   0.605000 (  0.604758)
File.open(file, "r+")   0.601000   0.000000   0.601000 (  0.600772)
File.open(file, "r+")   0.621000   0.000000   0.621000 (  0.621210)
File.open(file, "r+")   0.601000   0.000000   0.601000 (  0.600824)
File.open(file, "r+")   0.602000   0.000000   0.602000 (  0.601984)
File.open(file, "r+")   0.602000   0.000000   0.602000 (  0.602048)
File.open(file, "r+")   0.615000   0.000000   0.615000 (  0.615581)

Ruby:
                            user     system      total        real
File.open(file, "r+")   0.080000   0.100000   0.180000 (  0.177464)
File.open(file, "r+")   0.070000   0.090000   0.160000 (  0.176072)
File.open(file, "r+")   0.070000   0.100000   0.170000 (  0.179987)
File.open(file, "r+")   0.080000   0.100000   0.180000 (  0.173712)
File.open(file, "r+")   0.070000   0.100000   0.170000 (  0.171952)
File.open(file, "r+")   0.070000   0.100000   0.170000 (  0.173249)
File.open(file, "r+")   0.080000   0.090000   0.170000 (  0.180945)
File.open(file, "r+")   0.070000   0.100000   0.170000 (  0.174079)
File.open(file, "r+")   0.070000   0.100000   0.170000 (  0.178888)
File.open(file, "r+")   0.080000   0.100000   0.180000 (  0.181685)

Activity

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

Still valid; slightly improved since it was filed, though.

Show
Charles Oliver Nutter added a comment - Still valid; slightly improved since it was filed, though.
Hide
Permalink
Charles Oliver Nutter added a comment -

Latest results show us only about 2x slower than MRI, so we're pretty close now.

Show
Charles Oliver Nutter added a comment - Latest results show us only about 2x slower than MRI, so we're pretty close now.
Hide
Permalink
Ivo Wever added a comment -

It seems there has been a regression here. JRuby 1.4.1 is consistently around 5% faster than 1.5.6 on my system. MRI is a factor 9 faster still. I left 1.2.0 out, but it was consistently slower than 1.4.1.

ruby -v bench/bench_io_open.rb
ruby 1.8.7 (2010-04-19 patchlevel 253) [x86_64-linux], MBARI 0x6770, Ruby Enterprise Edition 2010.02
Rehearsal ---------------------------------------------------------
File.open(file, "r+")   0.030000   0.020000   0.050000 (  0.060564)
File.open(file, "r+")   0.030000   0.020000   0.050000 (  0.061693)
File.open(file, "r+")   0.020000   0.040000   0.060000 (  0.062378)
File.open(file, "r+")   0.040000   0.010000   0.050000 (  0.060962)
File.open(file, "r+")   0.040000   0.010000   0.050000 (  0.061521)
File.open(file, "r+")   0.040000   0.010000   0.050000 (  0.062309)
File.open(file, "r+")   0.040000   0.010000   0.050000 (  0.062137)
File.open(file, "r+")   0.040000   0.010000   0.050000 (  0.061564)
File.open(file, "r+")   0.050000   0.010000   0.060000 (  0.061476)
File.open(file, "r+")   0.030000   0.020000   0.050000 (  0.062032)
------------------------------------------------ total: 0.520000sec

~/bin/jruby-1.4.1/bin/jruby -v bench/bench_io_open.rb
jruby 1.4.1 (ruby 1.8.7 patchlevel 174) (2010-04-26 ea6db6a) (Java HotSpot(TM) 64-Bit Server VM 1.6.0_20) [amd64-java]
Rehearsal ---------------------------------------------------------
File.open(file, "r+")   1.090000   0.000000   1.090000 (  1.041000)
File.open(file, "r+")   0.832000   0.000000   0.832000 (  0.831000)
File.open(file, "r+")   0.743000   0.000000   0.743000 (  0.743000)
File.open(file, "r+")   0.292000   0.000000   0.292000 (  0.292000)
File.open(file, "r+")   0.339000   0.000000   0.339000 (  0.340000)
File.open(file, "r+")   0.261000   0.000000   0.261000 (  0.261000)
File.open(file, "r+")   0.313000   0.000000   0.313000 (  0.313000)
File.open(file, "r+")   0.248000   0.000000   0.248000 (  0.248000)
File.open(file, "r+")   0.305000   0.000000   0.305000 (  0.305000)
File.open(file, "r+")   0.241000   0.000000   0.241000 (  0.241000)
------------------------------------------------ total: 4.664000sec

~/bin/jruby-1.5.6/bin/jruby -v bench/bench_io_open.rb
jruby 1.5.6 (ruby 1.8.7 patchlevel 249) (2010-12-03 9cf97c3) (Java HotSpot(TM) 64-Bit Server VM 1.6.0_20) [amd64-java]
Rehearsal ---------------------------------------------------------
File.open(file, "r+")   1.159000   0.000000   1.159000 (  1.103000)
File.open(file, "r+")   0.940000   0.000000   0.940000 (  0.939000)
File.open(file, "r+")   0.627000   0.000000   0.627000 (  0.628000)
File.open(file, "r+")   0.409000   0.000000   0.409000 (  0.409000)
File.open(file, "r+")   0.384000   0.000000   0.384000 (  0.384000)
File.open(file, "r+")   0.267000   0.000000   0.267000 (  0.267000)
File.open(file, "r+")   0.306000   0.000000   0.306000 (  0.306000)
File.open(file, "r+")   0.254000   0.000000   0.254000 (  0.254000)
File.open(file, "r+")   0.340000   0.000000   0.340000 (  0.340000)
File.open(file, "r+")   0.254000   0.000000   0.254000 (  0.254000)
------------------------------------------------ total: 4.939999sec
Show
Ivo Wever added a comment - It seems there has been a regression here. JRuby 1.4.1 is consistently around 5% faster than 1.5.6 on my system. MRI is a factor 9 faster still. I left 1.2.0 out, but it was consistently slower than 1.4.1. 
ruby -v bench/bench_io_open.rb
ruby 1.8.7 (2010-04-19 patchlevel 253) [x86_64-linux], MBARI 0x6770, Ruby Enterprise Edition 2010.02
Rehearsal ---------------------------------------------------------
File.open(file, "r+")   0.030000   0.020000   0.050000 (  0.060564)
File.open(file, "r+")   0.030000   0.020000   0.050000 (  0.061693)
File.open(file, "r+")   0.020000   0.040000   0.060000 (  0.062378)
File.open(file, "r+")   0.040000   0.010000   0.050000 (  0.060962)
File.open(file, "r+")   0.040000   0.010000   0.050000 (  0.061521)
File.open(file, "r+")   0.040000   0.010000   0.050000 (  0.062309)
File.open(file, "r+")   0.040000   0.010000   0.050000 (  0.062137)
File.open(file, "r+")   0.040000   0.010000   0.050000 (  0.061564)
File.open(file, "r+")   0.050000   0.010000   0.060000 (  0.061476)
File.open(file, "r+")   0.030000   0.020000   0.050000 (  0.062032)
------------------------------------------------ total: 0.520000sec

~/bin/jruby-1.4.1/bin/jruby -v bench/bench_io_open.rb
jruby 1.4.1 (ruby 1.8.7 patchlevel 174) (2010-04-26 ea6db6a) (Java HotSpot(TM) 64-Bit Server VM 1.6.0_20) [amd64-java]
Rehearsal ---------------------------------------------------------
File.open(file, "r+")   1.090000   0.000000   1.090000 (  1.041000)
File.open(file, "r+")   0.832000   0.000000   0.832000 (  0.831000)
File.open(file, "r+")   0.743000   0.000000   0.743000 (  0.743000)
File.open(file, "r+")   0.292000   0.000000   0.292000 (  0.292000)
File.open(file, "r+")   0.339000   0.000000   0.339000 (  0.340000)
File.open(file, "r+")   0.261000   0.000000   0.261000 (  0.261000)
File.open(file, "r+")   0.313000   0.000000   0.313000 (  0.313000)
File.open(file, "r+")   0.248000   0.000000   0.248000 (  0.248000)
File.open(file, "r+")   0.305000   0.000000   0.305000 (  0.305000)
File.open(file, "r+")   0.241000   0.000000   0.241000 (  0.241000)
------------------------------------------------ total: 4.664000sec

~/bin/jruby-1.5.6/bin/jruby -v bench/bench_io_open.rb
jruby 1.5.6 (ruby 1.8.7 patchlevel 249) (2010-12-03 9cf97c3) (Java HotSpot(TM) 64-Bit Server VM 1.6.0_20) [amd64-java]
Rehearsal ---------------------------------------------------------
File.open(file, "r+")   1.159000   0.000000   1.159000 (  1.103000)
File.open(file, "r+")   0.940000   0.000000   0.940000 (  0.939000)
File.open(file, "r+")   0.627000   0.000000   0.627000 (  0.628000)
File.open(file, "r+")   0.409000   0.000000   0.409000 (  0.409000)
File.open(file, "r+")   0.384000   0.000000   0.384000 (  0.384000)
File.open(file, "r+")   0.267000   0.000000   0.267000 (  0.267000)
File.open(file, "r+")   0.306000   0.000000   0.306000 (  0.306000)
File.open(file, "r+")   0.254000   0.000000   0.254000 (  0.254000)
File.open(file, "r+")   0.340000   0.000000   0.340000 (  0.340000)
File.open(file, "r+")   0.254000   0.000000   0.254000 (  0.254000)
------------------------------------------------ total: 4.939999sec

People

  • Assignee:
    Unassigned
    Reporter:
    Charles Oliver Nutter
Vote (0)
Watch (2)

Dates

  • Created:
    Updated: