Ruby

Why is Rubygems Slow?

Richard Schneeman
Share

rubygemsslow

“Why exactly is Rubygems slow?” is the question that more than one developer has asked, but few have bothered to do anything about. Recently @mfazekas took up the task for profiling an especially slow case using dtrace. This resulted in several high profile pull requests to improve performance and drop memory allocations. These in turn lead me to ask the question, just what is Rubygems doing that takes so long? The short answer is, way more than you ever thought; for the long answer, keep reading.

Rubygems Basics

The Rubygems gem comes stock with modern versions of Ruby. It’s goal is to make installing and using external pieces of code (or libraries) easier. To do this, it takes over Kernel#require so that after you’ve run:

$ gem install wicked

You can later require 'wicked' and right code gets loaded.

Load Path and Resolutions

When you require wicked you don’t specify a version to load, so how does Rubygems know which one to use? It could take the latest version, but then when you $ gem install a more recent version for a different project, your project might break. Rubygems tries to make an intelligent decision about the dependencies you need based on other dependencies. When a gem is published to rubygems.org (the server) they contain a .gemspec that declares information about the current gem as well as the dependencies that gem has. For example in wicked.gemspec

gem.add_dependency             "railties", [">= 3.0.7"]
gem.add_development_dependency "rails",    [">= 3.0.7"]
gem.add_development_dependency "capybara", [">= 0"]

If you only have this version of wicked required, it can’t be required unless you’re also using a version of railties greater than 3.0.7. If it can’t find one it will raise an exception. If it finds a valid version it adds it to $LOADED_FEATURES.

Using another library, threaded, we can see $LOADED_FEATURES, here it is before being loaded:

