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