summaryrefslogtreecommitdiff
path: root/lib/profiler.rb
blob: e53951cbe6e3099754bed0f788e39fd597698824 (plain)
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
# Profile provides a way to Profile your Ruby application.
#
# Profiling your program is a way of determining which methods are called and
# how long each method takes to complete.  This way you can detect which
# methods are possible bottlenecks.
#
# Profiling your program will slow down your execution time considerably,
# so activate it only when you need it.  Don't confuse benchmarking with
# profiling.
#
# There are two ways to activate Profiling:
#
# == Command line
#
# Run your Ruby script with <code>-rprofile</code>:
#
#   ruby -rprofile example.rb
#
# If you're profiling an executable in your <code>$PATH</code> you can use
# <code>ruby -S</code>:
#
#   ruby -rprofile -S some_executable
#
# == From code
#
# Just require 'profile':
#
#   require 'profile'
#
#   def slow_method
#     5000.times do
#       9999999999999999*999999999
#     end
#   end
#
#   def fast_method
#     5000.times do
#       9999999999999999+999999999
#     end
#   end
#
#   slow_method
#   fast_method
#
# The output in both cases is a report when the execution is over:
#
#   ruby -rprofile example.rb
#
#     %   cumulative   self              self     total
#    time   seconds   seconds    calls  ms/call  ms/call  name
#    68.42     0.13      0.13        2    65.00    95.00  Integer#times
#    15.79     0.16      0.03     5000     0.01     0.01  Fixnum#*
#    15.79     0.19      0.03     5000     0.01     0.01  Fixnum#+
#     0.00     0.19      0.00        2     0.00     0.00  IO#set_encoding
#     0.00     0.19      0.00        1     0.00   100.00  Object#slow_method
#     0.00     0.19      0.00        2     0.00     0.00  Module#method_added
#     0.00     0.19      0.00        1     0.00    90.00  Object#fast_method
#     0.00     0.19      0.00        1     0.00   190.00  #toplevel

module Profiler__
  class Wrapper < Struct.new(:defined_class, :method_id, :hash) # :nodoc:
    private :defined_class=, :method_id=, :hash=

    def initialize(klass, mid)
      super(klass, mid, nil)
      self.hash = Struct.instance_method(:hash).bind(self).call
    end

    def to_s
      "#{defined_class.inspect}#".sub(/\A\#<Class:(.*)>#\z/, '\1.') << method_id.to_s
    end
    alias inspect to_s
  end

  # internal values
  @@start = nil # the start time that profiling began
  @@stacks = nil # the map of stacks keyed by thread
  @@maps = nil # the map of call data keyed by thread, class and id. Call data contains the call count, total time,
  PROFILE_CALL_PROC = TracePoint.new(*%i[call c_call b_call]) {|tp| # :nodoc:
    now = Process.times[0]
    stack = (@@stacks[Thread.current] ||= [])
    stack.push [now, 0.0]
  }
  PROFILE_RETURN_PROC = TracePoint.new(*%i[return c_return b_return]) {|tp| # :nodoc:
    now = Process.times[0]
    key = Wrapper.new(tp.defined_class, tp.method_id)
    stack = (@@stacks[Thread.current] ||= [])
    if tick = stack.pop
      threadmap = (@@maps[Thread.current] ||= {})
      data = (threadmap[key] ||= [0, 0.0, 0.0, key])
      data[0] += 1
      cost = now - tick[0]
      data[1] += cost
      data[2] += cost - tick[1]
      stack[-1][1] += cost if stack[-1]
    end
  }
module_function
  # Starts the profiler.
  #
  # See Profiler__ for more information.
  def start_profile
    @@start = Process.times[0]
    @@stacks = {}
    @@maps = {}
    PROFILE_CALL_PROC.enable
    PROFILE_RETURN_PROC.enable
  end
  # Stops the profiler.
  #
  # See Profiler__ for more information.
  def stop_profile
    PROFILE_CALL_PROC.disable
    PROFILE_RETURN_PROC.disable
  end
  # Outputs the results from the profiler.
  #
  # See Profiler__ for more information.
  def print_profile(f)
    stop_profile
    total = Process.times[0] - @@start
    if total == 0 then total = 0.01 end
    totals = {}
    @@maps.values.each do |threadmap|
      threadmap.each do |key, data|
        total_data = (totals[key] ||= [0, 0.0, 0.0, key])
        total_data[0] += data[0]
        total_data[1] += data[1]
        total_data[2] += data[2]
      end
    end

    # Maybe we should show a per thread output and a totals view?

    data = totals.values
    data = data.sort_by{|x| -x[2]}
    sum = 0
    f.printf "  %%   cumulative   self              self     total\n"
    f.printf " time   seconds   seconds    calls  ms/call  ms/call  name\n"
    for d in data
      sum += d[2]
      f.printf "%6.2f %8.2f  %8.2f %8d ", d[2]/total*100, sum, d[2], d[0]
      f.printf "%8.2f %8.2f  %s\n", d[2]*1000/d[0], d[1]*1000/d[0], d[3]
    end
    f.printf "%6.2f %8.2f  %8.2f %8d ", 0.0, total, 0.0, 1     # ???
    f.printf "%8.2f %8.2f  %s\n", 0.0, total*1000, "#toplevel" # ???
  end
end