puts $LOADED_FEATURES.inspect
=> ["enumerator.so", "rational.so", "complex.so", "/Users/richardschneeman/.rubies/ruby-2.2.1/lib/ruby/2.2.0/x86_64-darwin14/enc/encdb.bundle", "/Users/richardschneeman/.rubies/ruby-2.2.1/lib/ruby/2.2.0/x86_64-darwin14/enc/trans/transdb.bundle", "/Users/richardschneeman/.rubies/ruby-2.2.1/lib/ruby/2.2.0/unicode_normalize.rb", "/Users/richardschneeman/.rubies/ruby-2.2.1/lib/ruby/2.2.0/x86_64-darwin14/rbconfig.rb", "thread.rb", "/Users/richardschneeman/.rubies/ruby-2.2.1/lib/ruby/2.2.0/x86_64-darwin14/thread.bundle", "/Users/richardschneeman/.rubies/ruby-2.2.1/lib/ruby/2.2.0/rubygems/compatibility.rb", "/Users/richardschneeman/.rubies/ruby-2.2.1/lib/ruby/2.2.0/rubygems/defaults.rb", "/Users/richardschneeman/.rubies/ruby-2.2.1/lib/ruby/2.2.0/rubygems/deprecate.rb", "/Users/richardschneeman/.rubies/ruby-2.2.1/lib/ruby/2.2.0/rubygems/errors.rb", "/Users/richardschneeman/.rubies/ruby-2.2.1/lib/ruby/2.2.0/rubygems/version.rb", "/Users/richardschneeman/.rubies/ruby-2.2.1/lib/ruby/2.2.0/rubygems/requirement.rb", "/Users/richardschneeman/.rubies/ruby-2.2.1/lib/ruby/2.2.0/rubygems/platform.rb", "/Users/richardschneeman/.rubies/ruby-2.2.1/lib/ruby/2.2.0/rubygems/basic_specification.rb", "/Users/richardschneeman/.rubies/ruby-2.2.1/lib/ruby/2.2.0/rubygems/stub_specification.rb", "/Users/richardschneeman/.rubies/ruby-2.2.1/lib/ruby/2.2.0/rubygems/util/stringio.rb", "/Users/richardschneeman/.rubies/ruby-2.2.1/lib/ruby/2.2.0/rubygems/specification.rb", "/Users/richardschneeman/.rubies/ruby-2.2.1/lib/ruby/2.2.0/rubygems/exceptions.rb", "/Users/richardschneeman/.rubies/ruby-2.2.1/lib/ruby/2.2.0/rubygems/core_ext/kernel_gem.rb", "/Users/richardschneeman/.rubies/ruby-2.2.1/lib/ruby/2.2.0/monitor.rb", "/Users/richardschneeman/.rubies/ruby-2.2.1/lib/ruby/2.2.0/rubygems/core_ext/kernel_require.rb", "/Users/richardschneeman/.rubies/ruby-2.2.1/lib/ruby/2.2.0/rubygems.rb", "/Users/richardschneeman/.rubies/ruby-2.2.1/lib/ruby/2.2.0/e2mmap.rb", "/Users/richardschneeman/.rubies/ruby-2.2.1/lib/ruby/2.2.0/irb/init.rb", "/Users/richardschneeman/.rubies/ruby-2.2.1/lib/ruby/2.2.0/irb/workspace.rb", "/Users/richardschneeman/.rubies/ruby-2.2.1/lib/ruby/2.2.0/irb/inspector.rb", "/Users/richardschneeman/.rubies/ruby-2.2.1/lib/ruby/2.2.0/irb/context.rb", "/Users/richardschneeman/.rubies/ruby-2.2.1/lib/ruby/2.2.0/irb/extend-command.rb", "/Users/richardschneeman/.rubies/ruby-2.2.1/lib/ruby/2.2.0/irb/output-method.rb", "/Users/richardschneeman/.rubies/ruby-2.2.1/lib/ruby/2.2.0/irb/notifier.rb", "/Users/richardschneeman/.rubies/ruby-2.2.1/lib/ruby/2.2.0/irb/slex.rb", "/Users/richardschneeman/.rubies/ruby-2.2.1/lib/ruby/2.2.0/irb/ruby-token.rb", "/Users/richardschneeman/.rubies/ruby-2.2.1/lib/ruby/2.2.0/irb/ruby-lex.rb", "/Users/richardschneeman/.rubies/ruby-2.2.1/lib/ruby/2.2.0/irb/src_encoding.rb", "/Users/richardschneeman/.rubies/ruby-2.2.1/lib/ruby/2.2.0/irb/magic-file.rb", "/Users/richardschneeman/.rubies/ruby-2.2.1/lib/ruby/2.2.0/x86_64-darwin14/readline.bundle", "/Users/richardschneeman/.rubies/ruby-2.2.1/lib/ruby/2.2.0/irb/input-method.rb", "/Users/richardschneeman/.rubies/ruby-2.2.1/lib/ruby/2.2.0/irb/locale.rb", "/Users/richardschneeman/.rubies/ruby-2.2.1/lib/ruby/2.2.0/irb.rb", "/Users/richardschneeman/.rubies/ruby-2.2.1/lib/ruby/2.2.0/rubygems/path_support.rb", "/Users/richardschneeman/.rubies/ruby-2.2.1/lib/ruby/2.2.0/rubygems/dependency.rb"]

And after:

