kernel/core/sampler.rb

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