[Rubygems-developers] RubyGems performance

[Gavin Sinclair]

As I mentioned in the other thread ("Gem::Specification#copy_of and
Rails makes tests startup slow"), I'm doing some performance
investigations of RubyGems.  Just FYI I'm posting results here as I
go.


Source code (rgperf.rb):

  $:.unshift 'lib'

  require 'rubygems/logger'

  time("require 'rubygems'")  { require 'rubygems' }
  time("Gem.manage_gems")     { Gem.manage_gems }
  time("require_gem 'log4r'") { require_gem 'log4r' }

  
Source code(rubygems/logger.rb):

  $log = Object.new
  def $log.debug(str)
    STDERR.puts str
  end

  def time(msg, width=25)
    t = Time.now
    yield
    elapsed = Time.now.to_f - t.to_f
    elapsed = sprintf("%3.3f", elapsed)
    $log.debug "#{msg.ljust(width)}: #{elapsed}s"
  end

  
Source code (extract from rubygems.rb):

    def manage_gems
      $log.debug "Timing manage_gems"
      time("manage_gems") {
        time("  require 'rubygems/user_interaction'", 40) { require 'rubygems/user_interaction' }
        time("  require 'rubygems/builder'", 40)          { require 'rubygems/builder' }
        time("  require 'rubygems/format'", 40)           { require 'rubygems/format' }
        time("  require 'rubygems/remote_installer'", 40) { require 'rubygems/remote_installer' }
        time("  require 'rubygems/installer'", 40)        { require 'rubygems/installer' }
        time("  require 'rubygems/validator'", 40)        { require 'rubygems/validator' }
        time("  require 'rubygems/doc_manager'", 40)      { require 'rubygems/doc_manager' }
        time("  require 'rubygems/cmd_manager'", 40)      { require 'rubygems/cmd_manager' }
        time("  require 'rubygems/gem_runner'", 40)       { require 'rubygems/gem_runner' }
        time("  require 'rubygems/config_file'", 40)      { require 'rubygems/config_file' }
      }
    end

    
Results (ruby rgperf.rb):

  require 'rubygems'       : 0.323s
  Timing manage_gems
    require 'rubygems/user_interaction'   : 0.060s
    require 'rubygems/builder'            : 2.304s
    require 'rubygems/format'             : 0.152s
    require 'rubygems/remote_installer'   : 0.308s
    require 'rubygems/installer'          : 0.339s
    require 'rubygems/validator'          : 0.140s
    require 'rubygems/doc_manager'        : 0.085s
    require 'rubygems/cmd_manager'        : 0.509s
    require 'rubygems/gem_runner'         : 0.082s
    require 'rubygems/config_file'        : 0.158s
  manage_gems              : 4.146s
  Gem.manage_gems          : 4.146s
  require_gem 'log4r'      : 3.434s


Comments:

 * manage_gems and require_gem both take >3s to complete, whereas a
   regular require takes 0.3s

 * obviously not all requires and require_gems are alike, but 3.4s for
   require_gem 'log4r' is too long

 * manage_gem isn't such an issue because it's not used in runtime
   situations, EXCEPT when using the gem command (so it would be nice
   to improve somehow)

 * a very disproportionate amount of time in manage_gem is spent loading
   'rubygems/builder'

   * the culprit is obviously 'rubygems/package', which I doubt has
     any glaring inefficiencies -- it's just the volume of Ruby code

     * perhaps we should only load it when we need it?

 * my investigation will now focus on require_gem


Gavin

P.S. Loading 'rubygems/specification' FIRST (in a separate test) took
0.386s.  By comparison, stdlib's 'logger' took 0.034s and 'yaml' took
0.600s.  There's probably room for improvement, but it's not the
pressing issue.