Lunch Break Debugging

I spend quite a few of my lunch breaks playing around with some hobby game development in Ruby. I noticed that the game was running poorly. Eventually, I found that I had been needlessly creating many small Arrays in a very tight loop in my collision detection code. As with many things in life, the journey is much more interesting than the destination. Here’s how an hour of debugging resulted in an easy performance gain:

I used perftools.rb to find what code was running slowly.

TIP: for 1.9 add this to Gemfile:
gem 'perftools.rb', :git => 'git://github.com/bearded/perftools.rb.git', :branch => 'perftools-1.8'

<code class="language-ruby">
require 'perftools'
 # let code execute here


<code class="language-txt">
shawn42@bits ~/code/games/princess_game (git::master)✗ $ be pprof.rb --text /tmp/princess_perf.txt
 Using local file /Users/shawn42/.rvm/rubies/ruby-1.9.3-p0/bin/ruby.
 Using local file /tmp/princess_perf.txt.
 Total: 225 samples
       80  35.6%  35.6%       80  35.6% garbage_collector
       48  21.3%  56.9%      145  64.4% Gosu::Window#show_internal
        9   4.0%  60.9%       10   4.4% Hash#[]=
        7   3.1%  64.0%       24  10.7% GraphicalActorView#draw
        6   2.7%  66.7%       11   4.9% Arbiter#collide_circle_circle?

The results show that 36% of time is being spent in the garbage collector. Perftools.rb doesn’t have any heap inspection tools and I’m using ruby 1.9; ObjectSpace.count_objects seemed like a good place to start.


  1. Not even close to exact, but gives a rough idea of what’s being collected
    old_objects = ObjectSpace.count_objects.dup
    new_objects = ObjectSpace.count_objects

old_objects.each do |k,v| diff = v – new_objects[k] puts “#{k} #{diff} diff” if diff != 0


GARBAGE COLLECTION FREE -22353 diff T_OBJECT 6 diff T_FLOAT 10806 diff T_STRING 521 diff T_ARRAY 9263 diff <— a lot of arrays being collected? T_HASH 312 diff T_STRUCT 862 diff T_DATA 563 diff T_NODE 20 diff

I saw a lot of arrays constantly being collected; but where were they coming from?

I decided to use set_trace_func to see where all those temporary arrays were instantiated. Unfortunately I found that using the [ ] syntax for a new array does not invoke Array#initialize. After changing all my array calls to Array.new, I was ready for some set_trace_func action.

def toggle_trace do_trace = !do_trace if @do_trace set_trace_func proc { |event, file, line, id, binding, classname| printf(“8s %s:-2d %10s %8s\n”, event, file, line, id, classname) if classname Array && id :initialize } else set_trace_func nil end


c-call /Users/shawn42/.rvm/gems/ruby-1.9.3-p0/gems/gamebox-0.3.3/lib/gamebox/spatial_hash.rb:139 initialize Array c-return /Users/shawn42/.rvm/gems/ruby-1.9.3-p0/gems/gamebox-0.3.3/lib/gamebox/spatial_hash.rb:139 initialize Array c-call /Users/shawn42/.rvm/gems/ruby-1.9.3-p0/gems/gamebox-0.3.3/lib/gamebox/spatial_hash.rb:139 initialize Array c-return /Users/shawn42/.rvm/gems/ruby-1.9.3-p0/gems/gamebox-0.3.3/lib/gamebox/spatial_hash.rb:139 initialize Array c-call /Users/shawn42/.rvm/gems/ruby-1.9.3-p0/gems/gamebox-0.3.3/lib/gamebox/spatial_hash.rb:139 initialize Array

set_trace_func told me the file and lines to investigate. It turned out that I was returning arrays from methods just to turn around and splat them back out elsewhere. After a quick refactor, my garbage collection is down from 36% of my CPU time to 15%. Not bad for a lunchtime endeavor.


shawn42@bits ~/code/games/princess_game (git::master)✗ $ be pprof.rb —text /tmp/princess_perf.txt
Using local file /Users/shawn42/.rvm/rubies/ruby-1.9.3-p0/bin/ruby.
Using local file /tmp/princess_perf.txt.
Total: 313 samples 106 33.9% 33.9% 266 85.0% Gosu::Window#show_internal 47 15.0% 48.9% 47 15.0% garbage_collector 25 8.0% 56.9% 40 12.8% Range#each 19 6.1% 62.9% 42 13.4% GraphicalActorView#draw 7 2.2% 65.2% 8 2.6% Hash#[]= 6 1.9% 67.1% 10 3.2% Arbiter#collide_circle_circle?