Investigate performance regressions on Windows CI

[deivid-rodriguez]

Describe the problem as clearly as you can

This is most likely a third party issue, but it'd be nice to do some research so a proper issue can be reported to ruby-core.

Since we added a Windows CI for bundler, it's been the bottleneck of our CI since it's quite slow.

I can live with that for the moment, but a first observation is that CI seems consistently 50% slower on Windows 2.5-2.7 that on Windows 2.4.

So maybe there's some performance regression on ruby on Windows that we could report to ruby-core and if fixed, it would not only benefit our CI, but windows ruby users in general.

This is mostly likely related to process creation which seems particularly slow on Windows, and which bundler CI makes heavy use of.

Post steps to reproduce the problem

Go to the "Actions" tab and compare the build times of bundler on windows.

[djberg96]

Do we have a general benchmarking suite for rubygems? Should we add one?

[deivid-rodriguez]

Any improvements you feel worth adding are welcome 🤷‍♂️. I just noticed this issue because I know windows is inherently slow when it comes to launching processes from ruby, but it could certainly be faster, since ruby 2.4 was.

[djberg96]

Maybe we could use something like this? https://github.com/nmeans/minitest-profile

[MSP-Greg]

Having experienced this before, and also having just switched to a new desktop, tried locally. Installing gems runs an endless loop? Was on current master...

I've also got Ubuntu 20.04 running, so busy with that...

[deivid-rodriguez]

@MSP-Greg Sorry I never got back to you about this. How did you try to install gems? To get setup, you should

• Clone the repo.
• rake setup from the root folder.
• cd bundler.
• bin/rake spec:parallel_deps.
• bin/parallel_rspec.

Running specs on Windows is very slow, you I think more like an endless loop, it's a slow loop 😅.

The problem is that, talking about our CI, while specs take ~40 minutes on Ruby 2.4, they take ~1h or more on later rubies. I guess you could try running subsets of the suite like a single file, or a single spec, and see if that 50% decrease in performance is maintained. That would go a long way in being closer to produce something easily reproducible the can be reported to ruby-core.

[MSP-Greg]

@deivid-rodriguez

As to the Windows speed, using the Windows file system with Ruby is slow, and Bundler CI creates a lot of small files.

How did you try to install gems?

I can't recall.

Sorry I never got back to you about this.

No problem. You're doing a lot of great work here.

I've still got a lot of code running under Windows Ruby (like https://msp-greg.github.io/), but I spend more time in WSL2/Ubuntu (which has things like fork, UNIXSocket, etc).

I'll try to revisit things in a few days. I think...

[djberg96]

I'm wondering why running the bundler specs locally takes so long in general. Even on my Mac, I saw this:

Top 3 slowest examples (4852.22 seconds, 62.5% of total time):
  compact index api fetches again when more dependencies are found in subsequent sources
    2711.28 seconds ./spec/install/gems/compact_index_spec.rb:286
  bundle outdated with --group option returns a sorted list of outdated gems from one group => 'development'
    1810.13 seconds ./spec/commands/outdated_spec.rb:265
  bundle lock with git gems locks a git source to the current ref
    330.81 seconds ./spec/lock/git_spec.rb:17

Top 3 slowest example groups:
  bundle lock with git gems
    111.03 seconds average (333.1 seconds / 3 examples) ./spec/lock/git_spec.rb:3
  compact index api
    47.65 seconds average (2811.29 seconds / 59 examples) ./spec/install/gems/compact_index_spec.rb:3
  bundle outdated
    29.43 seconds average (1972.07 seconds / 67 examples) ./spec/commands/outdated_spec.rb:3

Finished in 129 minutes 22 seconds (files took 1.39 seconds to load)

I'll post my Windows results once it's finished, but it's been running for hours at this point.

[deivid-rodriguez]

Top 3 slowest examples (4852.22 seconds, 62.5% of total time):
compact index api fetches again when more dependencies are found in subsequent sources
2711.28 seconds ./spec/install/gems/compact_index_spec.rb:286
bundle outdated with --group option returns a sorted list of outdated gems from one group => 'development'
1810.13 seconds ./spec/commands/outdated_spec.rb:265
bundle lock with git gems locks a git source to the current ref
330.81 seconds ./spec/lock/git_spec.rb:17

