Why is Ruby irb iteration so slow?

Question

I was playing around with Ruby's Benchmark class in irb and I noticed that Ruby was noticeably slower when iterating.

I made a simple test without using Benchmark or Profiler__ class (I thought maybe it was slowing it down).

def average_test
    total_time = 0
    time = 0
    TESTS.times do |count|
        time = test
        total_time = total_time + time
        yield count, time
    end
    average = total_time / TESTS
    yield 'average', average
end
def test
    x = 0
    start_time = Time.now
    for i in 1..ITERATIONS
        x = x + 1
    end
    end_time = Time.now
    time = end_time - start_time
end
ITERATIONS = 10_000_000
TESTS = 20
# create results file
results = File.new('results.txt', 'w')
# start test
average_test {|count, time| results.print "Test #{count}: #{time}"}
results.close

Here are the results after running it in irb. (in seconds, sorry)

Test 0: 2.390647, Test 1: 2.343761, Test 2: 2.312554, Test 3: 2.566792, Test 4: 2.665193, Test 5: 2.537908, Test 6: 2.643086, Test 7: 2.534492, Test 8: 2.589034, Test 9: 2.390633, Test 10: 2.539533, Test 11: 2.385508, Test 12: 2.49659, Test 13: 2.498958, Test 14: 2.527309, Test 15: 2.462983, Test 16: 2.504546, Test 17: 2.570159, Test 18: 2.371447, Test 19: 2.330072,

Test average: 2.48306025(s), 2483(ms)

I also made the same test in JavaScript, just to compare speeds.

function test() {
    var start = Date.now();
    var x = 0;
    for (var i = 0; i < ITERATIONS; i++) {
        x = x + 1;
    }
    var end = Date.now();
    var dt = end - start;
    return dt;
}
function averageTest() {
    var total = 0;
    for (var i = 0; i < TESTS; i++) {
        var time = test();
        total = total + time;
        console.log('Test ' + i + ': ', time);
    }
    var avg = total / TESTS;
    console.log('Average: ', avg);
    return avg;
}
var ITERATIONS = 10000000;
var TESTS = 20;
// start test
var avgTime = averageTest(); // results

Here are the results for the JavaScript code run in Chrome. (in milliseconds)

Test 0: 41, Test 1: 44, Test 2: 41, Test 3: 48, Test 4: 46, Test 5: 48, Test 6: 49, Test 7: 47, Test 8: 46, Test 9: 50, Test 10: 41, Test 11: 41, Test 12: 47, Test 13: 54, Test 14: 55, Test 15: 57, Test 16: 35, Test 17: 50, Test 18: 47, Test 19: 49,

Average: 46.8(ms), 0.0468(s)

Ruby had an average of 2483 ms compared to JavaScript's 46.8 ms.

Why is there such a huge difference? Is it because Ruby's operators are method calls and methods calls are slow or something?

I feel like I'm doing something really wrong. Thanks.

Answer 1

I tried your benchmark with a couple of different Ruby implementations, and I got wildly differing results. This seems to confirm my suspicions that your benchmark is not measuring what you think it does. As I mentioned in my comment above: when writing benchmarks, you should always read the generated native machine code to verify that it actually measures what you think it does.

For example, there is a benchmark in the YARV benchmark suite that is supposed to measure message dispatch performance, however, on Rubinius, the message dispatch gets optimized away completely, so the only thing that is actually executed is incrementing the counter variable for the benchmark loop. Essentially, it tells you the frequency of your CPU, nothing more.

ruby 2.3.0dev (2015-08-08 trunk 51510) [x86_64-darwin14]

Here's a current snapshop of YARV:

Test  0: 0.720945
Test  1: 0.733733
Test  2: 0.722778
Test  3: 0.734074
Test  4: 0.774355
Test  5: 0.773379
Test  6: 0.751547
Test  7: 0.708566
Test  8: 0.724959
Test  9: 0.730899
Test 10: 0.725978
Test 11: 0.712902
Test 12: 0.747069
Test 13: 0.737792
Test 14: 0.736885
Test 15: 0.751422
Test 16: 0.718943
Test 17: 0.760094
Test 18: 0.746343
Test 19: 0.764731
Average: 0.738870

