mirror of
https://github.com/ruby/ruby.git
synced 2022-11-09 12:17:21 -05:00
e527695d50
git-svn-id: svn+ssh://ci.ruby-lang.org/ruby/trunk@57363 b2dd03c8-39d4-4d8f-98ff-823fe69b080e
149 lines
4.5 KiB
Ruby
149 lines
4.5 KiB
Ruby
# frozen_string_literal: true
|
|
# 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
|