Wow, 3 specs took 62.5% of your tests runtime time. There's definitely something going on there. If you rerun tests, do you get similar results?

Bundler tests are indeed very slow, because they are all integration tests which completely run bundler from scracth inside a subprocess and then check the outcome, sometimes many times per test. Recently we parallelized the test suite (you have to run it using bin/parallel_rspec) and it's still bad, but not that bad. The whole suite takes 10-15 minutes on my machine.

[djberg96]

Hm, parallel_rspec didn't seem to work for me:

>bin/rspec bin/parallel_rspec 

An error occurred while loading ./bin/parallel_rspec.
Failure/Error: load Gem.bin_path(gem_name, bin_container)

LoadError:
  cannot load such file -- parallel_tests/rspec/runner
# ./tool/turbo_tests/runner.rb:5:in `<top (required)>'
# ./tool/turbo_tests.rb:8:in `require_relative'
# ./tool/turbo_tests.rb:8:in `<top (required)>'
# ./tool/turbo_tests/cli.rb:3:in `require_relative'
# ./tool/turbo_tests/cli.rb:3:in `<top (required)>'
# ./spec/support/rubygems_ext.rb:99:in `load'
# ./spec/support/rubygems_ext.rb:99:in `gem_load_and_activate'
# ./spec/support/rubygems_ext.rb:18:in `gem_load'
Run options: exclude {:truffleruby=>true, :jruby=>true, :readline=>false, :permissions=>false, :no_color_tty=>false, :ruby_repo=>false, :bundler=>"!= 2", :git=>"!= 2.28.0", :realworld=>true, :sudo=>true}

[deivid-rodriguez]

Just bin/parallel_rspec, you don't run it through rspec, it's a binstub of its own.

[djberg96]

Same:

