load times discrepancy between loading all verses single test or directory. #2611

ChrisCPO · 2019-03-25T17:35:23Z

TIme Discrepancy

We are noticing a very large time discrepancy between loading the entire suite verses, a directory, or a single test.

Versions

Ruby version: ruby 2.6.1p33
Rails version: Rails 5.1.6.2
RSpec version: RSpec 3.7

rspec-core 3.7.1

Observed behavior

We are noticing a very large time discrepancy between loading the entire suite verses, a directory, or a single test.

When bundle exec rspec spec/models/user_spec.rb
=> Finished... (files took 4 seconds to load)

When bundle exec rspec spec/{directory}
Files take 10 to 20 seconds to load. Running the entire suite this way would take in total about 45 seconds to load.

When bundle exec rspec spec
=> Finished... (files took 4 minutes 24.9 seconds to load)
Greater then 4 minutes!

Our environment takes about 4 seconds to load.

Expected behavior

By adding the load times when loading each directory, I would assume that the entire suite would take about 40 - 50 seconds to load all of the files.

We are seeing this across multiple machines.

There are a lot of interwebs about load times, many are old as they point to spring. Though I was unable to find a reference about an issue like this.

Digging into this, the issue appears to be in

rspec-core/lib/rspec/core/configuration.rb

Line 1547 in 0b4c98d

def load_spec_files

I pry'd into it and the files_to_run.uniq.each do ... block takes our 4 minutes and change to load all 2k ish spec files.

I don't think this is a monolithic app issue because totaling the load time when running each directory versus the full suite does not add up to over 4 minutes.

Considering that load is a kernel method... ?

The text was updated successfully, but these errors were encountered:

JonRowe · 2019-03-26T11:09:48Z

@ChrisCPO I'm sorry to hear that, have you tried passing in all of the files manually? Theres some logic surrounding digging through all of the folders which might be improvable, and building a list of files outside of RSpec and passing them in might end up being faster? It'd be a good point to start looking into why this seems to take longer in the default command rather than per directory.

If load is the bottleneck theres nothing we can do of course, but it might be possible to speed your spec files themselves up by ensuring they don't trigger autoloading until they are run.

You might also wish to check your rails settings, if your "fast boot" is caused by turning off preload and using eager loading then thats actually going to be slower overall for you, as everything will be loaded as your specs are loaded. Its possible you have some really slow loading specs, which is hidden until you load all the files.

ChrisCPO · 2019-03-26T15:07:43Z

Thanks for the Response @JonRowe

have you tried passing in all of the files manually?

