Performance question

sorry for the cross-post from RoR, but I actually think this is more
of a ruby question.

I got sidetracked while benchmarking ruby factorial code:

I put all that code into test_fact.rb and ran with:

ruby test_fact.rb
rails runner test_fact.rb #from a fresh rails app
rails runner test_fact.rb #from a mature rails app

here are the respective results:

                  user system total real # ruby
recursive: 8.660000 0.040000 8.700000 ( 8.888191)
iterative: 6.770000 0.030000 6.800000 ( 6.892491)
functional: 6.240000 0.030000 6.270000 ( 6.334801)

                  user system total real # rails_f
recursive: 10.140000 0.070000 10.210000 ( 10.760008)
iterative: 8.750000 0.050000 8.800000 ( 9.050677)
functional: 8.200000 0.040000 8.240000 ( 8.477966)

                  user system total real # rails_m
recursive: 17.400000 0.170000 17.570000 ( 17.792121)
iterative: 15.730000 0.140000 15.870000 ( 16.233311)
functional: 15.450000 0.160000 15.610000 ( 16.245557)

I profiled it as well and the function calls were identical, just
slower.

This feels like a ruby issue that rails brings out in spades, I'm
wondering if anyone here has some insight as to what's going on.

- kevin

Not every runtime we behave the same. You didn't mention which Ruby runtime you are using (MRI 1.8.x, MRI 1.9.x, JRuby 1.?, Rubinius, etc.).

No one can even start to answer your question without knowing the Ruby you are using.

Secondly, the Ruby code examples you pointed to aren't even necessarily testing what you think they are. The "iterative" and "functional" examples are probably a test of how fast the runtime can yield a block, or iterate a range, or any number of things. I wouldn't use that code to extrapolate any larger meaning about runtime performance.

cr

···

On Jan 27, 2011, at 12:55 PM, klochner wrote:

sorry for the cross-post from RoR, but I actually think this is more
of a ruby question.

I got sidetracked while benchmarking ruby factorial code:
Factorial - Rosetta Code

I put all that code into test_fact.rb and ran with:

ruby test_fact.rb
rails runner test_fact.rb #from a fresh rails app
rails runner test_fact.rb #from a mature rails app

here are the respective results:

                 user system total real # ruby
recursive: 8.660000 0.040000 8.700000 ( 8.888191)
iterative: 6.770000 0.030000 6.800000 ( 6.892491)
functional: 6.240000 0.030000 6.270000 ( 6.334801)

                 user system total real # rails_f
recursive: 10.140000 0.070000 10.210000 ( 10.760008)
iterative: 8.750000 0.050000 8.800000 ( 9.050677)
functional: 8.200000 0.040000 8.240000 ( 8.477966)

                 user system total real # rails_m
recursive: 17.400000 0.170000 17.570000 ( 17.792121)
iterative: 15.730000 0.140000 15.870000 ( 16.233311)
functional: 15.450000 0.160000 15.610000 ( 16.245557)

I profiled it as well and the function calls were identical, just
slower.

This feels like a ruby issue that rails brings out in spades, I'm
wondering if anyone here has some insight as to what's going on.

Not every runtime we behave the same. You didn't mention which Ruby runtime you are using

No one can even start to answer your question without knowing the Ruby you are using.

Ruby Enterprise Edition - ruby 1.8.7 (2010-04-19 patchlevel 253)

Secondly, the Ruby code examples you pointed to aren't even necessarily testing what you think they are.

Ignoring the between-test comparisons, there is clearly a slowdown
after loading rails. My *guess* is that it has to do with the size of
ObjectSpace causing a slowdown in function lookup, but again, I was
hoping someone here would have a more concrete understanding.

···

On Jan 27, 11:37 am, Chuck Remes <cremes.devl...@mac.com> wrote:

Garbage collection.

REE has some optimizations to how it manages GC, but the fundamentals
are still the same for any 1.8.x. When a garbage collection cycle
starts, everything else stops. While it is running Ruby has to walk
through it's heaps, examining everything that looks like an object
that it can find.

The more stuff that is in there, the longer this takes. If there is a
lot of stuff in there, the impact can be significant.

You can readily see this yourself within an irb session.

irb(main):001:0> require 'benchmark'
=> true
irb(main):002:0> junk =
=>
irb(main):003:0> Benchmark.bm {|bm| bm.report {1000.times {GC.start}}}
      user system total real
  0.780000 0.000000 0.780000 ( 0.977218)
=> true
irb(main):004:0> Benchmark.bm {|bm| bm.report {1000.times {GC.start}}}
      user system total real
  0.780000 0.000000 0.780000 ( 0.796975)
=> true
irb(main):005:0> 10000.times {|n| junk << n.to_s}
=> 10000
irb(main):006:0> Benchmark.bm {|bm| bm.report {1000.times {GC.start}}}
      user system total real
  1.120000 0.000000 1.120000 ( 1.266903)
=> true
irb(main):007:0> 20000.times {|n| junk << n.to_s}
=> 20000
irb(main):008:0> Benchmark.bm {|bm| bm.report {1000.times {GC.start}}}
      user system total real
  1.900000 0.020000 1.920000 ( 2.125608)
=> true
irb(main):009:0> 40000.times {|n| junk << n.to_s}
=> 40000
irb(main):010:0> Benchmark.bm {|bm| bm.report {1000.times {GC.start}}}
      user system total real
  2.360000 0.010000 2.370000 ( 2.441193)
