[ruby-core:106918] [Ruby master Bug#18452] Dramatic performance regression in Zeitwerk with 3.1

Issue #18452 has been updated by jeremyevans0 (Jeremy Evans).


The bug fixed in commit:79a4484a072e9769b603e7b4fbdb15b1d7eccb15 is always going to result in some slow down, since Ruby now has to determine the realpath for all entries in `$LOADED_FEATURES`.  The commit doesn't change when the loaded feature index is rebuilt, though it makes the rebuilding process slower as the realpath is recalculated for all entries in `$LOADED_FEATURES`.

`$LOADED_FEATURES` is supposed to have files that ruby has required, it's not supposed to contain directories.  So any code that modifies `$LOADED_FEATURES` to add a directory is doing something wrong, in my opinion.  Is there a reason Zeitwerk is adding directories to `$LOADED_FEATURES`, instead of using its own data structure?  I assume if you are overriding `require`, you can check your own data structure instead of abusing `$LOADED_FEATURES`.

FWIW, I tried the reproducer without Zeitwerk, and it performed about the same in both 3.0 and 3.1:

```
$ ruby30 -v t/t33.rb
ruby 3.0.3p157 (2021-11-24 revision 3fb7d2cadc) [x86_64-openbsd]
0.00035451585426926613
$ ruby31 -v t/t33.rb
ruby 3.1.0p0 (2021-12-25 revision fb4df44d16) [x86_64-openbsd]
0.00035237614065408707
```

I'm not sure why the code in your non-Zeitwerk example would perform differently, as the index rebuild only happens when `get_loaded_features_index` is called (which is called by `Kernel#require` in ruby code) is called, it's not called just by modifying `$LOADED_FEATURES`, and your non-Zeitwerk example doesn't call `Kernel#require`, it only modifies `$LOADED_FEATURES`.

If I modify the script slightly, to add a `require 'set'` to the code being timed, then I do see a difference, it is a little less than 3x slower:

```
$ ruby30 -v t/t33.rb
ruby 3.0.3p157 (2021-11-24 revision 3fb7d2cadc) [x86_64-openbsd]
0.005338589195162058
$ ruby31 -v t/t33.rb
ruby 3.1.0p0 (2021-12-25 revision fb4df44d16) [x86_64-openbsd]
0.01448665326461196
```

Considering it has to determine the realpath on over 65536 entries in `$LOADED_FEATURES`, that seems reasonable.  My only guess as to what is happening with Zeitwerk is Zeitwerk is requiring an loaded feature index rebuild every time it is modifying `$LOADED_FEATURES`, resulting in quadratic behavior.

----------------------------------------
Bug #18452: Dramatic performance regression in Zeitwerk with 3.1
https://bugs.ruby-lang.org/issues/18452#change-95737

* Author: fxn (Xavier Noria)
* Status: Open
* Priority: Normal
* Backport: 2.6: UNKNOWN, 2.7: UNKNOWN, 3.0: UNKNOWN, 3.1: UNKNOWN
----------------------------------------
Hi!

In Ruby 3.1, Zeitwerk loads implicit namespaces way slower than in previous versions. In this benchmark:

```ruby
require 'fileutils'
require 'tmpdir'
require 'zeitwerk'

Dir.mktmpdir do |dir|
  Dir.chdir(dir)

  for i in 'a'..'z'
    for j in 'a'..'z'
      FileUtils.mkdir_p("lib/#{i}/#{j}")
    end
  end

  loader = Zeitwerk::Loader.new
  loader.push_dir('lib')
  loader.setup

  start = Process.clock_gettime(Process::CLOCK_MONOTONIC)
  loader.eager_load
  puts Process.clock_gettime(Process::CLOCK_MONOTONIC) - start
end
```

you go from about 0.06s to +11s. That is like a **180x slow down** .

I have seen that the single cause of the slow down is one line: Zeitwerk's `Kernel#require` wrapper pushing to `$LOADED_FEATURES` when it intercepts a directory [source code](https://github.com/fxn/zeitwerk/blob/1ff6336d937514c923f2c5a60cfaa501f150a7b5/lib/zeitwerk/kernel.rb#L32). For context, Zeitwerk sets autoloads for directories that define namespaces, so that their corresponding modules get autovivified when first referenced by the user.

I have written a self-contained script that reproduces the root of the issue without Zeitwerk, in case that helps debugging:

```ruby
module Kernel
  alias original_require require

  def require(path)
    if path.start_with?('/foo')
      $LOADED_FEATURES << path
      true
    else
      original_require(path)
    end
  end
end

foos = []
('a'..'z').each do |i|
  ('a'..'z').each do |j|
    foos << "/foo#{i}#{j}"
  end
end

start = Process.clock_gettime(Process::CLOCK_MONOTONIC)
foos.each { |foo| require foo }
puts Process.clock_gettime(Process::CLOCK_MONOTONIC) - start
```

I have seen that [this commit](https://github.com/ruby/ruby/commit/79a4484a072e9769b603e7b4fbdb15b1d7eccb15) is responsible for the majority of the regression, But it is not the only cause, before that commit, the script is faster, but not as fast by an important factor too.



-- 
https://bugs.ruby-lang.org/

Unsubscribe: <mailto:[e-mail]?subject=unsubscribe>
<http://lists.ruby-lang.org/cgi-bin/mailman/options/ruby-core>