hacking up custom_require to show library load times. (HINT: This is silly, use a debugger!)

require_profiling__custom_require.rb

# 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"

So dumb, should not be all in a mega eval.

Aside.... Which is faster?

1. require 'somegem' unless defined? SomeGemSymbol
2. require 'somegem'

Update: made it clear that somegem is a placeholder.

Answer: 1. by 2+ orders of magnitude. ruby 1.9.3p125 (2012-02-16 revision 34643) [x86_64-darwin11.3.0]

Related: https://blog.gregbrockman.com/2012/02/improving-ruby-code-load-time/

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