[ruby-core:19277] Re: performance of C function calls in 1.8 vs 1.9

On Fri, Oct 10, 2008 at 10:30:31AM +0900, Michael Selig wrote:
> I am not too sure what is going on here, because my results are:
>
> ruby1.8 test.rb
>                           user     system      total        real
> Ruby method          11.540000   4.260000  15.800000 ( 16.032414)
> C function            6.380000   1.470000   7.850000 (  7.989895)
>
> ruby1.9 test.rb
>                           user     system      total        real
> Ruby method           6.170000   0.010000   6.180000 (  6.348794)
> C function            5.710000   0.010000   5.720000 (  5.835988)

Interesting.  I wonder why ruby method invocation is so much faster for
you on 1.9.

What options did you pass to configure when you built ruby?

> which looks quite respectable, and is a testament to the improvements 
> made in 1.9 that the Ruby method runs nearly as fast as the C method.
>
> The other important thing is that the bulk of the time in this benchmark  
> is actually executing the for loop itself, not the method you are trying  
> to measure (especially so in 1.9). For example, simply by changing the  
> "for i in 1..N" to "N.times", I get:
>
> ruby1.8 test1.rb
>                           user     system      total        real
> Ruby method           9.720000   3.150000  12.870000 ( 13.071435)
> C function            4.800000   0.690000   5.490000 (  5.576923)
>
> ruby1.9 test1.rb:
>                           user     system      total        real
> Ruby method           2.440000   0.000000   2.440000 (  2.648241)
> C function            1.880000   0.000000   1.880000 (  1.984703)

Also interesting.  Using for instead of #each is usually a significant
improvement, because it doesn't create a new scope (and thus the loop
variable is a local variable instead of a dynamic variable).  Here there
is no loop variable, so #times avoids the assignment altogether.

However, I wonder why for is so much slower on 1.9:

[pbrannan@zem tmp]$ ruby test2.rb
                          user     system      total        real
times                 1.810000   0.000000   1.810000 (  1.824813)
for                   2.150000   0.000000   2.150000 (  2.152103)
each                  1.890000   0.000000   1.890000 (  1.893991)
[pbrannan@zem tmp]$ ruby1.9 test2.rb
                          user     system      total        real
times                 1.540000   0.000000   1.540000 (  1.536957)
for                   7.240000   0.000000   7.240000 (  7.248789)
each                  1.530000   0.000000   1.530000 (  1.540226)
[pbrannan@zem tmp]$ cat test2.rb
require 'benchmark'

N = 10_000_000

Benchmark.bm(20) { |x|
  x.report("times") {
    N.times { }
  }

  x.report("for") {
    for i in 1..N do; end
  }

  x.report("each") {
    (1..N).each { }
  }
}

> So you really should subtract the loop overhead to get a true comparison. 
> One way of doing this is to run the benchmark again with 11 calls to the  
> method inside the loop. If you then subtract the time of the original  
> benchmark from this, you should be left with the time for executing the  
> method 10 * N times.

This does make the results less astonishing:

[pbrannan@zem tmp]$ ruby test3.rb
                          user     system      total        real
Ruby method           4.510000   0.000000   4.510000 (  4.510998)
C function            1.740000   0.000000   1.740000 (  1.746879)
[pbrannan@zem tmp]$ ruby1.9 test3.rb
                          user     system      total        real
Ruby method           1.360000   0.000000   1.360000 (  1.368023)
C function            0.880000   0.010000   0.890000 (  0.882869)
[pbrannan@zem tmp]$ cat test3.rb
require 'foo'
require 'benchmark'

N = 10_000_000

def bar
  return nil
end

puts "#{' '*20}#{Benchmark::CAPTION}"

base_tms = Benchmark.measure("") {
  for i in 1..N do
  end
}

ruby_tms = Benchmark.measure("Ruby method") {
  for i in 1..N do
    bar
  end
}

puts "#{ruby_tms.label.ljust(20)}#{(ruby_tms - base_tms).format}"

c_tms = Benchmark.measure("C function") {
  for i in 1..N do
    foo
  end
}

puts "#{c_tms.label.ljust(20)}#{(c_tms - base_tms).format}"

Paul