Ruby profiler results interpretation

Question

I'm using a ruby-prof gem to profile my code.

And results looks like this:

 %self     total     self     wait    child    calls  name
 50.56     31.06    23.45     0.00     7.62   234593  Array#each
 14.29      6.62     6.62     0.00     0.00   562480  Array#-
 13.63      6.32     6.32     0.00     0.00   157816  Array#|
 11.20      5.20     5.20     0.00     0.00  6210903  Hash#default
  2.44     46.36     1.13     0.00    46.36    78909  Analyzer#process
  2.02     46.36     0.94     0.00    46.36    78908  Analyzer#try
  1.70      0.79     0.79     0.00     0.00   562481  UnboundMethod#bind
  1.53      7.34     0.71     0.00     6.62   562480  Method#call
  1.18      0.55     0.55     0.00     0.00   562480  Kernel#instance_variable_defined?
  0.76     46.36     0.35     0.00    46.36     6250  Array#combination
  0.37      0.17     0.17     0.00     0.00   105763  Array#concat
  0.25     25.19     0.12     0.00    25.07    77842  Enumerable#group_by
  0.02     46.36     0.01     0.00    46.36     3125  Enumerator#each
  0.02      0.01     0.01     0.00     0.00    78908  Array#empty?
...

I'm sure that my code does not tries to access non-existing keys in some of the Hashes. The question is - what Hash#default might mean?

And here is a piece of code:

class Analyzer

  def process(level, hypo_right, hypo_wrong)
    if portion = @portions[level]
      selections = @selections[level] - hypo_wrong
      master_size = selections.size
      selections -= hypo_right
      new_portion = portion + selections.size - master_size
      if new_portion > selections.size || new_portion < 0
        return
      elsif new_portion == 0
        try(level, hypo_right, [], hypo_wrong, selections)
      else
        selections.combination(new_portion).each do |hypo_right2|
          try(level, hypo_right, hypo_right2, hypo_wrong, (selections - hypo_right2))
        end
      end
    else
      puts hypo_right.inspect
    end
  end

  def try(level, right, right2, wrong, wrong2)
    local_right = right | right2
    local_wrong = wrong | wrong2
    right2.each { |r| local_wrong.concat(@siblings[r]) }

    unless wrong2.empty?
      grouped_wrong = local_wrong.group_by{|e| @vars[e] }
      wrong2.each do |w|
        qid = @vars[w]
        if grouped_wrong[qid].size == @limits[qid]
          local_right << (@q_hash[qid] - grouped_wrong[qid])[0]
        end
      end
    end
    process(level + 1, local_right, local_wrong)
  end

  def start
    process(0, [], [])
  end
end

@selections, @portions are Arrays; @q_hash, @siblings, @limits and @vars are Hashes.

Isn't `group_by` that is invoking `Hash#default`? Which ruby are you using? — riffraff, Dec 05 '11 at 17:07
riffraff, Probably, you are right. 6210903/77842 = 79, this might be an average grouped_wrong size. — taro, Dec 05 '11 at 17:12
If you've got the time, you may want to try the different printer options, such as `--printer=call_stack` and `--printer=graph_html` (although they can't be cut and pasted into a SO question). It may help you work out what method was responsible for `Hash#default` taking so much time. — Andrew Grimm, Dec 05 '11 at 22:28

score 0 · Answer 1 · answered Dec 05 '11 at 18:05

Thanks to riffraff, found answer:

require 'ruby-prof'
h = (0..9).inject({}) {|h, x| h[x] = (x+97).chr;h }
a = (0..1000000).collect { rand(100) }
RubyProf.start
g = a.group_by {|x| h[x/10] }
RubyProf::FlatPrinter.new(RubyProf.stop).print(STDOUT)


Thread ID: 17188993880
Total: 1.210938

 %self     total     self     wait    child    calls  name
100.00      1.21     1.21     0.00     0.00        1  Array#each
  0.00      0.00     0.00     0.00     0.00       10  Hash#default
  0.00      1.21     0.00     0.00     1.21        1  Enumerable#group_by
  0.00      1.21     0.00     0.00     1.21        1  Object#irb_binding

Ruby profiler results interpretation

1 Answers1