=> true
irb(main):011:0> 1000000.times {|n| junk << n.to_s}
=> 1000000
irb(main):012:0> Benchmark.bm {|bm| bm.report {1000.times {GC.start}}}
      user system total real
32.970000 0.250000 33.220000 ( 36.181590)
=> true

Kirk Haines
Developer
Engine Yard

···

On Thu, Jan 27, 2011 at 1:10 PM, klochner <klochner@gmail.com> wrote:

Ignoring the between-test comparisons, there is clearly a slowdown
after loading rails. My *guess* is that it has to do with the size of
ObjectSpace causing a slowdown in function lookup, but again, I was
hoping someone here would have a more concrete understanding.

I totally agree with you Kirk...but...

I just want to add that not all Ruby GC impls are equal. While lots
of garbage will have an effect on any GC, some GC's just do a better
job. JRuby GC times are generally a smaller percentage of execution
than the amount of time MRI spends collecting. JRuby also allows
parallel and concurrent collection (JVM allows a variety of plugable
GCs) which reduces GC pauses by pushing collection onto separate
processor cores. Even without using the parallel or concurrent
collectors the percentage pauses are much shorter mostly due to
generational collection.

-Tom

···

On Fri, Jan 28, 2011 at 8:59 AM, Kirk Haines <wyhaines@gmail.com> wrote:

On Thu, Jan 27, 2011 at 1:10 PM, klochner <klochner@gmail.com> wrote:

Ignoring the between-test comparisons, there is clearly a slowdown
after loading rails. My *guess* is that it has to do with the size of
ObjectSpace causing a slowdown in function lookup, but again, I was
hoping someone here would have a more concrete understanding.

Garbage collection.

REE has some optimizations to how it manages GC, but the fundamentals
are still the same for any 1.8.x. When a garbage collection cycle
starts, everything else stops. While it is running Ruby has to walk
through it's heaps, examining everything that looks like an object
that it can find.

The more stuff that is in there, the longer this takes. If there is a
lot of stuff in there, the impact can be significant.

--
blog: http://blog.enebo.com twitter: tom_enebo
mail: tom.enebo@gmail.com

Sorry Kirk you were probably specifically talking about Ruby impls
based on MRI 1.8.x derived codebases and not in the more general
sense. My info may still be interesting to someone, but it was
specifically about JRuby and how it can handle GC'ing workloads.

-Tom

···

On Fri, Jan 28, 2011 at 11:10 AM, Thomas E Enebo <tom.enebo@gmail.com> wrote:

On Fri, Jan 28, 2011 at 8:59 AM, Kirk Haines <wyhaines@gmail.com> wrote:

On Thu, Jan 27, 2011 at 1:10 PM, klochner <klochner@gmail.com> wrote:

Ignoring the between-test comparisons, there is clearly a slowdown
after loading rails. My *guess* is that it has to do with the size of
ObjectSpace causing a slowdown in function lookup, but again, I was
hoping someone here would have a more concrete understanding.

Garbage collection.

REE has some optimizations to how it manages GC, but the fundamentals
are still the same for any 1.8.x. When a garbage collection cycle
starts, everything else stops. While it is running Ruby has to walk
through it's heaps, examining everything that looks like an object
that it can find.

The more stuff that is in there, the longer this takes. If there is a
lot of stuff in there, the impact can be significant.

I totally agree with you Kirk...but...

I just want to add that not all Ruby GC impls are equal. While lots
of garbage will have an effect on any GC, some GC's just do a better
job. JRuby GC times are generally a smaller percentage of execution
than the amount of time MRI spends collecting. JRuby also allows
parallel and concurrent collection (JVM allows a variety of plugable
GCs) which reduces GC pauses by pushing collection onto separate
processor cores. Even without using the parallel or concurrent
collectors the percentage pauses are much shorter mostly due to
generational collection.

-Tom

--
blog: http://blog.enebo.com twitter: tom_enebo
mail: tom.enebo@gmail.com

--
blog: http://blog.enebo.com twitter: tom_enebo
mail: tom.enebo@gmail.com

Yeah, I should have worded it more specifically. I was talking about
MRI based 1.8.x's. :slight_smile:

Kirk Haines

···

On Fri, Jan 28, 2011 at 10:17 AM, Thomas E Enebo <tom.enebo@gmail.com> wrote:

Sorry Kirk you were probably specifically talking about Ruby impls
based on MRI 1.8.x derived codebases and not in the more general
sense. My info may still be interesting to someone, but it was
specifically about JRuby and how it can handle GC'ing workloads.

Thanks a ton guys, this is all great info.

- kevin

···

On Jan 28, 9:27 am, Kirk Haines <wyhai...@gmail.com> wrote:

On Fri, Jan 28, 2011 at 10:17 AM, Thomas E Enebo <tom.en...@gmail.com> wrote:

> Sorry Kirk you were probably specifically talking about Ruby impls
> based on MRI 1.8.x derived codebases and not in the more general
> sense. My info may still be interesting to someone, but it was
> specifically about JRuby and how it can handle GC'ing workloads.

Yeah, I should have worded it more specifically. I was talking about
MRI based 1.8.x's. :slight_smile:

Kirk Haines