3 Comments

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'
PerfTools::CpuProfiler.start("/tmp/princess_perf.txt")
# let code execute here
PerfTools::CpuProfiler.stop
Output:
<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.

<code class="language-ruby">

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:

<code class="language-txt">

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.

<code class="language-ruby">

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 %8sn", event, file, line, id, classname) if classname  Array && id  :initialize
}
else
set_trace_func nil
end
end

Output:

<code class="language-txt">

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:

<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: 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?