From: "jeremyevans0 (Jeremy Evans)" <noreply@...>
Date: 2021-12-30T16:44:07+00:00
Subject: [ruby-core:106921] [Ruby master Bug#18452] Dramatic performance regression in Zeitwerk with 3.1

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


fxn (Xavier Noria) wrote in #note-2:
> I thought about different options, and believed that Bootsnap made a reasonable assumption, so just a few days ago I published a new version that pushed the directory to `$LOADED_FEATURES`.
> 
> You are right about directories being unexpected in that collection, see my [comment](https://github.com/fxn/zeitwerk/issues/198#issuecomment-1001539203) in the original issue.

I think your original assumption is more reasonable, and Bootsnap's assumption is not.  I'm also not sure what code is expecting a `Kernel#require` with a directory to work, but such code also seems suspect, IMO.  If you've only made this change to Zeitwerk in the last week, I recommend reverting it.  

> Every `require` call pushes to `$LOADED_FEATURES`, and if I comment out the line that pushes to `$LOADED_FEATURES` in Zeitwerk performance is not affected. Why is the lib's `push` more costly?

When you modify `$LOADED_FEATURES` directly, you trigger a rebuild of the loaded feature index the next time `Kernel#require` (or related C-API method) is called.  This has been the case for many years, it's just that index rebuilds are more expensive now due to realpath calculations.  In general, it's best to never modify `$LOADED_FEATURES` unless you must (such as to remove entries to allow for code reloading).

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

* 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:ruby-core-request@ruby-lang.org?subject=unsubscribe>
<http://lists.ruby-lang.org/cgi-bin/mailman/options/ruby-core>