Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Speed up complex dependency resolves by creating DepProxy factory and cache #4216

Merged
merged 5 commits into from Jan 13, 2021

Conversation

lukaso
Copy link
Contributor

@lukaso lukaso commented Dec 30, 2020

What was the end-user or developer problem that led to this PR?

Running some (relatively complex) resolution cases can lead to extremely poor performance of Resolving dependencies. Here is a trivial case to reproduce this which runs in 22 minutes on my laptop.

Gemfile

source 'https://rubygems.org'

gem "actionmailer"
gem "mongoid", ">= 0.10.2"

The same problem has been seen in the real world at Simply Business where we have repeatedly run into resolution taking excessively long or even hanging.

What is your fix for the problem, implemented in this PR?

Solution

The solution in this PR takes the above case from 22 minutes to 1 minute 32 seconds (on my laptop).

On other runs with different gem files, I've seen improvements including a 30% improvement and a 5 x improvement.

For the general case, there is no performance implications.

The basic solution (I will describe the diagnostics below) that led me to this requires two things:

  1. Dedup DepProxy by creating a factory method and comparing requests for new DepProxys to existing proxies (which creates a high cache hit rate). The using the hash of the objects to cache. This also allows comparison of two exactly the same DepProxys to use the inbuilt Object#== which is very fast. This does mean that the objects are now shared. If they were immutable before, this would be totally fine, but even if they aren't, it appears not to cause problems.
  2. Changing the Molinillo build_details_for_unwind in resolution.rb with an implementation for relevant_unused_unwinds that uses Array#- which takes advantage of object comparison rather than Array#& which uses Array#hash and in this case is substantially slower. Without the Molinillo change, the DepProxy factory is performance neutral.

build_details_for_unwind and specifically Array#& were where most of the time in the cases above were spent, as the analysis will demonstrate.

Note on the PR

I present the full PR with vendored changes, assuming if you would like to move forward I would submit a PR to Molinillo.

Analysis

The added slow_perf_spec.rb can run against this branch or master. On this branch it runs in:

Finished in 4 minutes 37 seconds (files took 0.25304 seconds to load)

On master it runs:

Finished in 6 minutes 29 seconds (files took 0.27068 seconds to load)

This gives a savings of two minutes or ~ 30%.

Here is the output of the old and new algorithms:

DepProxy branch

$ rm Gemfile.lock; time ~/projects/rubygems/bundler/bin/bundle --gemfile=Gemfile
Fetching gem metadata from https://rubygems.org/........
Resolving dependencies...............
Using concurrent-ruby 1.1.7
Using minitest 5.14.2
Using zeitwerk 2.4.2
Using builder 3.2.4
Using erubi 1.10.0
Using mini_portile2 2.4.0
Using crass 1.0.6
Using rack 2.2.3
Using mini_mime 1.0.2
Using bson 4.11.1
Using bundler 2.3.0.dev
Using leshill-will_paginate 2.3.11
Using durran-validatable 2.0.1
Using i18n 1.8.5
Using nokogiri 1.10.10
Using tzinfo 2.0.4
Using loofah 2.8.0
Using activesupport 6.1.0
Using mongo 2.14.0
Using rails-html-sanitizer 1.3.0
Using rack-test 1.1.0
Using mail 2.7.1
Using globalid 0.4.2
Using rails-dom-testing 2.0.3
Using activejob 6.1.0
Using actionview 6.1.0
Using actionpack 6.1.0
Using mongoid 1.0.6
Using actionmailer 6.1.0
Bundle complete! 2 Gemfile dependencies, 29 gems now installed.
Use `bundle info [gemname]` to see where a bundled gem is installed.

real	1m31.824s
user	1m30.883s
sys	0m0.497s

Master branch

$ rm Gemfile.lock; time ~/projects/rubygems/bundler/bin/bundle --gemfile=Gemfile
Fetching gem metadata from https://rubygems.org/........
Resolving dependencies........................
Using concurrent-ruby 1.1.7
Using minitest 5.14.2
Using zeitwerk 2.4.2
Using builder 3.2.4
Using erubi 1.10.0
Using mini_portile2 2.4.0
Using crass 1.0.6
Using rack 2.2.3
Using mini_mime 1.0.2
Using bson 4.11.1
Using bundler 2.3.0.dev
Using leshill-will_paginate 2.3.11
Using durran-validatable 2.0.1
Using i18n 1.8.5
Using tzinfo 2.0.4
Using nokogiri 1.10.10
Using activesupport 6.1.0
Using mail 2.7.1
Using rails-dom-testing 2.0.3
Using rack-test 1.1.0
Using globalid 0.4.2
Using mongo 2.14.0
Using loofah 2.8.0
Using activejob 6.1.0
Using rails-html-sanitizer 1.3.0
Using mongoid 1.0.6
Using actionview 6.1.0
Using actionpack 6.1.0
Using actionmailer 6.1.0
Bundle complete! 2 Gemfile dependencies, 29 gems now installed.
Use `bundle info [gemname]` to see where a bundled gem is installed.

