performance question

[klochner]

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:
http://rosettacode.org/wiki/Factorial#Ruby

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

 

[Chuck Remes]

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:
http://rosettacode.org/wiki/Factorial#Ruby

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


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 (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

 

[klochner]

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.

 

[Kirk Haines]

Ignoring the between-test comparisons, there is clearly a slowdown
after loading rails. =A0My *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.

You can readily see this yourself within an irb session.

irb(main):001:0> require 'benchmark'
=3D> true
irb(main):002:0> junk =3D []
=3D> []
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)
=3D> 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)
=3D> true
irb(main):005:0> 10000.times {|n| junk << n.to_s}
=3D> 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)
=3D> true
irb(main):007:0> 20000.times {|n| junk << n.to_s}
=3D> 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)
=3D> true
irb(main):009:0> 40000.times {|n| junk << n.to_s}
=3D> 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)
=3D> true
irb(main):011:0> 1000000.times {|n| junk << n.to_s}
=3D> 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)
=3D> true


Kirk Haines
Developer
Engine Yard

 

[Thomas E Enebo]

Garbage collection.

REE has some optimizations to how it manages GC, but the fundamentals
are still the same for any 1.8.x. =A0When 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

--=20
blog: http://blog.enebo.com=A0 =A0 =A0=A0 twitter: tom_enebo
mail: (e-mail address removed)

 

[Thomas E Enebo]

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

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

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

-Tom

--=20
blog: http://blog.enebo.com=A0 =A0 =A0=A0 twitter: tom_enebo
mail: (e-mail address removed)

 

[Kirk Haines]

Sorry Kirk you were probably specifically talking about Ruby impls
based on MRI 1.8.x =A0derived codebases and not in the more general
sense. =A0My 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.


Kirk Haines

 

[klochner]

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

Kirk Haines

Thanks a ton guys, this is all great info.

- kevin