>bin/parallel_rspec          
<internal:/Users/dberger/.rbenv/versions/3.0.2/lib/ruby/site_ruby/3.0.0/rubygems/core_ext/kernel_require.rb>:85:in `require': cannot load such file -- parallel_tests/rspec/runner (LoadError)
	from <internal:/Users/dberger/.rbenv/versions/3.0.2/lib/ruby/site_ruby/3.0.0/rubygems/core_ext/kernel_require.rb>:85:in `require'
	from /Users/dberger/Dev/rubygems-djberg96/bundler/tool/turbo_tests/runner.rb:5:in `<top (required)>'
	from /Users/dberger/Dev/rubygems-djberg96/bundler/tool/turbo_tests.rb:8:in `require_relative'
	from /Users/dberger/Dev/rubygems-djberg96/bundler/tool/turbo_tests.rb:8:in `<top (required)>'
	from /Users/dberger/Dev/rubygems-djberg96/bundler/tool/turbo_tests/cli.rb:3:in `require_relative'
	from /Users/dberger/Dev/rubygems-djberg96/bundler/tool/turbo_tests/cli.rb:3:in `<top (required)>'
	from bin/parallel_rspec:6:in `require_relative'
	from bin/parallel_rspec:6:in `<main>'

BTW, running the specs locally again on my Mac were faster, down to about an hour:

Top 3 slowest examples (82.65 seconds, 2.1% of total time):
  bundle install --standalone run in a subdirectory with default gems and a lockfile works
    31.99 seconds ./spec/install/gems/standalone_spec.rb:144
  bundle install --standalone with default gems and a lockfile works
    26.12 seconds ./spec/install/gems/standalone_spec.rb:144
  compact index api does not double check for gems that are only installed locally
    24.53 seconds ./spec/install/gems/compact_index_spec.rb:247

Top 3 slowest example groups:
  global gem caching
    5.34 seconds average (32.02 seconds / 6 examples) ./spec/install/global_cache_spec.rb:3
  bundle update conservative
    4.82 seconds average (62.62 seconds / 13 examples) ./spec/commands/update_spec.rb:1060
  bundle pristine
    4.51 seconds average (58.57 seconds / 13 examples) ./spec/commands/pristine_spec.rb:5

Finished in 65 minutes 15 seconds (files took 2.2 seconds to load)
3204 examples, 0 failures, 12 pending

Randomized with seed 20863

[djberg96]

Windows bundler tests seemed to be hung up on something until I manually hit the return key this morning, then they progressed again. Still running....

[deivid-rodriguez]

You need to run bin/rake spec:parallel_deps before running bin/parallel_rspec.

[djberg96]

You need to run bin/rake spec:parallel_deps before running bin/parallel_rspec.

Aha, thanks. Any chance we could update the CONTRIBUTING.md file with this tidbit?

[djberg96]

Definitely ran faster with parallel_rspec, though it does generate confused output in conjunction with the --profile option.

[deivid-rodriguez]

Aha, thanks. Any chance we could update the CONTRIBUTING.md file with this tidbit?

I thought it was already documented, we should definitely update CONTRIBUTING.md 👍.

[deivid-rodriguez]

Updated! #4831

[djberg96]

FWIW, keeping in mind that I think one of these was "stuck" until I manually hit a carriage return.

Top 10 slowest examples (24226.81 seconds, 28.3% of total time):
  bundle info with a standard Gemfile prints path if gem exists in bundle
    9966.12 seconds ./spec/commands/info_spec.rb:43
  bundle exec handles gems installed with --without
    8708.38 seconds ./spec/commands/exec_spec.rb:314
  bundle update in more complicated situations when the lockfile is for a different platform allows updating
    2013.52 seconds ./spec/commands/update_spec.rb:834
  Bundler.setup after setup takes care of requiring rubygems
    1959.08 seconds ./spec/runtime/setup_spec.rb:1429
  bundle install from an existing gemspec should evaluate the gemspec in its directory
    1257.69 seconds ./spec/install/gemfile/gemspec_spec.rb:186
  Bundler#requires_sudo? bundle_path doesn't exist and parent dir can't be written is expected to equal true
    109.88 seconds ./spec/bundler/bundler_spec.rb:304
  global gem caching using the cross-application user cache when the same gem from different sources is installed should
 use the appropriate one from the global cache
    58.77 seconds ./spec/install/global_cache_spec.rb:41
  bundle binstubs <gem> when the gem exists in the lockfile the bundle binstub when BUNDLER_VERSION is set runs the corr
ect version of bundler even if a higher version is installed
    52.27 seconds ./spec/commands/binstubs_spec.rb:147
  bundle executable printing the outdated warning when the latest version is less than the current version prints no war
ning
    51.75 seconds ./spec/bundler/cli_spec.rb:134
  bundle check BUNDLED WITH is older does not change the lock
    49.35 seconds ./spec/commands/check_spec.rb:431

Top 10 slowest example groups:
  Resolving platform craziness
    2249.6 seconds average (44992.09 seconds / 20 examples) ./spec/resolver/platform_spec.rb:3
  bundle info
    671.41 seconds average (10071.17 seconds / 15 examples) ./spec/commands/info_spec.rb:3
  bundle update in more complicated situations
    258.17 seconds average (2065.35 seconds / 8 examples) ./spec/commands/update_spec.rb:707
  Bundler.require with platform specific dependencies
    111.26 seconds average (222.52 seconds / 2 examples) ./spec/runtime/require_spec.rb:435
  bundle exec
    90.66 seconds average (9156.63 seconds / 101 examples) ./spec/commands/exec_spec.rb:3
  bundle install from an existing gemspec
    59.64 seconds average (1431.25 seconds / 24 examples) ./spec/install/gemfile/gemspec_spec.rb:3
  global gem caching
    24.49 seconds average (146.92 seconds / 6 examples) ./spec/install/global_cache_spec.rb:3
  hook plugins
    20.71 seconds average (82.83 seconds / 4 examples) ./spec/plugins/hook_spec.rb:3
  bundle update
    19.71 seconds average (630.73 seconds / 32 examples) ./spec/commands/update_spec.rb:3
  Bundler.setup
    18.94 seconds average (3220.36 seconds / 170 examples) ./spec/runtime/setup_spec.rb:6

[deivid-rodriguez]

I think it's the first test of each parallel run that it's very slow, because dummy test repos are built on the fly and they are apparently quite costly to build. I have an idea on how to improve that.