real	22m27.811s
user	22m15.555s
sys	0m4.723s

The results of running ruby-prof on master and on the new branch

Original implementation
Measure Mode: wall_time
Thread ID: 70207129452500
Fiber ID: 70207121129620
Total: 514.729486
Sort by: self_time

 %self      total      self      wait     child     calls  name                           location
 54.20    481.506   278.970     0.000   202.536  2230632   Array#&
 38.29    197.141   197.101     0.000     0.039 870039195   Bundler::DepProxy#hash         /Users/lukas.oberhuber/projects/rubygems/bundler/lib/bundler/dep_proxy.rb:12
  0.95     12.820     4.877     0.000     7.943  7039049   Bundler::DepProxy#eql?         /Users/lukas.oberhuber/projects/rubygems/bundler/lib/bundler/dep_proxy.rb:16
  0.72    493.137     3.682     0.000   489.455   233778  *Array#select
  0.65      7.320     3.367     0.000     3.953  8345705   Gem::Dependency#==             /Users/lukas.oberhuber/.rbenv/versions/2.6.5/lib/ruby/2.6.0/rubygems/dependency.rb:173
  0.37      2.953     1.899     0.000     1.054  2239519   Bundler::Molinillo::Resolver::Resolution::UnwindDetails#<=> /Users/lukas.oberhuber/projects/rubygems/bundler/lib/bundler/vendor/molinillo/lib/molinillo/resolution.rb:83
  0.37     10.352     1.884     0.000     8.469   138522  *Array#each
  0.36      1.876     1.876     0.000     0.000 15642359   Bundler::Molinillo::Resolver::Resolution::UnwindDetails#state_index
  ...
With adding a DepProxy factory
Measure Mode: wall_time
Thread ID: 70284950585360
Fiber ID: 70284980000360
Total: 97.786107
Sort by: self_time

 %self      total      self      wait     child     calls  name                           location
 76.78     75.077    75.077     0.000     0.000  2327396   Array#-
  3.54     85.954     3.465     0.000    82.489    95397   Array#select
  1.87      2.805     1.831     0.000     0.974  2239519   Bundler::Molinillo::Resolver::Resolution::UnwindDetails#<=> /Users/lukas.oberhuber/projects/rubygems/bundler/lib/bundler/vendor/molinillo/lib/molinillo/resolution.rb:83
  1.83      1.789     1.789     0.000     0.000 15642359   Bundler::Molinillo::Resolver::Resolution::UnwindDetails#state_index
  1.81      9.044     1.774     0.000     7.270   138532  *Array#each
  0.95      1.570     0.928     0.000     0.642   260374   Gem::Version#<=>               /Users/lukas.oberhuber/.rbenv/versions/2.6.5/lib/ruby/2.6.0/rubygems/version.rb:342
  0.87      0.852     0.852     0.000     0.000  4454118   Bundler::Molinillo::Resolver::Resolution::UnwindDetails#requirements_unwound_to_instead
  0.74      3.494     0.720     0.000     2.774  2218106   Comparable#>
  0.66      1.028     0.650     0.000     0.378   350426   Array#reject!
  ...

Other interesting findings

