Time yer loads and requires

gistfile1.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}  ..."
          if SAVING_HISTOGRAM
            if $load_histogram.has_key? method_name
              $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 ] unless 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
        
      #[ [ filename (String), start_time (DateTime), time_taken (seconds Float), result ], ... 
      def show_load_order
        raise 'No data likely' unless SAVING_AUDIT
        load_order.each do |load_item|
          load_outputter({ :start_time  => load_item[1],
                            :time_taken => (1000.0 * load_item[2]),  # convert from ms to seconds.
                            :filename   => load_item[0],
                            :result     => load_item[3] }, 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" unless ENV.has_key? 'RBDEBUG_HIDE'