As you can see, the performance is very consistent across runs, and it seems to be in line with the other results posted in the comments.

rubinius 2.5.8 (2.1.0 bef51ae3 2015-08-09 3.5.1 JI) [x86_64-darwin14.4.0]

Here's the current release of Rubinius:

Test  0: 1.159465
Test  1: 1.063721
Test  2: 0.516513
Test  3: 0.515016
Test  4: 0.553987
Test  5: 0.544286
Test  6: 0.567737
Test  7: 0.563350
Test  8: 0.517581
Test  9: 0.501865
Test 10: 0.503399
Test 11: 0.512046
Test 12: 0.487296
Test 13: 0.533193
Test 14: 0.533217
Test 15: 0.511648
Test 16: 0.535847
Test 17: 0.490049
Test 18: 0.539681
Test 19: 0.551324
Average: 0.585061

As you can see, the compiler kicks in sometime during the second run, after which it gets twice as fast, significantly faster than YARV, whereas during the first two runs, it is significantly slower than YARV.

jruby 9.0.0.0-SNAPSHOT (2.2.2) 2015-07-23 89c1348 Java HotSpot(TM) 64-Bit Server VM 25.5-b02 on 1.8.0_05-b13 +jit [darwin-x86_64]

This is a current snapshot of JRuby running on a slightly old release (a couple of months) of HotSpot:

Test  0: 1.169000
Test  1: 0.805000
Test  2: 0.772000
Test  3: 0.755000
Test  4: 0.777000
Test  5: 0.749000
Test  6: 0.751000
Test  7: 0.694000
Test  8: 0.696000
Test  9: 0.708000
Test 10: 0.691000
Test 11: 0.745000
Test 12: 0.752000
Test 13: 0.755000
Test 14: 0.707000
Test 15: 0.744000
Test 16: 0.674000
Test 17: 0.710000
Test 18: 0.733000
Test 19: 0.706000
Average: 0.754650

Again, the compiler seems to kick in somewhere between runs 1 and 2, after which it performs comparably with YARV.

jruby 9.0.1.0-SNAPSHOT (2.2.2) 2015-08-09 2939c73 OpenJDK 64-Bit Server VM 25.40-b25-internal-graal-0.7 on 1.8.0-internal-b128 +jit [darwin-x86_64]

This is a slightly newer snapshot of JRuby running on a future version of HotSpot:

Test  0: 0.815000
Test  1: 0.693000
Test  2: 0.634000
Test  3: 0.615000
Test  4: 0.599000
Test  5: 0.616000
Test  6: 0.623000
Test  7: 0.611000
Test  8: 0.604000
Test  9: 0.598000
Test 10: 0.628000
Test 11: 0.627000
Test 12: 0.601000
Test 13: 0.646000
Test 14: 0.675000
Test 15: 0.611000
Test 16: 0.684000
Test 17: 0.689000
Test 18: 0.626000
Test 19: 0.639000
Average: 0.641700

Again, we see the pattern of it getting faster during the first two runs, after which it settles somewhere in between slightly faster than YARV and the other JRuby and slightly slower than Rubinius.

jruby 9.0.1.0-SNAPSHOT (2.2.2) 2015-08-09 2939c73 OpenJDK 64-Bit Server VM 25.40-b25-internal-graal-0.7 on 1.8.0-internal-b128 +jit [darwin-x86_64]

This is my favorite: JRuby+Truffle with Truffle enabled and running on a Graal-enabled JVM:

Test  0:  6.226000
Test  1:  5.696000
Test  2:  1.836000
Test  3:  0.057000
Test  4:  0.111000
Test  5:  0.103000
Test  6:  0.082000
Test  7:  0.146000
Test  8:  0.089000
Test  9:  0.077000
Test 10:  0.076000
Test 11:  0.082000
Test 12:  0.072000
Test 13:  0.104000
Test 14:  0.124000
Test 15:  0.084000
Test 16:  0.080000
Test 17:  0.118000
Test 18:  0.087000
Test 19:  0.070000
Average:  0.766000

Truffle seems to need a significant amount of ramp-up time, with the first three runs being abysmally slow, but then it dramatically picks up speed, leaving everything else in the dust by a factor 5-10.

Note: this is not 100% fair, since JRuby+Truffle does not yet support the full Ruby language.

