Berkshelf gem require slow - Vagrantfile

berkshelf-gem-require.md

After installing vagrant-berkshelf, running vagrant executable has a 2+ second lag:

for N in {1..3} ; do time vagrant ; done
#    real	0m2.830s
#    real	0m2.524s
#    real	0m2.531s

vagrant plugin list
#    vagrant-berkshelf (1.3.3)
#    vagrant-cachier (0.1.0)
#    vagrant-digitalocean (0.1.2)
#    vagrant-omnibus (1.0.2)
#    vagrant-vbox-snapshot (0.0.4)
#    vagrant-vboxmanage (0.0.2)

vagrant plugin uninstall vagrant-berkshelf

for N in {1..3} ; do time vagrant ; done
#    real	0m0.731s
#    real	0m0.744s
#    real	0m0.721s

vagrant plugin install librarian-chef

for N in {1..3} ; do time vagrant ; done
#    real	0m0.909s
#    real	0m0.938s
#    real	0m0.942s

Clearly the problem is vagrant-berkshelf, the fact that it requires a huge amount of dependent gems unconditionally.

Here's one way to look at the bloat:

mkdir -p ~/code/berkshelf-debug
cd ~/code/berkshelf-debug
git clone https://github.com/RiotGames/vagrant-berkshelf.git
cd vagrant-berkshelf

# install all dependent gems to a local folder; takes a minute or 2
bundle install --path=./vendor

ls vendor/ruby/2.0.0/gems | wc -l
#    75 gems

There are 75 (!!) gems that are downloaded as dependencies.

Here's a Vagrantfile that will help measure why it's slow:

if ENV['PROFILE_REQUIRE']
  require 'benchmark'
  module Kernel
      # make an alias of the original require
    alias_method :original_require, :require

    # rewrite require
    def require name
      time = (Benchmark.realtime { original_require name } * 1000).round
      if time > 50
        $stderr.puts "#{time} MS elapsed requiring #{name}"
      end
    end
  end
end

# not using Vagrant.require_plugin because it suppresses STDOUT
require "vagrant-berkshelf"

Vagrant.configure("2") do |config|
  config.vm.box = "precise64"
end

Let's install it and see what the culprits are. Additionally, we run a few diagnostic benchmarks to get a sense for the overhead of using bundler, etc:

cd ~/code/berkshelf-debug/vagrant-berkshelf

time ruby -e 'require "json"'
#    real	0m0.112s

time bundle exec ruby -e 'require "json"'
#    real	0m1.064s

time bundle exec ruby -e 'require "vagrant-berkshelf"'
#    real 0m1.967s

time vagrant
#    real 0m0.848s

time bundle exec vagrant
#    real	0m1.179s

# now lets add a Vagrantfile that requires vagrant-berkshelf
# and supports PROFILE_REQUIRE env variable
wget https://gist.github.com/dergachev/6770076/raw/Vagrantfile

time bundle exec vagrant
#    real	0m2.121s

time PROFILE_REQUIRE=1 bundle exec vagrant
#    real	0m2.198s

The output from the invocation with PROFILE_REQUIRE=1 was:

72 MS elapsed requiring celluloid
53 MS elapsed requiring psych
55 MS elapsed requiring yaml
78 MS elapsed requiring net/ssh
57 MS elapsed requiring httpclient/auth
79 MS elapsed requiring httpclient
58 MS elapsed requiring nokogiri/xml
103 MS elapsed requiring nokogiri
106 MS elapsed requiring wasabi/document
107 MS elapsed requiring wasabi
108 MS elapsed requiring savon/wasabi/document
77 MS elapsed requiring nori/xml_utility_node
83 MS elapsed requiring nori
85 MS elapsed requiring savon/soap/xml
234 MS elapsed requiring savon/client
237 MS elapsed requiring savon
353 MS elapsed requiring winrm/soap_provider
422 MS elapsed requiring winrm
776 MS elapsed requiring ridley
991 MS elapsed requiring berkshelf
1000 MS elapsed requiring berkshelf/vagrant
1001 MS elapsed requiring vagrant-berkshelf

From the above, it's obvious that winrm is a major part of the problem. In general though, we could shave 900ms if vagrant-berkshelf would only require berkshelf if it needs it. (However, my familiarity with berkshelf is insufficient to take a stab at this).

Resources

Related to Benchmark and gems:

• http://stackoverflow.com/questions/15661788/how-to-override-require-in-ruby
• http://stackoverflow.com/questions/4736546/rails-3-osx-speed-up-console-loading-time

Related to vagrant-berkshelf performance:

• hashicorp/vagrant#1810
• berkshelf/berkshelf#540

Vagrantfile

if ENV['PROFILE_REQUIRE']
  require 'benchmark'
  module Kernel
      # make an alias of the original require
    alias_method :original_require, :require

    # rewrite require
    def require name
      time = (Benchmark.realtime { original_require name } * 1000).round
      if time > 50
        $stderr.puts "#{time} MS elapsed requiring #{name}"
      end
    end
  end
end

# not using Vagrant.require_plugin because it suppresses STDOUT
require "vagrant-berkshelf"

Vagrant.configure("2") do |config|
  config.vm.box = "precise64"
end