summaryrefslogtreecommitdiff
path: root/lib/profiler.rb
blob: d68bd71c491c278b781acf081da9ca6a2df4998c (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
# 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_PROC = TracePoint.new(:call, :c_call, :return, :c_return) {|tp|
    case tp.event
    when :call, :c_call
      now = Process.times[0]
      stack = (@@stacks[Thread.current] ||= [])
      stack.push [now, 0.0]
    when :return, :c_return
      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
    end
  }
module_function
  def start_profile
    @@start = Process.times[0]
    @@stacks = {}
    @@maps = {}
    PROFILE_PROC.enable
  end
  def stop_profile
    PROFILE_PROC.disable
  end
  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