Also note: this shows that simply taking the average over all runs is grossly misleading, since JRuby+Truffle comes out to the same average as YARV and JRuby, but actually has 7 times faster steady-state performance. The difference between the slowest run (run 1 of JRuby+Truffle) and the fastest run (run 20 also of JRuby+Truffle) is a wopping 100x.

Note #3: notice how the JRuby numbers all end with 000? That's because JRuby does not get easy access to the underlying OS's microsecond timer through the JVM and thus has to be content with milliseconds. It doesn't matter too much in this particular benchmark, but for faster benchmarks it can skew the results significantly. That's just another thing you have to consider when designing benchmarks.

Why is there such a huge difference? Is it because Ruby's operators are method calls and methods calls are slow or something?

I don't think so. On YARV, Fixnum#+ isn't even a method call, it is optimized to a static built-in operator. It essentially performs an in-register primitive integer add operation in the CPU. As fast as it gets.

YARV only falls back to treating it as a method call when you monkey-patch Fixnum.

Rubinius probably can optimize the method calls away, although I didn't check.

I feel like I'm doing something really wrong.

Probably, your benchmark doesn't measure what you think it does. In particular, I believe that on implementations with sophisticated optimizing compilers, the iteration part of your iteration benchmark may get optimized away.

Actually, I noticed a significant difference between your JavaScript and Ruby benchmarks: in JavaScript, you are using a primitive for loop, in Ruby, you are using Range#each (for … in just gets translated to each). If I switch both the Ruby and the JavaScript benchmarks over to an identical while loop, I get for the Ruby version: 223ms for YARV, 56ms for Rubinius, 28ms for JRuby, and 33ms for JRuby+Truffle. For the JS version: 30ms for Squirrelfish Extreme / Nitro (Safari), and 16ms for V8/Crankshaft (Chrome).

Or, in other words: if you measure the same thing, they end up equally fast ;-) (Well, except for YARV, which however is well-known to be slow anyways.)

So, as it turns out, the difference between Ruby and JavaScript was that in JS you weren't iterating anything, you were just incrementing a number, whereas in Ruby, you were actually iterating a datastructure (namely, a Range). Remove the iteration from Ruby, and it is as fast as JavaScript.

I have created two benchmark scripts that now hopefully roughly measure the same thing:

#!/usr/bin/env ruby

ITERATIONS = 10_000_000
TESTS = 20
WARMUP = 3
TOTALRUNS = TESTS + WARMUP
RESULTS = []

run = -1

while (run += 1) < TOTALRUNS
  i = -1
  starttime = Time.now

  while (i += 1) < ITERATIONS do end

  endtime = Time.now
  RESULTS[run] = (endtime - starttime) * 1000
end

puts RESULTS.drop(WARMUP).reduce(:+) / TESTS

"use strict";

const ITERATIONS = 10000000;
const TESTS = 20;
const WARMUP = 3;
const TOTALRUNS = TESTS + WARMUP;
const RESULTS = [];

let run = -1;

while (++run < TOTALRUNS) {
    let i = -1;
    const STARTTIME = Date.now();

    while (++i < ITERATIONS);

    const ENDTIME = Date.now();
    RESULTS[run] = ENDTIME - STARTTIME;
}

alert(RESULTS.slice(WARMUP).reduce((acc, el) => acc + el) / TESTS);

You'll notice I increased the number of iterations, I doubled the number of test runs, and I introduced a number of warmup runs that are not included in the computation of the result. I also tried to make the two snippets as similar as possible. (Note: you might have to remove some of the ES6isms to get it to run on your browser. E.g. my version of Safari doesn't like fat arrow function literals.)

The results are:

• Ruby
  • YARV: 223.2498ms
  • JRuby: 358.45ms
  • Rubinius: 477.49485ms
  • JRuby+Truffle+Graal: 26.4ms
• JavaScript
  • Nitro: 3827.3ms
  • V8: 6839ms

I'm a bit baffled, to be honest. Now, Nitro is ahead of V8, all Ruby implementations are 10x faster than JavaScript, JRuby+Truffle+Graal is again 10x faster than the rest of Ruby, thus making it 100x faster than JavaScript.

I guess what this really tells us is that the benchmark is meaningless :-D