["enumerator.so", "rational.so", "complex.so", "/Users/richardschneeman/.rubies/ruby-2.2.1/lib/ruby/2.2.0/x86_64-darwin14/enc/encdb.bundle", "/Users/richardschneeman/.rubies/ruby-2.2.1/lib/ruby/2.2.0/x86_64-darwin14/enc/trans/transdb.bundle", "/Users/richardschneeman/.rubies/ruby-2.2.1/lib/ruby/2.2.0/unicode_normalize.rb", "/Users/richardschneeman/.rubies/ruby-2.2.1/lib/ruby/2.2.0/x86_64-darwin14/rbconfig.rb", "thread.rb", "/Users/richardschneeman/.rubies/ruby-2.2.1/lib/ruby/2.2.0/x86_64-darwin14/thread.bundle", "/Users/richardschneeman/.rubies/ruby-2.2.1/lib/ruby/2.2.0/rubygems/compatibility.rb", "/Users/richardschneeman/.rubies/ruby-2.2.1/lib/ruby/2.2.0/rubygems/defaults.rb", "/Users/richardschneeman/.rubies/ruby-2.2.1/lib/ruby/2.2.0/rubygems/deprecate.rb", "/Users/richardschneeman/.rubies/ruby-2.2.1/lib/ruby/2.2.0/rubygems/errors.rb", "/Users/richardschneeman/.rubies/ruby-2.2.1/lib/ruby/2.2.0/rubygems/version.rb", "/Users/richardschneeman/.rubies/ruby-2.2.1/lib/ruby/2.2.0/rubygems/requirement.rb", "/Users/richardschneeman/.rubies/ruby-2.2.1/lib/ruby/2.2.0/rubygems/platform.rb", "/Users/richardschneeman/.rubies/ruby-2.2.1/lib/ruby/2.2.0/rubygems/basic_specification.rb", "/Users/richardschneeman/.rubies/ruby-2.2.1/lib/ruby/2.2.0/rubygems/stub_specification.rb", "/Users/richardschneeman/.rubies/ruby-2.2.1/lib/ruby/2.2.0/rubygems/util/stringio.rb", "/Users/richardschneeman/.rubies/ruby-2.2.1/lib/ruby/2.2.0/rubygems/specification.rb", "/Users/richardschneeman/.rubies/ruby-2.2.1/lib/ruby/2.2.0/rubygems/exceptions.rb", "/Users/richardschneeman/.rubies/ruby-2.2.1/lib/ruby/2.2.0/rubygems/core_ext/kernel_gem.rb", "/Users/richardschneeman/.rubies/ruby-2.2.1/lib/ruby/2.2.0/monitor.rb", "/Users/richardschneeman/.rubies/ruby-2.2.1/lib/ruby/2.2.0/rubygems/core_ext/kernel_require.rb", "/Users/richardschneeman/.rubies/ruby-2.2.1/lib/ruby/2.2.0/rubygems.rb", "/Users/richardschneeman/.rubies/ruby-2.2.1/lib/ruby/2.2.0/e2mmap.rb", "/Users/richardschneeman/.rubies/ruby-2.2.1/lib/ruby/2.2.0/irb/init.rb", "/Users/richardschneeman/.rubies/ruby-2.2.1/lib/ruby/2.2.0/irb/workspace.rb", "/Users/richardschneeman/.rubies/ruby-2.2.1/lib/ruby/2.2.0/irb/inspector.rb", "/Users/richardschneeman/.rubies/ruby-2.2.1/lib/ruby/2.2.0/irb/context.rb", "/Users/richardschneeman/.rubies/ruby-2.2.1/lib/ruby/2.2.0/irb/extend-command.rb", "/Users/richardschneeman/.rubies/ruby-2.2.1/lib/ruby/2.2.0/irb/output-method.rb", "/Users/richardschneeman/.rubies/ruby-2.2.1/lib/ruby/2.2.0/irb/notifier.rb", "/Users/richardschneeman/.rubies/ruby-2.2.1/lib/ruby/2.2.0/irb/slex.rb", "/Users/richardschneeman/.rubies/ruby-2.2.1/lib/ruby/2.2.0/irb/ruby-token.rb", "/Users/richardschneeman/.rubies/ruby-2.2.1/lib/ruby/2.2.0/irb/ruby-lex.rb", "/Users/richardschneeman/.rubies/ruby-2.2.1/lib/ruby/2.2.0/irb/src_encoding.rb", "/Users/richardschneeman/.rubies/ruby-2.2.1/lib/ruby/2.2.0/irb/magic-file.rb", "/Users/richardschneeman/.rubies/ruby-2.2.1/lib/ruby/2.2.0/x86_64-darwin14/readline.bundle", "/Users/richardschneeman/.rubies/ruby-2.2.1/lib/ruby/2.2.0/irb/input-method.rb", "/Users/richardschneeman/.rubies/ruby-2.2.1/lib/ruby/2.2.0/irb/locale.rb", "/Users/richardschneeman/.rubies/ruby-2.2.1/lib/ruby/2.2.0/irb.rb", "/Users/richardschneeman/.rubies/ruby-2.2.1/lib/ruby/2.2.0/rubygems/path_support.rb", "/Users/richardschneeman/.rubies/ruby-2.2.1/lib/ruby/2.2.0/rubygems/dependency.rb", "/Users/richardschneeman/.rubies/ruby-2.2.1/lib/ruby/2.2.0/timeout.rb", "/Users/richardschneeman/.rubies/ruby-2.2.1/lib/ruby/2.2.0/logger.rb", "/Users/richardschneeman/.rubies/ruby-2.2.1/lib/ruby/2.2.0/x86_64-darwin14/stringio.bundle", "/Users/richardschneeman/.gem/ruby/2.2.1/gems/threaded-0.0.4/lib/threaded/version.rb", "/Users/richardschneeman/.gem/ruby/2.2.1/gems/threaded-0.0.4/lib/threaded/errors.rb", "/Users/richardschneeman/.gem/ruby/2.2.1/gems/threaded-0.0.4/lib/threaded/ext/stdout.rb", "/Users/richardschneeman/.gem/ruby/2.2.1/gems/threaded-0.0.4/lib/threaded/worker.rb", "/Users/richardschneeman/.gem/ruby/2.2.1/gems/threaded-0.0.4/lib/threaded/master.rb", "/Users/richardschneeman/.gem/ruby/2.2.1/gems/threaded-0.0.4/lib/threaded/promise.rb", "/Users/richardschneeman/.gem/ruby/2.2.1/gems/threaded-0.0.4/lib/threaded.rb"]