bundle exec rspec spec $(tree | find -E . -regex “.*/*_spec.rb”)
yes, it does not seem to have any effect. The method get_files_to_run does not appear to be the issue it returns the array rather quickly it's parsing over that array. I checked by adding some start and end times in there, that array takes about 4 minutes to go over.

If load is the bottleneck there's nothing we can do of course

As of now it would appear the more files you load with load there is some sort of exponential increase in time.

Its possible you have some really slow loading specs, which is hidden until you load all the files.

Wouldn't an issue like this show up when each spec directory is run separately? Which the sum of the load times are about 35 seconds.

ChrisCPO · 2019-03-26T19:01:28Z

here is a weird part, our worst directory takes ~15 seconds to load when just that directory is loaded. Here are some load times from the same file:

directory	full suite
0.959565	9.201081
0.580894	7.909137
0.19103	6.096184
0.355666	5.00293

The difference on the first file is 10x, these times are fairly consistent within a 5% variance.

As I understand kernel.load is going to be searching for the file in $LOAD_PATH and then loading the absolute path, "requiring" and executing the file in a nameless module. Our load paths size is 400, is that big? Could searching the entire load path take 8 seconds more than when a directory is specified, therefore narrowing the scope?

JonRowe · 2019-03-26T19:24:28Z

Well, you should be able to bench mark this! This is a... crude... attempt:

require 'rspec'
$LOAD_PATH.push << File.expand_path('spec')
# contents of .rspec for me means that I require this always.
require 'spec_helper.rb'

dirs =
  Dir['spec/**'].select { |n| Dir.exists? n } + ['spec']

configs =
  dirs.inject({}) do |hash, dir|
    config = RSpec::Core::Configuration.new
    config.files_or_directories_to_run = dir
    hash[dir] = config
    hash
  end

require 'benchmark'

configs.each do |dir, config|
  puts "configuring: #{dir}"
  Benchmark.bm do |b|
    files = []
    b.report("expand") { files = config.files_to_run.map { |file| File.expand_path file } }
    b.report("load") { Process.wait fork { files.each { |file| __send__ :load, file } } }
  end
end

I warn you the fork is used to make the require of rails etc happen each time...

JonRowe · 2019-03-26T19:29:18Z

My results from a real world project:

configuring: spec/features
       user     system      total        real
expand  0.000195   0.000204   0.000399 (  0.000397)
load    0.000159   0.001490   8.162786 (  8.724841)
configuring: spec/models
       user     system      total        real
expand  0.000330   0.000420   0.000750 (  0.000748)
load    0.000110   0.001204   9.484556 ( 10.205385)
configuring: spec/requests
       user     system      total        real
expand  0.000333   0.000374   0.000707 (  0.000708)
load    0.000104   0.000853   7.625843 (  7.668836)
configuring: spec/support
       user     system      total        real
expand  0.000434   0.000578   0.001012 (  0.001017)
load    0.000107   0.001085   0.023011 (  0.022893)
configuring: spec/factories
       user     system      total        real
expand  0.000335   0.000410   0.000745 (  0.000758)
load    0.000119   0.001199   0.023377 (  0.024646)
configuring: spec/serializiers
       user     system      total        real
expand  0.000376   0.000421   0.000797 (  0.000808)
load    0.000102   0.000866   8.516927 (  8.915675)
configuring: spec/lib
       user     system      total        real
expand  0.000709   0.000903   0.001612 (  0.001611)
load    0.000132   0.001232   9.056844 (  9.664607)
configuring: spec/controllers
       user     system      total        real
expand  0.000549   0.000805   0.001354 (  0.001401)
load    0.000119   0.001083   7.657808 (  7.726346)
configuring: spec
       user     system      total        real
expand  0.001576   0.002249   0.003825 (  0.003854)
load    0.000117   0.001242   8.192876 (  8.474317)

Showing what I'd typically expect, a reasonable load time caused by rails in each directory invoking it.

pirj · 2020-01-09T23:04:48Z

Please feel free to reopen if there is something actionable in rspec-core.
The problem supposedly relies on different sets of files loaded by Rails triggered by spec files.

agis · 2020-04-02T14:24:40Z

@ChrisCPO did you by any chance find the root cause for this? If so, did you manage to tackle it somehow? Thanks!

agis · 2020-04-03T14:51:33Z

I'm experiencing the same issue with a Rails 5.1 and rspec-core 3.8.0. We have 2676 spec files.

@JonRowe I have a question about your script. Why do you also load the whole spec/ path at the end? Is it what typically happens when one executes bundle exec rspec? I'm asking because this seems to be the culprit in our case.

Using the script you provided, I measured the load times of each of the root spec paths in my app (I didn't benchmark the expand path because it was insignificant). Here are the results:

       user     system      total        real
spec/facades  0.000000   0.010000   0.520000 (  0.525482)

       user     system      total        real
spec/kafka  0.000000   0.000000   0.510000 (  0.525686)

       user     system      total        real
spec/presenters  0.000000   0.010000   0.990000 (  0.998101)

       user     system      total        real
spec/helpers  0.000000   0.000000   3.800000 (  3.836663)

       user     system      total        real
spec/maestros  0.000000   0.010000   0.770000 (  0.756742)

       user     system      total        real
spec/requests  0.000000   0.010000   2.070000 (  2.087123)

       user     system      total        real
spec/views  0.000000   0.010000   2.070000 (  2.094770)

       user     system      total        real
spec/mailers  0.000000   0.010000   0.860000 (  0.860082)

       user     system      total        real
spec/decorators  0.000000   0.000000   1.070000 (  1.075212)

       user     system      total        real
spec/javascripts  0.010000   0.000000   0.330000 (  0.326302)

       user     system      total        real
spec/config  0.000000   0.010000   0.330000 (  0.334946)

       user     system      total        real
spec/fixtures  0.000000   0.010000   0.330000 (  0.326360)

       user     system      total        real
spec/uploaders  0.000000   0.010000   0.610000 (  0.612634)

       user     system      total        real
spec/serializers  0.000000   0.000000   1.100000 (  1.111742)

       user     system      total        real
spec/cron  0.000000   0.010000   0.340000 (  0.331764)

       user     system      total        real
spec/system  0.000000   0.010000   0.530000 (  0.535039)

       user     system      total        real
spec/features  0.000000   0.010000   0.680000 (  0.669061)

       user     system      total        real
spec/ymls  0.000000   0.000000   0.320000 (  0.340731)

       user     system      total        real
spec/integration  0.000000   0.010000   0.600000 (  0.588522)

       user     system      total        real
spec/support  0.000000   0.010000   0.330000 (  0.332707)

       user     system      total        real
spec/controllers  0.000000   0.010000   8.710000 (  8.713314)

       user     system      total        real
spec/routing  0.000000   0.010000   2.620000 (  2.644377)

       user     system      total        real
spec/elastic  0.000000   0.010000   0.920000 (  0.933902)

       user     system      total        real
spec/factories  0.000000   0.010000   0.330000 (  0.322735)

       user     system      total        real
spec/models  0.000000   0.010000   9.090000 (  9.123153)

       user     system      total        real
spec/lib  0.010000   0.010000  11.180000 ( 11.233031)

       user     system      total        real
spec  0.040000   0.010000 118.530000 (118.933386)

It strikes me that configuring the whole spec/ path (last line) is way above the sum of all other individual paths - the numbers don't add up (but should they?)

JonRowe · 2020-04-03T20:36:21Z

It is not expected to add up, but the subfolders added up should be more than the spec folder on its own. Some further benchmarking of your loading files might help here.

agis · 2020-04-06T09:10:34Z

@JonRowe I've modified your script to measure individual file load timings. It seems that, in the case where each folder is loaded separately, individual file load timings add up to 30s. In the last case, where all files are loaded via spec, the total timings are 90s.

By comparing the timings of the same files in both cases, indeed in the spec case files take a lot longer. For example:

spec/helpers/application_helper_spec.rb,0.764 # loaded via 'spec/helpers'
spec/helpers/application_helper_spec.rb,6.100631 # loaded via 'spec'

spec/views/skus/show/_details.html.erb_spec.rb,0.1617539999999999 # loaded via 'spec/views'
spec/views/skus/show/_details.html.erb_spec.rb,4.82285899999999 # loaded via 'spec'

pirj · 2020-04-06T09:36:22Z

Can you please debug it further @agis?

JonRowe · 2020-04-06T09:40:46Z

Can you run the script I produced? Your output before doesn't contain the expand vs load comparison.

This is important because it show'd that load is the culprit previous which is not something we can fix...

agis · 2020-04-06T12:59:09Z

@JonRowe perhaps that wasn't clear from my previous comments, but load is indeed the culprit, that's why I removed the File.expand_path calls. However, that didn't explain why individual spec folder timings (totaling 30s) don't add up to give a time close to the spec timing (90s).

Anyway, I did some more digging by profiling two load calls to the same spec file and got to some interesting conclusions.

Apparently, in the case of the "load spec/", the time spent in Module#name is significantly larger: 96.88% of the total time compared to 0.10% of the total time in the "load spec/helpers/" case. This method is called by Rails' AbstractController::Helpers::ClassMethods#inherited which is somehow called by RSpec's <Class::RSpec::Core::ExampleGroup>#subclass. I get that RSpec defined anonymous modules for each example group?

In any case, the issue here is caused by the fact that Module#name scales poorly for anonymous classes - there's even an issue in the Ruby tracker: https://bugs.ruby-lang.org/issues/11119. Hopefully, the situation got a lot better with Ruby 2.7 and specifically with this fix and in fact, running the initial tests from #2611 (comment), the loading times dropped down significantly.

spec/facades,0.19424600000000028
spec/kafka,0.2145920000000007
spec/presenters,0.5101729999999997
spec/helpers,0.6426690000000008
spec/maestros,0.3762200000000003
spec/requests,1.3813589999999987
spec/views,0.5963979999999995
spec/mailers,0.5267020000000002
spec/decorators,0.6826819999999998
spec/javascripts,0.17387399999999942
spec/fixtures,0.17311199999999993
spec/uploaders,0.2726810000000006
spec/serializers,0.7323250000000001
spec/cron,0.17685600000000057
spec/system,0.21526499999999893
spec/features,0.4184669999999999
spec/ymls,0.17456700000000058
spec/integration,0.24822399999999978
spec/support,0.17572399999999955
spec/controllers,5.327960000000001
spec/routing,2.7772819999999996
spec/elastic,0.5973080000000013
spec/factories,0.19000199999999756
spec/models,6.287398
spec/lib,6.916092
spec,29.959453000000003

So from 118s., loading every file in spec went down to 30sec.

I don't know if something can be done from RSpec's point of view. I could upload here the HTML profile generated from ruby-prof, of the slow load call, in case it helps.

References:

Ruby issue: https://bugs.ruby-lang.org/issues/11119
Ruby issue drb support #2: https://bugs.ruby-lang.org/issues/15625
Fix: https://bugs.ruby-lang.org/issues/15765
Related: Find a more performant way to detect anonymous classes and modules #1954
Related: Boot time: ActionDispatch::Routing::RouteSet is very slow (delegation / anon modules) rails/rails#24248

JonRowe · 2020-04-08T09:10:52Z

However, that doesn't explain why individual spec folder timings (totaling 30s) don't add up to give a time close to the spec timing (90s).

It does if its exponentially linked to the number of files / classes / modules.

Apparently, in the case of the "load spec/", the time spent in Module#name is significantly larger: 96.88% of the total time compared to 0.10% of the total time in the "load spec/helpers/" case. This method is called by Rails' AbstractController::Helpers::ClassMethods#inherited which is somehow called by RSpec's Class::RSpec::Core::ExampleGroup#subclass. I get that RSpec defined anonymous modules for each example group?

Each describe / context defines a class, but they are non anonymous, they are named for the strings they are created with e.g. RSpec::ExampleGroups::RSpecMocksMatchersReceive::ExpectAnyInstanceOfToReceive::BehavesLikeAnExpectSyntaxExpectation::BehavesLikeAReceiveMatcher

If theres something we can do here please comment, otherwise I'm closing for now.

pirj closed this as completed Jan 9, 2020

pirj reopened this Apr 6, 2020

JonRowe closed this as completed Apr 8, 2020

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

load times discrepancy between loading all verses single test or directory. #2611

load times discrepancy between loading all verses single test or directory. #2611

ChrisCPO commented Mar 25, 2019 •

edited by JonRowe

Loading

JonRowe commented Mar 26, 2019 •

edited

Loading

ChrisCPO commented Mar 26, 2019

ChrisCPO commented Mar 26, 2019

JonRowe commented Mar 26, 2019 •

edited

Loading

JonRowe commented Mar 26, 2019

pirj commented Jan 9, 2020

agis commented Apr 2, 2020

agis commented Apr 3, 2020

JonRowe commented Apr 3, 2020

agis commented Apr 6, 2020 •

edited

Loading

pirj commented Apr 6, 2020

JonRowe commented Apr 6, 2020 •

edited

Loading

agis commented Apr 6, 2020 •

edited

Loading

JonRowe commented Apr 8, 2020

load times discrepancy between loading all verses single test or directory. #2611

load times discrepancy between loading all verses single test or directory. #2611

Comments

ChrisCPO commented Mar 25, 2019 • edited by JonRowe Loading

TIme Discrepancy

Versions

Observed behavior

Expected behavior

JonRowe commented Mar 26, 2019 • edited Loading

ChrisCPO commented Mar 26, 2019

ChrisCPO commented Mar 26, 2019

JonRowe commented Mar 26, 2019 • edited Loading

JonRowe commented Mar 26, 2019

pirj commented Jan 9, 2020

agis commented Apr 2, 2020

agis commented Apr 3, 2020

JonRowe commented Apr 3, 2020

agis commented Apr 6, 2020 • edited Loading

pirj commented Apr 6, 2020

JonRowe commented Apr 6, 2020 • edited Loading

agis commented Apr 6, 2020 • edited Loading

JonRowe commented Apr 8, 2020

ChrisCPO commented Mar 25, 2019 •

edited by JonRowe

Loading

JonRowe commented Mar 26, 2019 •

edited

Loading

JonRowe commented Mar 26, 2019 •

edited

Loading

agis commented Apr 6, 2020 •

edited

Loading

JonRowe commented Apr 6, 2020 •

edited

Loading

agis commented Apr 6, 2020 •

edited

Loading