Why does my gem take so long to load?

Question

I'm developing my first gem called t_time_tracker (woohoo!). All was going great in development; I optomized it as much as I possibly could to cut execution time down to as little as possible:

t_time_tracker[master*]% time ruby -Ilib ./bin/t_time_tracker 
You're not working on anything
0.07s user 0.03s system 67% cpu 0.141 total

(this is the "hello world" of my app - calling it with no parameters just prints out "You're not working on anything")

About a tenth of a second and uses 67% of my CPU - cool, I can live with that. It feels fairly instantaneous. Let's build it:

$ gem build t_time_tracker.gemspec
$ gem install ./t_time_tracker-0.0.0.gem

And do the exact same thing with the installed binary:

$ time t_time_tracker
You're not working on anything
t_time_tracker  0.42s user 0.06s system 93% cpu 0.513 total

Half a second?! Where did that come from?! Let's add some debugging output and include the system gem from the development binary to see where the bottleneck is:

t_time_tracker[master*]% time ruby ./bin/t_time_tracker  
(starting binary)
(require 'time' and 'optparse')
0.041432
(before `require 't_time_tracker')
0.497135
(after `require 't_time_tracker')
(Gem.loaded_specs.keys = t_time_tracker)
(initializing TTimeTracker class)
You're not working on anything
ruby ./bin/t_time_tracker  0.44s user 0.07s system 91% cpu 0.551 total

Alright, so the `require 't_time_tracker' line seems to be the culprit. Let's try again in irb to narrow it down further:

$ irb
>> t=Time.now; require 't_time_tracker'; puts Time.now-t
0.046792
=> nil

...what? But that was just taking half a second! Let's try building the gem with our debugging output:

$ gem build t_time_tracker.gemspec
$ gem install ./t_time_tracker-0.0.0.gem
$ time t_time_tracker
(starting binary) <---noticeable half second delay before this line shows up
(require 'time' and 'optparse')
0.050458
(before `require 't_time_tracker')
0.073789
(after `require 't_time_tracker')
(Gem.loaded_specs.keys = t_time_tracker)
(initializing TTimeTracker class)
You're not working on anything
t_time_tracker  0.42s user 0.06s system 88% cpu 0.546 total

So yeah, where is this 0.5 second delay coming from? I usually wouldn't care, but this is something that I'm calling about fifty times a day to update what I'm doing. 50 * 0.5 seconds * 365 days * 70 years = 15 days of lost life.

System information:

Mac OS X 10.7.3. 2 GHz Intel Core 2 Duo. 4 GB ram. ruby 1.9.2p290.

% gem -v
1.8.10<---noticeable half second delay before this line shows up
% gem list | wc -l
209

Answer 1

Been a while since I looked at this but RubyGems has, in the past (and maybe the present), taken a long time to load for mainly two reasons:

• It would load many relatively expensive libraries like 'time' via 'yaml'. Usually you don't care because it's slow relative to ruby all by itself, not slow compared to the run time of many scripts.
• It would scan over all the installed gems and load the most recent gemspecs into memory. This took a long time if you have a lot of gems.

These issues may or may not still be in play. However you'll always have some overhead from RubyGems. If you really need performance, then just set up your load path yourself! Ruby without RubyGems is very fast, as you know.

To see where your gem is installed:

gem list -d YOUR_GEM_NAME

You'll see the install directory. Your gem will be at INSTALL_DIR/gems/GEM_NAME-VERSION so try executing:

time ruby -IINSTALL_DIR/gems/GEM_NAME-VERSION/lib INSTALL_DIR/gems/GEM_NAME-VERSION/bin/t_time_tracker

That's a lot, but you should be able to wrap this in a separate script, something like this (name it t_time_tracker):

#!/usr/bin/env ruby -IINSTALL_DIR/gems/GEM_NAME-VERSION/lib
load 'INSTALL_DIR/gems/GEM_NAME-VERSION/bin/t_time_tracker'

Then:

chmod +x t_time_tracker
time ./t_time_tracker

And put that file anywhere along your PATH. RubyGems does for you automatically, but of course you then accept the overhead of RubyGems.