If you’re worried that Rubygems might pick the wrong version of a gem, you’ll need to be using bundler, which most Ruby developers already are. Bundler does gem resolution the first time you run bundle install. Bundler uses explicit specifications from the Gemfile alongside information found in an individual gem’s gemspec. Once resolved, bundler generates a Gemfile.lock. Developers check this file into their source control to ensure that every version they install is the same as their coworkers’. Otherwise, you end up with the “it works on my machine” subtle bugs that exist between minor version differences in software. Bundler works with Rubygems by adding all gems in the Gemfile.lock explicitly to $LOAD_PATH

$ echo Gemfile
source 'https://rubygems.org'

gem 'threaded'

$ bundle exec irb
> puts  $LOAD_PATH
# => ["/Users/richardschneeman/.gem/ruby/2.2.1/gems/threaded-0.0.4/lib", "/Users/richardschneeman/.gem/ruby/2.2.1/gems/bundler-1.8.3/lib", "/Users/richardschneeman/.rubies/ruby-2.2.1/lib/ruby/site_ruby/2.2.0", "/Users/richardschneeman/.rubies/ruby-2.2.1/lib/ruby/site_ruby/2.2.0/x86_64-darwin14", "/Users/richardschneeman/.rubies/ruby-2.2.1/lib/ruby/site_ruby", "/Users/richardschneeman/.rubies/ruby-2.2.1/lib/ruby/vendor_ruby/2.2.0", "/Users/richardschneeman/.rubies/ruby-2.2.1/lib/ruby/vendor_ruby/2.2.0/x86_64-darwin14", "/Users/richardschneeman/.rubies/ruby-2.2.1/lib/ruby/vendor_ruby", "/Users/richardschneeman/.rubies/ruby-2.2.1/lib/ruby/2.2.0", "/Users/richardschneeman/.rubies/ruby-2.2.1/lib/ruby/2.2.0/x86_64-darwin14"]

Here you can see that threaded version 0.0.4 is already on the load path. Now, when you try to require threaded, that explicit version will be found and Rubygems doesn’t have to attempt resolution.

