Created
March 12, 2012 19:18
-
-
Save skull-squadron/2024099 to your computer and use it in GitHub Desktop.
hacking up custom_require to show library load times. (HINT: This is silly, use a debugger!)
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
# Usage: MRI put at the top of custom_require.rb | |
# | |
# ~/.rvm/rubies/ruby-1.9.3-p125/lib/ruby/site_ruby/1.9.1/rubygems/custom_require.rb | |
# This is crappy/untested proof-of-concept code, do not use it in production. It will fail. | |
# Unlikely to be threadsafe either. | |
# Don't run this on anything you care about. | |
# No warranties, express or implied. GPL v3 license. | |
if ENV['RBDEBUG_REQUIRE'] && !ENV['RBDEBUG_HIDE'] | |
$load_tabs ||= 0 | |
$load_histogram ||= {} | |
$load_order ||= [] #[ [ filename (String), start_time (DateTime), time_taken (seconds Float), result ], ... ] | |
$load_bypass_stats ||= 0 | |
SAVING_HISTOGRAM = false | |
SAVING_AUDIT = false | |
# $stderr.sync = $stdout.sync = true | |
# STDERR.sync = STDOUT.sync = true | |
%w|require load import|.each do |fn| | |
next unless Kernel.respond_to? fn | |
oldfn = ("old_" + fn).to_sym | |
next if Kernel.respond_to? oldfn | |
Kernel.class_eval <<-function_def | |
RETRY_COOLOFF_TIME ||= 15 | |
# not DRY, make it a monad or something | |
def bypass_stats(*args, &block) | |
$load_bypass_stats += 1 | |
yield(*args) | |
ensure | |
$load_bypass_stats -= 1 | |
end | |
def increase_tab_depth(*args, &block) | |
$load_tabs += 1 | |
yield(*args) | |
ensure | |
$load_tabs -= 1 | |
end | |
bypass_stats { require 'date' } | |
$load_last_tried = DateTime.now | |
$load_last_tries = 0 | |
def tabs | |
' ' * ($load_tabs * 2 + 4) | |
end | |
def load_outputter(value, tabs_enabled = true) | |
bypass_stats do | |
unless $w | |
begin | |
raise LoadError unless $stdout.tty? # aweseome requires tty | |
if ((now=DateTime.now) - $load_last_tried)*60*60*24 > RETRY_COOLOFF_TIME # retry after 15 sec | |
$load_last_tries = 0 | |
else | |
$load_last_tried = now | |
if ($load_last_tries += 1) > 8 | |
$stdout.puts "too many errors, disabling for \#{RETRY_COOLOFF_TIME}" | |
raise LoadError | |
end | |
end | |
require 'ap' | |
$w = :ap | |
rescue LoadError | |
$w = :p | |
end | |
end | |
$stdout.puts tabs + "\#{$load_tabs}" if tabs_enabled | |
# $stdout.flush | |
send w, value | |
# $stdout.flush | |
end # bypass_stats | |
end | |
alias :#{oldfn} :#{fn} | |
def #{fn}(*args, &block) | |
required_line = args[0] | |
if $load_bypass_stats > 0 | |
#### Don't do any timing, would cause stack recursion (darn imperative languages) | |
$stdout.puts tabs + "\#{required_line} (stats bypassed \#{$load_bypass_stats})" | |
return #{oldfn}(*args, &block) | |
end | |
increase_tab_depth do | |
$stdout.puts tabs + "\#{required_line} ..." | |
# Update stats | |
if SAVING_HISTOGRAM | |
if $load_histogram.has_key? required_line | |
$load_histogram[required_line] += 1 | |
else | |
$load_histogram[required_line] = 1 | |
end | |
end | |
unless defined? AbsoluteTime | |
begin | |
bypass_stats do | |
require 'absolute_time' | |
end | |
$stdout.puts 'loaded absolute_time' | |
rescue LoadError | |
$stdout.puts 'Absolute Time gem not available. [sudo] gem install absolute_time to fix.' | |
end | |
end | |
result = nil | |
start_time = DateTime.now | |
time_elapsed = if defined? AbsoluteTime | |
### absolute time, computed using available hardware | |
AbsoluteTime.realtime do | |
result = #{oldfn}(*args, &block) | |
end * 1000000.0 # ns to ms | |
else | |
# crappy normal time | |
result = #{oldfn}(*args, &block) | |
((DateTime.now - start_time)*60*60*24) # whatever to seconds, may not be portable | |
end | |
$stdout.printf tabs + "\#{required_line} took %5.3f ms\\n", time_elapsed / 1000.0 #; $stdout.flush | |
# Save the results | |
$load_order << [ required_line, start_time, time_elapsed, result ] if SAVING_AUDIT | |
result | |
end # increase_tab_depth | |
end # def | |
function_def | |
## Only load once past here | |
next unless defined? Kernel::LoadOnceFlag ; Kernel::LoadOnceFlag = true | |
## | |
Kernel.class_eval <<-once_def | |
def show_load_histogram | |
raise 'No data likely' unless SAVING_HISTOGRAM | |
load_outputter $load_histogram.sort_by { |load_file, count| -count } # Descending by count | |
end | |
#[ [ required_line (String), start_time (DateTime), time_taken (seconds Float), result (boolean) ], ... | |
def show_load_order | |
raise 'No data likely' unless SAVING_AUDIT | |
load_order.each do |required_line, start_time, time_taken, result| | |
load_outputter( [required_line, start_time, time_taken, result], false) | |
end | |
end | |
once_def | |
end | |
end | |
# Don't forget this stupid hack. | |
$stdout.puts "patched #{__FILE__} to show requires, loads and imports. RBDEBUG_REQUIRE shows, RBDEBUG_HIDE hides" |
require 'date'
DateTime.new
#require 'benchmark'
require 'absolute_time' # returns microseconds on mac
TIMES = 100000
10.times do
time1 = AbsoluteTime.realtime do
TIMES.times do
require 'date'
end
end
time2 = AbsoluteTime.realtime do
TIMES.times do
require 'date' unless defined? DateTime
end
end
printf " require: %4.8f milliseconds/call\n", ( 1000.0 * time1 ) / TIMES
printf "require /w defined?: %4.8f milliseconds/call\n", ( 1000.0 * time2 ) / TIMES
end
# i should add stddev, trend, etc. maybe csv
require: 0.06408896 milliseconds/call
require /w defined?: 0.00034230 milliseconds/call
require: 0.02353274 milliseconds/call
require /w defined?: 0.00036613 milliseconds/call
require: 0.02460732 milliseconds/call
require /w defined?: 0.00042176 milliseconds/call
require: 0.02445202 milliseconds/call
require /w defined?: 0.00033817 milliseconds/call
require: 0.02361804 milliseconds/call
require /w defined?: 0.00035523 milliseconds/call
require: 0.02355366 milliseconds/call
require /w defined?: 0.00035150 milliseconds/call
require: 0.02393944 milliseconds/call
require /w defined?: 0.00035333 milliseconds/call
require: 0.02426665 milliseconds/call
require /w defined?: 0.00040322 milliseconds/call
require: 0.02388820 milliseconds/call
require /w defined?: 0.00041266 milliseconds/call
require: 0.02374663 milliseconds/call
require /w defined?: 0.00036372 milliseconds/call
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Answer: 1. by 2+ orders of magnitude.
ruby 1.9.3p125 (2012-02-16 revision 34643) [x86_64-darwin11.3.0]