Interestingly, by switching the mongoid version from >=0.10.2 to >=0.10.3, steps to resolve go from 6264 down to 827 due to picking a different starting requirment (although I haven't analysed the algorithm to understand why the change is triggered). Red or < version is >=0.10.3 and Green or > is >=0.10.2. There is also a dramatic slowdown in dependency resolution between the two options, due to the very slow algorithm (even with the fixes proposed here) related to looking for previous unwind states.

< BUNDLER: Starting resolution (2020-12-30 00:44:11 +0000)
< BUNDLER: User-requested dependencies: [#<Bundler::DepProxy:0x00007fef5f0d8058 @dep=<Bundler::Dependency type=:runtime name="actionmailer" requirements=">= 0">, @__platform=#<Gem::Platform:0x00007fef5f016098 @cpu="x86_64", @os="darwin", @version="19" @cpu="x86_64", @os="darwin", @version="19">, @hash=325717142915182719>, #<Bundler::DepProxy:0x00007fef66073408 @dep=<Bundler::Dependency type=:runtime name="mongoid" requirements=">= 0.10.3">, @__platform=#<Gem::Platform:0x00007fef5f016098 @cpu="x86_64", @os="darwin", @version="19" @cpu="x86_64", @os="darwin", @version="19">, @hash=1448836936842474097>, #<Bundler::DepProxy:0x00007fef66073070 @dep=<Bundler::Dependency type=:runtime name="Ruby\u0000" requirements=">= 0">, @__platform=#<Gem::Platform:0x00007fef5f016098 @cpu="x86_64", @os="darwin", @version="19" @cpu="x86_64", @os="darwin", @version="19">, @hash=-4097237829671024793>, #<Bundler::DepProxy:0x00007fef66072800 @dep=<Bundler::Dependency type=:runtime name="RubyGems\u0000" requirements="= 3.1.4">, @__platform=#<Gem::Platform:0x00007fef5f016098 @cpu="x86_64", @os="darwin", @version="19" @cpu="x86_64", @os="darwin", @version="19">, @hash=-3847635433202042685>]
---
> BUNDLER: Starting resolution (2020-12-30 00:40:45 +0000)
> BUNDLER: User-requested dependencies: [#<Bundler::DepProxy:0x00007fc6070f4518 @dep=<Bundler::Dependency type=:runtime name="actionmailer" requirements=">= 0">, @__platform=#<Gem::Platform:0x00007fc6078f1ec8 @cpu="x86_64", @os="darwin", @version="19" @cpu="x86_64", @os="darwin", @version="19">, @hash=-3111283843832305287>, #<Bundler::DepProxy:0x00007fc60c147dd0 @dep=<Bundler::Dependency type=:runtime name="mongoid" requirements=">= 0.10.2">, @__platform=#<Gem::Platform:0x00007fc6078f1ec8 @cpu="x86_64", @os="darwin", @version="19" @cpu="x86_64", @os="darwin", @version="19">, @hash=-4225324059996933406>, #<Bundler::DepProxy:0x00007fc60c147358 @dep=<Bundler::Dependency type=:runtime name="Ruby\u0000" requirements=">= 0">, @__platform=#<Gem::Platform:0x00007fc6078f1ec8 @cpu="x86_64", @os="darwin", @version="19" @cpu="x86_64", @os="darwin", @version="19">, @hash=-329411114533298518>, #<Bundler::DepProxy:0x00007fc60c146ed0 @dep=<Bundler::Dependency type=:runtime name="RubyGems\u0000" requirements="= 3.1.4">, @__platform=#<Gem::Platform:0x00007fc6078f1ec8 @cpu="x86_64", @os="darwin", @version="19" @cpu="x86_64", @os="darwin", @version="19">, @hash=-3561920153128883523>]
13,20c13,20
< BUNDLER:     Creating possibility state for mongoid (>= 0.10.3) x86_64-darwin-19 (428 remaining)
< BUNDLER:       Attempting to activate [mongoid (7.2.0) (x86_64-darwin-19)]
< BUNDLER:       Activated mongoid at [mongoid (7.2.0) (x86_64-darwin-19)]
< BUNDLER:       Requiring nested dependencies (activemodel (>= 5.1, < 6.1) x86_64-darwin-19, mongo (>= 2.10.5, < 3.0.0) x86_64-darwin-19)
< BUNDLER:       Creating possibility state for actionmailer x86_64-darwin-19 (744 remaining)
< BUNDLER:         Attempting to activate [actionmailer (6.1.0) (x86_64-darwin-19)]
< BUNDLER:         Activated actionmailer at [actionmailer (6.1.0) (x86_64-darwin-19)]
< BUNDLER:         Requiring nested dependencies (activesupport (= 6.1.0) x86_64-darwin-19, actionpack (= 6.1.0) x86_64-darwin-19, actionview (= 6.1.0) x86_64-darwin-19, activejob (= 6.1.0) x86_64-darwin-19, mail (~> 2.5, >= 2.5.4) x86_64-darwin-19, rails-dom-testing (~> 2.0) x86_64-darwin-19)
---
> BUNDLER:     Creating possibility state for actionmailer x86_64-darwin-19 (744 remaining)
> BUNDLER:       Attempting to activate [actionmailer (6.1.0) (x86_64-darwin-19)]
> BUNDLER:       Activated actionmailer at [actionmailer (6.1.0) (x86_64-darwin-19)]
> BUNDLER:       Requiring nested dependencies (activesupport (= 6.1.0) x86_64-darwin-19, actionpack (= 6.1.0) x86_64-darwin-19, actionview (= 6.1.0) x86_64-darwin-19, activejob (= 6.1.0) x86_64-darwin-19, mail (~> 2.5, >= 2.5.4) x86_64-darwin-19, rails-dom-testing (~> 2.0) x86_64-darwin-19)
> BUNDLER:       Creating possibility state for mongoid (>= 0.10.2) x86_64-darwin-19 (430 remaining)
> BUNDLER:         Attempting to activate [mongoid (7.2.0) (x86_64-darwin-19)]
> BUNDLER:         Activated mongoid at [mongoid (7.2.0) (x86_64-darwin-19)]
> BUNDLER:         Requiring nested dependencies (activemodel (>= 5.1, < 6.1) x86_64-darwin-19, mongo (>= 2.10.5, < 3.0.0) x86_64-darwin-19)

Make sure the following tasks are checked

@deivid-rodriguez
Copy link
Member

Oh wow, we definitely want this it's great 🎉! I'll have a detailed look tomorrow 👍.

@indirect
Copy link
Member

Great investigation work here, thanks for the PR!

@lukaso
Copy link
Contributor Author

lukaso commented Dec 30, 2020

My pleasure. Thanks.

@lukaso
Copy link
Contributor Author

lukaso commented Dec 31, 2020

This additional change looks like it took this case from 1m32s down to 10s on my laptop. The requirements_unwound_to_instead array was not being deduplicated on insert.

Copy link
Member

@deivid-rodriguez deivid-rodriguez left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Hei, this is really awesome, thanks soooooo much! ❤️

I made some small comments, but this is going in, soon! I think you can start proposing the molinillo changes upstream 😃.

Also, rubygems has a separate copy of molinillo, maybe it's worth updating that copy too.

bundler/lib/bundler/dep_proxy.rb Outdated Show resolved Hide resolved
bundler/lib/bundler/dep_proxy.rb Outdated Show resolved Hide resolved
bundler/lib/bundler/dep_proxy.rb Outdated Show resolved Hide resolved
bundler/spec/realworld/edgecases_spec.rb Outdated Show resolved Hide resolved
@deivid-rodriguez
Copy link
Member

deivid-rodriguez commented Jan 7, 2021

Ok, I've been working on finishing this up and it's almost ready. I'll force-push to this branch soon.

Current performance on my machine with the problematic Gemfile is ~3 seconds with the molinillo patch, and ~10 seconds without it 🎉.

@simi
Copy link
Member

simi commented Jan 7, 2021

I'll take a look once ready.

@deivid-rodriguez
Copy link
Member

Great! I created a PR to Molinillo: CocoaPods/Molinillo#146. If it passes Molinillo's specs I think we can ship it.

@lukaso
Copy link
Contributor Author

lukaso commented Jan 7, 2021

Ok, I've been working on finishing this up and it's almost ready. I'll force-push to this branch soon.

Current performance on my machine with the problematic Gemfile is ~3 seconds with the molinillo patch, and ~10 seconds without it 🎉.

Fantastic news.

@deivid-rodriguez deivid-rodriguez force-pushed the depproxy-factory branch 2 times, most recently from 0222795 to 53a6167 Compare January 7, 2021 18:40
@deivid-rodriguez
Copy link
Member

deivid-rodriguez commented Jan 7, 2021

Yay, it's great! I added some tweaks to get this ready. Suming them up:

  • Removed the changes to the realworld specs, since I wasn't sure. I'll still get specs working on MacOS on a separate PR.
  • Given that the spec now takes 3 seconds, I cut the limit to fail the realworld spec to 120 seconds.
  • I tadded the fix in Adds additional uniqueness to Requirement hashes #4250 to this PR, and tweaked it to only special case ~>. Also added a "polyfill" to bundler to support older rubygems not including the fix, and removed the tweak in hashes from DepProxy.
  • I added a note in the Rakefile to mention that we're cherry-picking some unreleased changes to Molinillo.
  • I regenerated cassettes, given recent changes from other PRs.
  • I simplified git history since it had got out of hand after quite a few review rounds.

I think that's it.

@simi You can have a look now!

@segiddins
Copy link
Member

segiddins commented Jan 7, 2021 via email

@deivid-rodriguez
Copy link
Member

That makes sense @segiddins, but won't ruby take care of collisions when generating hashes? If you implement your own #hash you need to make sure that you can't have collisions, but I would expect ruby's Array#hash to not generate collisions? At least the docs seem to suggest so.

In any case, even if we were to really fix this I'm not sure how to go about it, since using an array as the hash key I would imagine ruby would use Array#hash under the hood for the key, and with my suggestion we still end up using Gem::Platform and Gem::Requirement as keys, which use Array#hash to implement their own #hash methods.

So, to sum up, I don't think this is a problem in practice so I'm fine with whatever alternative you or @indirect think is safest. I'll just update this to use the Array as the key as you suggested.

Lukas Oberhuber and others added 5 commits January 7, 2021 23:38
The `~>` operator is special because what's on the right side of it
doesn't have the same properties as a `Gem::Version`. For example, `~>
2.0.0` is not the same as `~> 2.0` even if `2.0` and `2.0.0` are
equivalent as `Gem::Version`'s.
This means that all equal `DepProxy` objects will be the same object as
they are deduped on create. This then in turn allows
`Bundler::Molinillo::Resolver#build_details_for_unwind` function to use
`Array#-` to find relevant unused unwinds which is about 5 times faster
than `Array#&` was before. This dramatically improves performance for
some use cases as this function was where most of the time in the resolution
was being consumed.
This is a hot code path during resolution and `Array#-` performs much
better than `Array#&`.

With the following sample `Gemfile`:

```ruby
source 'https://rubygems.org'

gem "actionmailer"
gem "mongoid", ">= 0.10.2"
```

It reduces `bundle lock` time from 9.5s to 2.8s on my machine.

Co-authored-by: Lukas Oberhuber <lukas.oberhuber@simplybusiness.co.uk>
@deivid-rodriguez
Copy link
Member

@simi In case it helps with your review (assuming you're interested in reviewing the part about hash collisions specifically), I made some research on ruby sources:

This defines Hash#[]: https://github.com/ruby/ruby/blob/55e52c19e74d5df90560ea1cc4f2a2b9f5d7a5c4/hash.c#L6874, which is this method: https://github.com/ruby/ruby/blob/55e52c19e74d5df90560ea1cc4f2a2b9f5d7a5c4/hash.c#L2065, which calls the function hash_st_like_lookup and ends up calling st_lookup which implements the juicy part: https://github.com/ruby/ruby/blob/55e52c19e74d5df90560ea1cc4f2a2b9f5d7a5c4/st.c#L1007-L1031. I think the do_hash call in the second line calls #hash on the given key, in particular this line: https://github.com/ruby/ruby/blob/55e52c19e74d5df90560ea1cc4f2a2b9f5d7a5c4/st.c#L320.

If my interpretation of the C code is correct (which is assuming too much already 😅), that would mean that all alternatives proposed here are equally safe (or unsafe, although I would say they are all safe).

@lukaso
Copy link
Contributor Author

lukaso commented Jan 11, 2021

If my interpretation of the C code is correct (which is assuming too much already 😅), that would mean that all alternatives proposed here are equally safe (or unsafe, although I would say they are all safe).

I think the [dep, platform] without the .hash is best. It uses ruby's hash key functionality which does not allow hash collisions. I ran a test and there are many cache hits with this variant, meaning two instances of dep that are equal evaluate to the same key. Given this, the current implementation on the branch is the best from my reading and testing.

@deivid-rodriguez
Copy link
Member

Still need to investigate it more, but as of today, the Gemfile introduced as part of #4134 is again unbearably slow (I aborted it after 18 minutes).

It seems that some recent gem releases made the number of steps in that resolution go from ~1000 to ~6000. With this PR, resolution is at least workable taking ~ 1minute.

All that to say, we should merge this. I think it has gone through enough scrutiny already. If nobody beats me to it, I'll be merging this later today, we can address any late maintainer feedback post-merge.

Copy link
Member

@simi simi left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Good job! I got some minor comments regarding naming and potential places for additional comments. But nothing to block this for now. I'll introduce them in separate PR later.

@simi simi merged commit 9b50ef6 into rubygems:master Jan 13, 2021
deivid-rodriguez pushed a commit that referenced this pull request Jan 18, 2021
Speed up complex dependency resolves by creating DepProxy factory and cache

(cherry picked from commit 9b50ef6)
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging this pull request may close these issues.

None yet

6 participants