gc_stress.rb

# Adapted from a script by Evan Phoenix
require 'benchmark'

GC::Profiler.enable

class Simple
  attr_accessor :next
end

top = Simple.new

puts Benchmark.measure {
  outer = 10
  total = 100000
  per = 100

  outer.times do
    total.times do
      per.times { Simple.new }
      s = Simple.new
      top.next = s
      top = s
    end
  end
}

puts "GC time: #{GC::Profiler.total_time}s"

gistfile1.txt

system ~/projects/gc_tests $ rvm 1.9.3 do ruby -v gc_stress.rb 
ruby 1.9.3p0 (2011-10-30 revision 33570) [x86_64-darwin10.8.0]
 20.820000   0.240000  21.060000 ( 21.070793)
GC time: 2.29012300000049s

system ~/projects/gc_tests $ rvm ruby-head do ruby -v gc_stress.rb 
ruby 2.0.0dev (2012-02-19 trunk 34699) [x86_64-darwin10.8.0]
 21.740000   0.250000  21.990000 ( 22.002499)
GC time: 3.156919999999449s

system ~/projects/gc_tests $ (pickjdk 1 ; jruby -v gc_stress.rb)
New JDK: 1.6.0.jdk
jruby 1.7.0.dev (ruby-1.9.3-p28) (2012-02-19 348601d) (Java HotSpot(TM) 64-Bit Server VM 1.6.0_29) [darwin-x86_64-java]
  8.655000   0.000000   8.655000 (  8.655000)
GC time: 0.223s

system ~/projects/gc_tests $ (pickjdk 2 ; jruby -v gc_stress.rb)
New JDK: 1.6.0_30-b12-409.jdk
jruby 1.7.0.dev (ruby-1.9.3-p28) (2012-02-19 348601d) (Java HotSpot(TM) 64-Bit Server VM 1.6.0_30) [darwin-x86_64-java]
  9.354000   0.000000   9.354000 (  9.354000)
GC time: 0.217s

sad times :(

Development $ rvm 1.9.3 do ruby -v gc_stress.rb
ruby 1.9.3p0 (2011-10-30 revision 33570) [x86_64-darwin10.8.0]
 22.010000   0.260000  22.270000 ( 22.265166)
GC time: 2.361137000000679s
Development $ rvm ruby-head do ruby -v gc_stress.rb
ruby 2.0.0dev (2012-02-19 trunk 34699) [x86_64-darwin10.8.0]
 23.190000   0.260000  23.450000 ( 23.451425)
GC time: 3.2757459999999425s

This is all on a MBP running OSX 10.6.8 with an i7 2ghz and 8GB DDR3 RAM.

Is there any way to get timings for 1.9.2 and 1.8.7? This is a disturbing trend.

Here is 2 more. GC::Profiler didn't exist in 1.8.7. Since it's in C, is there another alternative that would benchmark the same for that one?

Development $ ruby -v gc_stress.rb
ruby 1.8.7 (2010-01-10 patchlevel 249) [universal-darwin10.0]
gc_stress.rb:4: uninitialized constant GC::Profiler (NameError)
Development $ rvm ruby-1.9.2-p180 do ruby -v gc_stress.rb
ruby 1.9.2p180 (2011-02-18 revision 30909) [x86_64-darwin10.8.0]
 20.430000   0.020000  20.450000 ( 20.428400)
GC time: 1.7632729999999577s
Development $ rvm ruby-1.9.2-p290 do ruby -v gc_stress.rb
ruby 1.9.2p290 (2011-07-09 revision 32553) [x86_64-darwin10.8.0]
 20.180000   0.030000  20.210000 ( 20.192023)
GC time: 1.7412599999998972s

I don't know what tools exist for 1.8.7, but I would guess there might be something in REE?

So...if your results are to be believed, GC is taking more and more time in each major release of Ruby. I hope some of that is being shunted to GC threads (or something), but given that the overall times go up too...it seems like things are moving in the wrong direction.