Vagrant: Commit 50c4464 in Vagrant v2.2.5 introduced a performance issue

[mika]

Starting with Vagrant v2.2.5 we have a major usability issue in our environment. I tracked down the underlying issue to commit https://github.com/hashicorp/vagrant/commit/50c4464d442f35a139ffa5ca916de5b2eb0966aa

In our environment we dynamically define many Vagrant box/VM names (for all kinds of different Debian releases combined with custom product versions) in one single repository, using e.g. a helper function get_box_url to define the actual box_url. Starting with Vagrant v2.2.5 during each vagrant up $SOME_VM run AFAICT it tries to check for configured plugins in all machine configurations (which is taking looooong in our situation).

Vagrant version

Vagrant 2.2.5

Host operating system

Debian/stretch

Guest operating system

Debian (shouldn't matter though)

Vagrantfile

This is a minimal working example (disclaimer: it doesn't make any sense as such, but it demonstrates the problem and simulates our situation):

$releases = [ "fake1", "fake2", "fake3", "fake4", "fake5", "fake6", "fake7", "fake8", "stretch"]

def get_box_url(box_path)
  puts("Simulating hitting " + box_path)
  return "https://vagrantcloud.com/debian/boxes/stretch64/versions/9.2.0/providers/virtualbox.box"
end

Vagrant.configure("2") do |config|
  vm_types = { }

  $releases.each do |rl|
    ce =  "ce-" + rl
    sp1 = "pro-" + rl + "-sp1"
    sp2 = "pro-" + rl + "-sp2"
    vm_types[ce]  =  { :url => "https://vagrantcloud.com/debian/boxes/stretch64/versions/9.0.0/providers/virtualbox.box" }                                                                                         
    vm_types[sp1]  = { :url => "https://vagrantcloud.com/debian/boxes/stretch64/versions/9.1.0/providers/virtualbox.box" }
    vm_types[sp2]  = { :url => "https://vagrantcloud.com/debian/boxes/stretch64/versions/9.2.0/providers/virtualbox.box" }
  end

  vm_types.each do |vmtype, vmdata|
    config.vm.define vmtype do |vmconf|
      vmconf.vm.box = vmtype
      vmconf.vm.box_url = get_box_url(vmdata[:url])
    end
  end
end

Expected behavior

When I replace the config_plugins = find_configured_plugins inside environment.rb of Vagrant >=2.2.5 with its older version config_plugins = vagrantfile.config.vagrant.plugins (as present in Vagrant <= v2.2.4) it's working fine for us.

With the working Vagrant version (<=2.2.4) it looks like that:

% vagrant up ce-stretch            
Simulating hitting https://vagrantcloud.com/debian/boxes/stretch64/versions/9.0.0/providers/virtualbox.box
Bringing machine 'ce-stretch' up with 'virtualbox' provider...
==> ce-stretch: Box 'ce-stretch' could not be found. Attempting to find and install...
    ce-stretch: Box Provider: virtualbox
    ce-stretch: Box Version: >= 0
==> ce-stretch: Waiting for cleanup before exiting...
==> ce-stretch: Box file was not detected as metadata. Adding it directly...
==> ce-stretch: Adding box 'ce-stretch' (v0) for provider: virtualbox
    ce-stretch: Downloading: https://vagrantcloud.com/debian/boxes/stretch64/versions/9.2.0/providers/virtualbox.box
[...]

Actual behavior

With the failing Vagrant version (>=2.2.5) it looks like that:

% vagrant up ce-stretch
Simulating hitting https://vagrantcloud.com/debian/boxes/stretch64/versions/9.0.0/providers/virtualbox.box
Simulating hitting https://vagrantcloud.com/debian/boxes/stretch64/versions/9.1.0/providers/virtualbox.box
Simulating hitting https://vagrantcloud.com/debian/boxes/stretch64/versions/9.2.0/providers/virtualbox.box
Simulating hitting https://vagrantcloud.com/debian/boxes/stretch64/versions/9.0.0/providers/virtualbox.box
Simulating hitting https://vagrantcloud.com/debian/boxes/stretch64/versions/9.1.0/providers/virtualbox.box
Simulating hitting https://vagrantcloud.com/debian/boxes/stretch64/versions/9.2.0/providers/virtualbox.box
Simulating hitting https://vagrantcloud.com/debian/boxes/stretch64/versions/9.0.0/providers/virtualbox.box
Simulating hitting https://vagrantcloud.com/debian/boxes/stretch64/versions/9.1.0/providers/virtualbox.box
Simulating hitting https://vagrantcloud.com/debian/boxes/stretch64/versions/9.2.0/providers/virtualbox.box
Simulating hitting https://vagrantcloud.com/debian/boxes/stretch64/versions/9.0.0/providers/virtualbox.box
Simulating hitting https://vagrantcloud.com/debian/boxes/stretch64/versions/9.1.0/providers/virtualbox.box
Simulating hitting https://vagrantcloud.com/debian/boxes/stretch64/versions/9.2.0/providers/virtualbox.box
Simulating hitting https://vagrantcloud.com/debian/boxes/stretch64/versions/9.0.0/providers/virtualbox.box
Simulating hitting https://vagrantcloud.com/debian/boxes/stretch64/versions/9.1.0/providers/virtualbox.box
Simulating hitting https://vagrantcloud.com/debian/boxes/stretch64/versions/9.2.0/providers/virtualbox.box
Simulating hitting https://vagrantcloud.com/debian/boxes/stretch64/versions/9.0.0/providers/virtualbox.box
Simulating hitting https://vagrantcloud.com/debian/boxes/stretch64/versions/9.1.0/providers/virtualbox.box
Simulating hitting https://vagrantcloud.com/debian/boxes/stretch64/versions/9.2.0/providers/virtualbox.box
Simulating hitting https://vagrantcloud.com/debian/boxes/stretch64/versions/9.0.0/providers/virtualbox.box
Simulating hitting https://vagrantcloud.com/debian/boxes/stretch64/versions/9.1.0/providers/virtualbox.box
Simulating hitting https://vagrantcloud.com/debian/boxes/stretch64/versions/9.2.0/providers/virtualbox.box
Simulating hitting https://vagrantcloud.com/debian/boxes/stretch64/versions/9.0.0/providers/virtualbox.box
Simulating hitting https://vagrantcloud.com/debian/boxes/stretch64/versions/9.1.0/providers/virtualbox.box
Simulating hitting https://vagrantcloud.com/debian/boxes/stretch64/versions/9.2.0/providers/virtualbox.box
Simulating hitting https://vagrantcloud.com/debian/boxes/stretch64/versions/9.0.0/providers/virtualbox.box
Simulating hitting https://vagrantcloud.com/debian/boxes/stretch64/versions/9.1.0/providers/virtualbox.box
Simulating hitting https://vagrantcloud.com/debian/boxes/stretch64/versions/9.2.0/providers/virtualbox.box
Bringing machine 'ce-stretch' up with 'virtualbox' provider...
==> ce-stretch: Box 'ce-stretch' could not be found. Attempting to find and install...
    ce-stretch: Box Provider: virtualbox
    ce-stretch: Box Version: >= 0
==> ce-stretch: Waiting for cleanup before exiting...
==> ce-stretch: Box file was not detected as metadata. Adding it directly...
==> ce-stretch: Adding box 'ce-stretch' (v0) for provider: virtualbox
    ce-stretch: Downloading: https://vagrantcloud.com/debian/boxes/stretch64/versions/9.2.0/providers/virtualbox.box
[...]

Steps to reproduce

1. Set up provided Vagrantfile
2. Execute vagrant up ce-stretch with Vagrant v2.2.4 vs. v2.2.5 (or replace config_plugins = find_configured_plugins with config_plugins = vagrantfile.config.vagrant.plugins inside /opt/vagrant/embedded/gems/2.2.5/gems/vagrant-2.2.5/lib/vagrant/environment.rb)

Is there any chance to get the old behavior back, or make this config_plugins behavior configurable?

Thanks for Vagrant!

[chrisroberts]

Hi!

After reviewing this issue with the provided Vagrantfile (thanks for that!) I have determined that the behavior is expected. Vagrantfiles can be (and many times are) evaluated more than once during a run. The difference now (introduced in the last release) is that we are running a basic evaluation at the start so we can detect any configured plugins properly. Given the example you provided, it's understandable how this re-evaluation can cause things to slow down. However, this impact can easily be mitigated by modifying the local implementation details within the Vagrantfile.

Taking the provided Vagrantfile above, we can adjust the get_box_url method to cache the lookup results instead of repeatedly performing the same task:

def get_box_url(box_path)
  @lookups ||= {}
  if @lookups[box_path].nil?
    puts("Simulating hitting " + box_path)
    @lookups[box_path] = "https://vagrantcloud.com/debian/boxes/stretch64/versions/9.2.0/providers/virtualbox.box"
  end
  @lookups[box_path]
end

and now when we up the guest, only three actual lookups are performed:

> vagrant up ce-stretch
Simulating hitting https://vagrantcloud.com/debian/boxes/stretch64/versions/9.0.0/providers/virtualbox.box
Simulating hitting https://vagrantcloud.com/debian/boxes/stretch64/versions/9.1.0/providers/virtualbox.box
Simulating hitting https://vagrantcloud.com/debian/boxes/stretch64/versions/9.2.0/providers/virtualbox.box

Bringing machine 'ce-stretch' up with 'virtualbox' provider...
==> ce-stretch: Box 'ce-stretch' could not be found. Attempting to find and install...
    ce-stretch: Box Provider: virtualbox
    ce-stretch: Box Version: >= 0
^C==> ce-stretch: Box file was not detected as metadata. Adding it directly...
==> ce-stretch: Waiting for cleanup before exiting...
==> ce-stretch: Adding box 'ce-stretch' (v0) for provider: virtualbox
    ce-stretch: Downloading: https://vagrantcloud.com/debian/boxes/stretch64/versions/9.2.0/providers/virtualbox.box
==> ce-stretch: Exiting immediately, without cleanup!
==> ce-stretch: Box download was interrupted. Exiting.

Cheers!

[kraigstrong]

@chrisroberts Thank you for providing some information on this issue, but I believe there is another performance hit aside from reaching out to perform box lookups.

I was experiencing a similar issue, and I implemented the caching as suggested, and that has helped by not reaching out over the network several times, but the latest implementation is still a few orders of magnitude slower for my Vagrantfile.

We have a Vagrantfile similar to the example posted above, but it contains a few hundred VMs that it defines so that we can create any one of our templates at will from a single Vagrantfile. After the configuration completes (which is now faster based on your caching suggestion), it goes through every possible machine defined to find configured plugins. From the same commit that @Mika pointed out, it's looping on this function https://github.com/hashicorp/vagrant/commit/50c4464d442f35a139ffa5ca916de5b2eb0966aa#diff-9a9f994a7f12cdd1d9505de5993c783aR953

I added a small print to that function to confirm that it is called on every machine, and not just the machine that you're currently interacting with.

In the above example, performing vagrant up ce-stretch would define all of the boxes, but then on this call: https://github.com/hashicorp/vagrant/commit/50c4464d442f35a139ffa5ca916de5b2eb0966aa#diff-9a9f994a7f12cdd1d9505de5993c783aR956-R959 would iterate over ce-stretch, sp1-stretch, sp2-stretch.

In the Vagrantfile that I'm testing with ~200 VMs defined, it takes ~4 seconds to call vagrant ssh <vm_name> when I change config_plugins = find_configured_plugins to config_plugins = vagrantfile.config.vagrant.plugins. With default Vagrant 2.2.5, it takes ~6 minutes, even after the caching suggestion is applied.

[mika]

@chrisroberts @kraigstrong same here, just tried it with the caching (thanks for providing this snippet!), but since it's "checking" for every single defined VM it still takes _way_ longer with v2.2.5 than with version v2.2.4, so I'd appreciate if the issue could be reopened.

[taurus-forever]

Dear @chrisroberts @briancain, can you please reopen the ticket here, as the suggested workaround doesn't help. Both vagrant releases 2.2.5 and 2.2.6 are broken for our use cases.

Thank you in advance!

[taurus-forever]

For the history, for other folks who struggling here, our workaround in Vagrantfile for now is:

+# XXX: We need to replace this function which is the one showing the
+# regression with the old implementation so that we can restore sane
+# behavior again.
+module Vagrant
+  class Environment
+    # Load any configuration provided by guests defined within
+    # the Vagrantfile to pull plugin information they may have
+    # defined.
+    def find_configured_plugins
+      config_plugins = vagrantfile.config.vagrant.plugins
+      config_plugins.each do |name, info|
+        if !installed[name]
+          needs_install << name
+        end
+      end
+    end
+  end
+end

P.S tnx to @guillemj for the workaround here!

[hashibot[bot]]

I'm going to lock this issue because it has been closed for _30 days_ ⏳. This helps our maintainers find and focus on the active issues.

If you have found a problem that seems similar to this, please open a new issue and complete the issue template so we can capture all the details necessary to investigate further.