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'

require 'perftools'
PerfTools::CpuProfiler.start("/tmp/princess_perf.txt")
# let code execute here
# ...
PerfTools::CpuProfiler.stop

Output:

 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.

puts "\nGARBAGE COLLECTION"
# Not even close to exact, but gives a rough idea of what's being collected
old_objects = ObjectSpace.count_objects.dup
ObjectSpace.garbage_collect
new_objects = ObjectSpace.count_objects
old_objects.each do |k,v|
  diff = v - new_objects[k]
  puts "#{k} #{diff} diff" if diff != 0
end

Output:

 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
end

Output:

 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.

Output:

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?