It would look like using a Gemfile.lock with bundler eliminates the need for Rubygems to resolve dependencies. This is mostly true, but there are still plenty of times when you need require to work correctly without a Gemfile.lock. A good example is running rails new foo. This command will actually generate a Gemfile and a Gemfile.lock for you. This is exactly what @mfazekas was doing when the problem was identified.

Rubygems Internals

What really happens when your require a gem in your Ruby code? When you call require "wicked", the code will first try to find wicked in the normal standard library. If it can’t, then Rubygems will see if it has been loaded previously. If wicked has not been previously required, Rubygems must work to find it and calls:

found_specs = Gem::Specification.find_in_unresolved path

In Rubygems, we “activate” a gem once we know exactly what version is needed and present on the system. Once activated, we cannot activate a different version of that gem. Rubygems works to resolve dependency collisions when possible, and will error out when it can’t.

Inside of Rubygems, an “unresolved” gem specification is a gem that has been referenced by another gem but has not been loaded yet. For example, if we have a gem a that requires a gem called b we will want both gems loaded when we require a. In order for this to work Gem::Specification#activate is called on the a gem. If these were the only two dependencies needed, then we could “activate” a version of b that a needs. However if there are other gems that the system is aware of that have not been activated that reference b, it can’t be resolved and loaded yet. When this happens the dependency requirements are stored in memory:

> puts Gem::Specification.unresolved_deps.inspect
[<Gem::Dependency type=:runtime name="b" requirements=">= 0">]

Later, when a gem is explicitly require-d we check to see if it was previously stored in our Gem::Specification#find_in_unresolved list.

If we are trying to require 'c' where a is activated and references b (which is “unresolved”), then Rubygems does not know where to find c yet. To do this, it needs to walk through all unresolved dependencies and find which have a reference to c. To do this we call:

found_specs = Gem::Specification.find_in_unresolved_tree path

which must traverse all possible gems.

Gem Traverse

The traverse method inside of Rubygems is an expensive one with no affiliation with Chevy.

chevy traverse

(groan)

When trying to find a specification in the unresolved tree, the unresolved dependencies must be looked up and each of their dependencies need to be inspected to see if they contain the gem we are looking for.

You can see this logic in Gem::Specification.find_in_unresolved_tree:

def self.find_in_unresolved_tree path
  specs = unresolved_deps.values.map { |dep| dep.to_specs }.flatten

  specs.reverse_each do |spec|
    trails = []
    spec.traverse do |from_spec, dep, to_spec, trail|
      next unless to_spec.conflicts.empty?
      trails << trail if to_spec.contains_requirable_file? path
    end

    next if trails.empty?

    return trails.map(&:reverse).sort.first.reverse
  end

  []
end

This code calls the traverse method on each “unresolved” spec:

def traverse trail = [], &block
  trail = trail + [self]
  runtime_dependencies.each do |dep|
    dep.to_specs.each do |dep_spec|
      block[self, dep, dep_spec, trail + [dep_spec]]
      dep_spec.traverse(trail, &block) unless
        trail.map(&:name).include? dep_spec.name
      end
  end
end

This method takes all Gem::Specification-s that will automatically be activated at runtime by the target gem; these are known as “runtime dependencies”. For each of these, it grabs their dependencies and calls traverse on each of the dependencies. Each time this happens the trail variable is added to with the current Gem::Specification.

This is a expensive method, as it allocates 2 arrays each time it is called:

trail = trail + [self]

In addition to the [self] array, the process of adding an array to an already existing array actually allocates a new array even if you use the same variable:

irb(main):005:0> array = [1,2,3]
=> [1, 2, 3]
irb(main):006:0> puts array.object_id
70265837266320
=> nil
irb(main):007:0> array = array + [4]
=> [1, 2, 3, 4]
irb(main):008:0> puts array.object_id
70265837200880

Once we do the assignment, array = array + [4], the object_id of the array variable changes. A new array has been allocated. The Ruby interpreter could optimize to not allocate this array, but it is very difficult, since somewhere else could hold a reference to the array, including eval-ed code:

