1# Profile provides a way to Profile your Ruby application. 2# 3# Profiling your program is a way of determining which methods are called and 4# how long each method takes to complete. This way you can detect which 5# methods are possible bottlenecks. 6# 7# Profiling your program will slow down your execution time considerably, 8# so activate it only when you need it. Don't confuse benchmarking with 9# profiling. 10# 11# There are two ways to activate Profiling: 12# 13# == Command line 14# 15# Run your Ruby script with <code>-rprofile</code>: 16# 17# ruby -rprofile example.rb 18# 19# If you're profiling an executable in your <code>$PATH</code> you can use 20# <code>ruby -S</code>: 21# 22# ruby -rprofile -S some_executable 23# 24# == From code 25# 26# Just require 'profile': 27# 28# require 'profile' 29# 30# def slow_method 31# 5000.times do 32# 9999999999999999*999999999 33# end 34# end 35# 36# def fast_method 37# 5000.times do 38# 9999999999999999+999999999 39# end 40# end 41# 42# slow_method 43# fast_method 44# 45# The output in both cases is a report when the execution is over: 46# 47# ruby -rprofile example.rb 48# 49# % cumulative self self total 50# time seconds seconds calls ms/call ms/call name 51# 68.42 0.13 0.13 2 65.00 95.00 Integer#times 52# 15.79 0.16 0.03 5000 0.01 0.01 Fixnum#* 53# 15.79 0.19 0.03 5000 0.01 0.01 Fixnum#+ 54# 0.00 0.19 0.00 2 0.00 0.00 IO#set_encoding 55# 0.00 0.19 0.00 1 0.00 100.00 Object#slow_method 56# 0.00 0.19 0.00 2 0.00 0.00 Module#method_added 57# 0.00 0.19 0.00 1 0.00 90.00 Object#fast_method 58# 0.00 0.19 0.00 1 0.00 190.00 #toplevel 59 60module Profiler__ 61 class Wrapper < Struct.new(:defined_class, :method_id, :hash) # :nodoc: 62 private :defined_class=, :method_id=, :hash= 63 64 def initialize(klass, mid) 65 super(klass, mid, nil) 66 self.hash = Struct.instance_method(:hash).bind(self).call 67 end 68 69 def to_s 70 "#{defined_class.inspect}#".sub(/\A\#<Class:(.*)>#\z/, '\1.') << method_id.to_s 71 end 72 alias inspect to_s 73 end 74 75 # internal values 76 @@start = nil # the start time that profiling began 77 @@stacks = nil # the map of stacks keyed by thread 78 @@maps = nil # the map of call data keyed by thread, class and id. Call data contains the call count, total time, 79 PROFILE_CALL_PROC = TracePoint.new(*%i[call c_call b_call]) {|tp| # :nodoc: 80 now = Process.times[0] 81 stack = (@@stacks[Thread.current] ||= []) 82 stack.push [now, 0.0] 83 } 84 PROFILE_RETURN_PROC = TracePoint.new(*%i[return c_return b_return]) {|tp| # :nodoc: 85 now = Process.times[0] 86 key = Wrapper.new(tp.defined_class, tp.method_id) 87 stack = (@@stacks[Thread.current] ||= []) 88 if tick = stack.pop 89 threadmap = (@@maps[Thread.current] ||= {}) 90 data = (threadmap[key] ||= [0, 0.0, 0.0, key]) 91 data[0] += 1 92 cost = now - tick[0] 93 data[1] += cost 94 data[2] += cost - tick[1] 95 stack[-1][1] += cost if stack[-1] 96 end 97 } 98module_function 99 def start_profile 100 @@start = Process.times[0] 101 @@stacks = {} 102 @@maps = {} 103 PROFILE_CALL_PROC.enable 104 PROFILE_RETURN_PROC.enable 105 end 106 def stop_profile 107 PROFILE_CALL_PROC.disable 108 PROFILE_RETURN_PROC.disable 109 end 110 def print_profile(f) 111 stop_profile 112 total = Process.times[0] - @@start 113 if total == 0 then total = 0.01 end 114 totals = {} 115 @@maps.values.each do |threadmap| 116 threadmap.each do |key, data| 117 total_data = (totals[key] ||= [0, 0.0, 0.0, key]) 118 total_data[0] += data[0] 119 total_data[1] += data[1] 120 total_data[2] += data[2] 121 end 122 end 123 124 # Maybe we should show a per thread output and a totals view? 125 126 data = totals.values 127 data = data.sort_by{|x| -x[2]} 128 sum = 0 129 f.printf " %% cumulative self self total\n" 130 f.printf " time seconds seconds calls ms/call ms/call name\n" 131 for d in data 132 sum += d[2] 133 f.printf "%6.2f %8.2f %8.2f %8d ", d[2]/total*100, sum, d[2], d[0] 134 f.printf "%8.2f %8.2f %s\n", d[2]*1000/d[0], d[1]*1000/d[0], d[3] 135 end 136 f.printf "%6.2f %8.2f %8.2f %8d ", 0.0, total, 0.0, 1 # ??? 137 f.printf "%8.2f %8.2f %s\n", 0.0, total*1000, "#toplevel" # ??? 138 end 139end 140