kernel/core/sampler.rb

   1 # depends on: class.rb
   2
   3 class MethodContext
   4   def normalized_name
   5     if method_module.is_a?(MetaClass)
   6       begin
   7         "#{method_module.attached_instance.inspect}.#{name}"
   8       rescue Object
   9         "#{method_module.attached_instance.class}##{name}"
  10       end
  11     else
  12       if method_module
  13         "#{method_module.name}##{name}"
  14       else
  15         "#{receiver}.#{name}"
  16       end
  17     end
  18   end
  19 end
  20
  21 class Sampler
  22   def initialize(freq=nil)
  23     @frequency = freq
  24     @frequency ||= ENV['PROFILE_FREQ'].to_i
  25     @frequency = 100 if @frequency == 0
  26
  27     @call_graph = ENV['PROFILE_FULL']
  28   end
  29
  30   def start
  31     @start_clock = activate(@frequency)
  32     nil
  33   end
  34
  35   def stop
  36     @results, @last_clock, @interval = terminate()
  37     nil
  38   end
  39
  40   class Call
  41     attr_accessor :slices
  42     attr_accessor :descendants_slices
  43     attr_accessor :name
  44     attr_accessor :parents
  45     attr_accessor :children
  46
  47     def initialize(name)
  48       @name = name
  49       @slices = 0
  50       @descendants_slices = 0
  51
  52       @parents = Hash.new { |h,k| h[k] = 0 }
  53       @children = Hash.new { |h,k| h[k] = 0 }
  54     end
  55
  56     def total_slices
  57       @slices + @descendants_slices
  58     end
  59
  60     def count_parent(call)
  61       if call
  62         @parents[call] += 1
  63         call.children[self] += 1
  64       end
  65     end
  66   end
  67
  68   def display(out=STDOUT)
  69     @total_slices = 0
  70     @calls = Hash.new { |h,k| h[k] = Call.new(k) }
  71
  72     @results.each do |ent|
  73       next unless ent
  74
  75       @total_slices += 1
  76
  77       call = find_call(ent)
  78       call.slices += 1
  79
  80       # skip context unwinding for a primitive
  81       next if ent.kind_of? Fixnum
  82
  83       if @call_graph
  84         # count parents and children
  85         call.count_parent(find_call(ent.sender))
  86
  87         # calc descendants
  88         seen_calls = { call => 1 }
  89
  90         while true
  91           ent = ent.sender
  92           break unless ent
  93
  94           c = find_call(ent)
  95
  96           # unwind to the root, but count each call only once
  97           unless seen_calls[c]
  98             seen_calls[c] = 1
  99
 100             c.descendants_slices += 1
 101           end
 102         end
 103       end
 104     end
 105
 106     out << "Total slices: #{@total_slices}, #{@last_clock - @start_clock} clocks\n\n"
 107     out << "=== FLAT PROFILE ===\n\n"
 108     out << " % time   slices   name\n"
 109
 110     @calls.sort { |a, b| b[1].slices <=> a[1].slices }.each do |name, call|
 111       out.printf " %6.2f %8d    %s\n", percent(call.slices), call.slices, name
 112     end
 113
 114     if @call_graph
 115       out << "\n=== CALL GRAPH ===\n\n"
 116       out << " % time   slices % self   slices  name\n"
 117       @calls.sort { |a, b| b[1].total_slices <=> a[1].total_slices }.each do |name, call|
 118         print_relatives(out, call.parents.sort { |a,b| a[1] <=> b[1] })
 119
 120         out.printf " %6.2f %8d %6.2f %8d   %s\n",
 121           percent(call.total_slices), call.total_slices,
 122           percent(call.slices), call.slices,
 123           name
 124
 125         print_relatives(out, call.children.sort { |a,b| b[1] <=> a[1] })
 126
 127         out << "----------------------------------------------------------------------\n"
 128       end
 129     end
 130     nil
 131   end
 132
 133   def context_name(entry)
 134     # a Fixnum means that a primitive was running
 135     if entry.kind_of? Fixnum
 136       "VM.primitive => #{Rubinius::Primitives[entry]}"
 137     else
 138       entry.normalized_name
 139     end
 140   end
 141
 142   def find_call(entry)
 143     @calls[context_name(entry)]
 144   end
 145
 146   def percent(slices)
 147     100.0 * slices / @total_slices
 148   end
 149
 150   def print_relatives(out, rels)
 151     rels[0,5].each do |rel|
 152       out << "                                       #{rel[0].name} (#{rel[1]})\n"
 153     end
 154   end
 155
 156   class Selectors
 157     def show_stats(range=30)
 158
 159       count = Selector::ALL.size
 160
 161       entries = Selector::ALL.values.map { |s| [s, s.receives] }
 162
 163       entries.delete_if { |e| e.last < 10 }
 164
 165       sort = entries.sort { |a,b| b.last <=> a.last }
 166
 167       puts "\nTotal Selectors: #{count}"
 168       puts "Top #{range}, by receives:"
 169       puts "%-20s| %-20s| %s" % ["name", "receives", "send sites"]
 170       puts "=========================================================="
 171       sort[0,range].each do |entry|
 172         puts "%-20s| %-20d| %d" % [entry.first.name, entry.last, entry.first.send_sites.size]
 173       end
 174     end
 175   end
 176
 177   class SendSites
 178     def show_stats(range=30)
 179       send_sites = Selector::ALL.values.inject([]) { |acc,s| acc.concat(s.send_sites) }
 180       count = send_sites.size
 181
 182       send_sites.delete_if { |e| (e.hits + e.misses) < 10 }
 183
 184       sort = send_sites.sort { |a,b| (b.hits + b.misses) <=> (a.hits + a.misses) }
 185
 186       puts "\nTotal SendSites: #{count}"
 187       puts "Top #{range}, by sends:"
 188       puts "%-32s| %-18s| %-10s| %s" % ["sender", "name", "hits", "misses"]
 189       puts "========================================================================"
 190       sort[0,range].each do |entry|
 191         mod = entry.sender.staticscope.module if entry.sender.staticscope
 192         sender = "#{mod}##{entry.sender.name}"
 193         puts "%-32s| %-18s| %-10d| %d" % [sender, entry.name, entry.hits, entry.misses]
 194       end
 195     end
 196   end
 197 end