[Rubygems-developers] RubyGems performance

[Gavin Sinclair]

On Saturday, December 11, 2004, 1:34:03 PM, Gavin wrote:

> 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.

More results:

  require 'rubygems'       : 0.321s
  require_gem 'log4r'      : 3.601s
  require_gem 'RedCloth'   : 0.119s
  require_gem 'rake'       : 0.013s
  require_gem 'extensions' : 0.009s
  require_gem 'cstemplate' : 0.009s
  require_gem 'dev-utils'  : 0.014s

The first require_gem is slow; subsequent ones are fast.  That's good.
Using require instead of require_gem (with none of these libraries
installed directly):

  require 'rubygems'       : 0.305s
  require 'log4r'          : 3.772s
  require 'redcloth'       : 0.577s
  require 'rake'           : 0.908s
  require 'extensions/all' : 5.594s
  require 'celsoft.com/template': 0.362s
  require 'dev-utils/debug': 5.697s

Log4r is probably taking a hit as an index is being built up.
RedCloth is comparable to require_gem.  Rake and cstemplate both take
a significant hit, explained by the lack of autorequire in their
gemspecs.  'extensions/all' and 'dev-utils/debug' -- my libraries --
are embarassingly slow.  Again, it's just that require_gem is fast
because they don't use autorequire.

Just to check, I rearranged the order to see if the first use of
require (after rubygems) takes a hit:

  require 'rubygems'       : 0.347s
  require 'redcloth'       : 0.633s
  require 'log4r'          : 3.961s
  require 'rake'           : 0.924s

It's inconclusive.  RedCloth is consistently taking longer than before
(0.6 instead of 0.2), but Log4r is much the same.  One more time, with
Rake leading the way:

  require 'rubygems'       : 0.304s
  require 'rake'           : 1.135s
  require 'redcloth'       : 0.597s
  require 'log4r'          : 4.547s

Yes, there's definitely an effect.  RedCloth is back to normal, and
Rake is taking a bit longer.

Anyway, the REAL test is to pit directly-installed libraries against
gem-installed libraries.  So I'll install those six libraries manually
and time their loading.  The results are interesting:

  require 'rake'           : 0.203s
  require 'redcloth'       : 0.477s
  require 'log4r'          : 0.430s
  require 'extensions/all' : 0.536s
  require 'dev-utils/debug': 0.640s
  require 'celsoft.com/template': 0.075s

I'll summarise the results in a table.

  * "DIRECT" means calling require 'X' where 'X' is installed
    directly (via RPA, as it happens).
  * "GEM" means calling require 'X' where X is installed as a gem.
  * "COMBO" means calling require 'X' _after_ having loaded 'rubygems'
    but where the library is also installed directly.

  LIBRARY                 |  DIRECT  |   GEM    |  COMBO
  ------------------------+----------+----------+---------
  'rake'                  |  0.203s  |  3.772s  |  0.481s
  'redcloth'              |  0.477s  |  0.577s  |  1.355s
  'log4r'                 |  0.430s  |  0.908s  |  2.545s
  'extensions/all'        |  0.536s  |  5.594s  |  2.741s
  'dev-utils/debug'       |  0.640s  |  5.697s  |  2.056s
  'celsoft.com/template'  |  0.075s  |  0.362s  |  0.096s


*** CONCLUSION ***

There's a startling difference between loading certain libraries
directly vs loading them as a gem.  And the difference is inconsistent
between libraries.

In all cases, it's slower to load gems than load direct libraries.
That's not surprising.  It's worth trying to speed the gem loading up,
because it becomes noticable in the startup time of many applications,
especially small applications that get run a lot (e.g. unit tests,
rake).

My next study will look into those libraries to find the reason for
the discrepancies and the inconsistencies.