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
|
