From: "fxn (Xavier Noria)" <noreply@...>
Date: 2021-12-30T15:56:33+00:00
Subject: [ruby-core:106919] [Ruby master Bug#18452] Dramatic performance regression in Zeitwerk with 3.1

Issue #18452 has been updated by fxn (Xavier Noria).


> Is there a reason Zeitwerk is adding directories to $LOADED_FEATURES, instead of using its own data structure?

It didn't do that since it first shipped. The lib intercepted the `require` and did its thing without invoking the original method. It hijacked the call and nobody noticed. This has worked fine since forever.

But last week I got a report about some namespaces not loading. The reason for that was that the project loaded Zeitwerk first, and Bootsnap later. Both decorate `require`. Bootsnap assumes a successful `require` puts its argument in `$LOADED_FEATURES` and caches the directory internally. And that prevented reload, because `$LOADED_FEATURES` did not have the directory to clean it up, and the cache of Bootsnap became out of sync.

I thought about different options, and believed that Bootsnap made a reasonable assumption, so just a few days ago I pushed 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.

You are also right about the self-contained script. I missed some scientific notation and misread some numbers. These are the figures:

```
BEFORE 79a4484a07

% ./ruby -v ~/tmp/foo.rb
ruby 3.1.0dev (2021-10-02T14:51:29Z v3_1_0_preview1~1463 3f7da458a7) [x86_64-darwin21]
/Users/fxn/prj/zeitwerk/lib/zeitwerk/kernel.rb:24: warning: method redefined; discarding old require
Zeitwerk: 0.28963999999905354
Self-contained: 0.000389000000723172

AFTER 79a4484a07

% ./ruby -v ~/tmp/foo.rb
ruby 3.1.0dev (2021-10-02T14:51:29Z v3_1_0_preview1~1462 79a4484a07) [x86_64-darwin21]
/Users/fxn/prj/zeitwerk/lib/zeitwerk/kernel.rb:24: warning: method redefined; discarding old require
Zeitwerk: 11.44435700000031
Self-contained: 9.200000022246968e-05
```

As you see, the reported impact happens in the script using Zeitwerk.

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?

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

* 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>