array = [1, 2, 3]

eval(
  <<-CODE
    def foo(ary); $array = ary; end
    foo(array)
  CODE
)
> array = array + [4]

Duplicating this array over and over on each run to traverse is made worse when it is done again later on down:

block[self, dep, dep_spec, trail + [dep_spec]]

Note: This is identical code to calling block.call(self, dep, dep_spec, trail + [dep_spec])

List to the Rescue?

An array contains quite a few features that aren’t needed in this case. All we’re trying to do is to keep track of the specs that have been traversed. Aaron submitted a relatively popular patch to help with this problem:

The Gem::List is a linked list data structure. This structure is like an array, in that it holds sequential data. In a linked list, elements can be added and removed very efficiently compared to an array, since the entire data structure does not need to be reorganized. A linked list is made up of many nodes that each have a value and a reference to the “next” or “tail” node. You can iterate over an entire linked list like this from the Gem::Node source:

def each
  n = self
  while n
    yield n.value
    n = n.tail
  end
end

In the pull request, this Gem::Node is used to track the traversal process. Take a look at the source:

##
# This method is for traversing spec dependencies.  Don't use this, it is
# super private. I am super serious!

def self._traverse spec, trail, &block # :nodoc:
  spec.dependencies.each do |dep|
    next unless dep.runtime?
    dep.to_specs.each do |dep_spec|
      stack = Gem::List.new(dep_spec, trail)
      block[dep_spec, stack]
      spec_name = dep_spec.name
      _traverse(dep_spec, stack, &block) unless
        stack.any? { |s| s.name == spec_name }
    end
  end
end
private_class_method :_traverse

The logic is essentially the same as the original traverse. Recursively go through all gem specifications and look through each of their specifications. While the account of “millions of allocations” was due to a bug in the PR, the improvement still stands that reducing allocations on each invocation is an improvement.

Effects

The test that was written highlights the worst case scenario. We have many gems that have not been “activated” but are loaded, and they also reference many other gems. We are forcing a full traversal by searching for a file that doesn’t exist.

What does this mean for your app? I modified Rubygems to print out the number of times Gem::Specification.find_in_unresolved_tree path is called while booting my codetriage.com app. That method gets called twice which results in 30 total calls to the traverse method.

You can reduce this to 0 calls to either method by booting the app with bundle exec. When bundle exec is used, the scope of gems that can be searched through is reduced, as only gems found in the Gemfile.lock will be present in the load path.

What Does It All Mean?

This is one of my favorite recent pull requests for a number of reasons. First, it had a bug in it that no one caught in the tests. What does this mean? We can’t always rely on existing test suites to handle every possible scenario. There’s a reason such pull requests are made in public. The human element to review and gauge validity cannot be underestimated.

My second favorite thing about this pull request is that the benchmarks used to deduce the savings were included in the description. Not only does it mean we can all learn from the PR, but we can all test it independently. This openness allowed anyone to run the code, apply the patch, and separately verify the savings. This is what attracted me to investigate the Rubygems behavior in the first place. This post is born out of the raw notes I took while evaluating the pull request. Finally, I really enjoy that this performance work came from finding and reporting a performance bug. Why don’t we as Rubyists spend half of the time benchmarking and finding performance bugs as we do complaining about slowness?

I wrote up my first draft of this article right before the announcement of RubyTogether which seeks to do many things, including helping to make rubygems.org sustainable.

It’s important for people outside of a project’s core developers to read over and make sense of popular pull requests. It’s a great way for you to learn about new tools and techniques, but it’s also a good time to learn about how different internal parts of projects work. I encourage you to go find a PR you don’t totally understand: take some notes, dig in, and learn something. The best part of open source contributions aren’t just that we benefit from other’s work, we get to see how that work came to be, and we get a chance to make ourselves better.

If you like open source and Ruby, follow @schneems. If you want to dig into open source issues and pull requests subscribe to codetriage.com.