Bug #15856: Performance of redundant `Kernel.require` is slow when many gems are activated

• Status: Closed
• Assignee: hsbt (Hiroshi SHIBATA)
• Target version: -
• Backport: 2.6: UNKNOWN, 2.7: DONE, 3.0: DONE
• Tags: perf, core

[lamont (Lamont Granquist)]

With many gems activated, performance of Kernel.require (renamed Kernel.gem_original_require after rubygems is loaded) is slow even when require has already been called (the redundant case).

This is likely because its string argument needs to be resolved to a pathname in order to be compared against a cache of already loaded paths shared between require and require_relative. But it becomes very expensive with lots of activated gems, particularly on windows, where open/stat is ten times more expensive than on linux.

require (but not require_relative, which is already fast) probably needs another layer of redundancy checking that examines if the string argument exists as a Hash key (which I believe is the way require used to work before require_relative was introduced). The second time a require line is processed, it would find the value true and short circuit File I/O to resolve the filename. Of course on the first time, it would still need to resolve the argument to full path and maintain the cache so that require and require_relative are still redundant between them.

After testing, I don't think this would introduce any behavior changes since require lines should always be redundant. I thought it would fix some bugs, but I could not let the existing loader double-load a require line even though I tried to install and activate gems after requiring system libs. I couldn't find any bugs, though, which also means that this should be backward compatible.

An strace of the process of a single require "openssl" after it has been already required looks like this:

open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/uuidtools-2.1.5/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/chef-bin-15.0.276/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/public_suffix-3.0.3/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/addressable-2.6.0/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/mixlib-shellout-2.4.4/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/mixlib-cli-2.0.3/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/appbundler-0.12.5/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/bcrypt_pbkdf-1.0.1/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/extensions/x86_64-linux/2.6.0/bcrypt_pbkdf-1.0.1/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/debug_inspector-0.0.3/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/extensions/x86_64-linux/2.6.0/debug_inspector-0.0.3/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/binding_of_caller-0.8.0/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/extensions/x86_64-linux/2.6.0/binding_of_caller-0.8.0/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/builder-3.2.3/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/byebug-11.0.1/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/extensions/x86_64-linux/2.6.0/byebug-11.0.1/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/tomlrb-1.2.8/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/mixlib-config-3.0.1/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/fuzzyurl-0.9.0/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/chef-config-15.0.276/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/net-ssh-5.2.0/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/net-scp-2.0.0/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/erubis-2.7.0/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/ffi-1.10.0/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/extensions/x86_64-linux/2.6.0/ffi-1.10.0/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/gssapi-1.3.0/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/gyoku-1.3.1/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/httpclient-2.8.3/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/little-plugger-1.1.4/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/multi_json-1.13.1/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/logging-2.2.2/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/nori-2.6.0/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/rubyntlm-0.6.2/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/winrm-2.3.2/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/rubyzip-1.2.2/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/winrm-fs-1.3.2/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/train-core-2.1.0/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/equatable-0.5.0/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/tty-color-0.4.3/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/pastel-0.7.2/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/tty-cursor-0.6.1/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/strings-ansi-0.1.0/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/unicode_utils-1.4.0/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/unicode-display_width-1.4.1/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/strings-0.1.4/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/tty-box-0.3.0/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/necromancer-0.4.0/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/timers-4.3.0/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/wisper-2.0.0/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/tty-screen-0.6.5/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/tty-reader-0.5.0/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/tty-prompt-0.18.1/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/license-acceptance-1.0.5/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/mixlib-log-3.0.1/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/mixlib-authentication-2.1.1/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/mixlib-archive-1.0.1/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/systemu-2.6.5/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/libyajl2-1.2.0/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/extensions/x86_64-linux/2.6.0/libyajl2-1.2.0/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/ffi-yajl-2.3.1/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/extensions/x86_64-linux/2.6.0/ffi-yajl-2.3.1/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/plist-3.5.0/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/ipaddress-0.8.3/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/wmi-lite-1.0.2/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/ohai-15.0.34/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/net-ssh-gateway-2.0.0/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/net-ssh-multi-1.2.1/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/net-sftp-2.1.2/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/ed25519-1.2.4/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/extensions/x86_64-linux/2.6.0/ed25519-1.2.4/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/highline-1.7.10/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/diff-lcs-1.3/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/ffi-libarchive-0.4.6/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/hashie-3.6.0/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/uuidtools-2.1.5/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/rack-2.0.7/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/chef-zero-14.0.12/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/iniparse-1.4.4/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/syslog-logger-1.6.8/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/proxifier-1.0.3/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/chef-15.0.276/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/chef-bin-15.0.276/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/chef-vault-3.4.3/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/cheffish-14.0.4/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/coderay-1.1.2/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/safe_yaml-1.0.5/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/crack-0.4.3/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/docile-1.3.1/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/multipart-post-2.0.0/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/faraday-0.15.4/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/faraday_middleware-0.12.2/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/hashdiff-0.3.9/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/htmlentities-4.3.4/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/thor-0.20.3/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/method_source-0.9.2/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/rspec-support-3.8.0/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/rspec-core-3.8.0/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/rspec-expectations-3.8.3/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/rspec-mocks-3.8.0/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/rspec-3.8.0/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/rspec-its-1.3.0/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/pry-0.12.2/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/sslshake-1.3.0/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/parallel-1.17.0/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/parslet-1.8.2/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/semverse-3.0.0/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/tty-table-0.10.0/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/tins-1.20.2/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/term-ansicolor-1.7.1/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/inspec-core-4.3.2/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/json-2.2.0/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/extensions/x86_64-linux/2.6.0/json-2.2.0/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/pry-byebug-3.7.0/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/slop-3.6.0/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/pry-remote-0.1.8/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/pry-stack_explorer-0.4.9.3/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/rake-12.3.2/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/rb-readline-0.5.5/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/rspec_junit_formatter-0.2.3/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/ruby-prof-0.17.0/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/extensions/x86_64-linux/2.6.0/ruby-prof-0.17.0/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/ruby-shadow-2.5.0/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/extensions/x86_64-linux/2.6.0/ruby-shadow-2.5.0/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/simplecov-html-0.10.2/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/simplecov-0.16.1/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/webmock-3.5.1/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/gems/2.6.0/gems/bundler-1.17.3/lib/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/site_ruby/2.6.0/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/site_ruby/2.6.0/x86_64-linux/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/site_ruby/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/vendor_ruby/2.6.0/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/vendor_ruby/2.6.0/x86_64-linux/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/vendor_ruby/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/opt/chef/embedded/lib/ruby/2.6.0/openssl.rb", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = 7

On windows, this much I/O on every single require line can quickly add up to 100,000s of open calls, which takes several seconds on an SSD or up to a minute on a spinning drive just to evaluate the requires of an application that does no work (i.e. command line tooling).

[hsbt (Hiroshi SHIBATA)]

• Status changed from Open to Assigned
• Assignee set to hsbt (Hiroshi SHIBATA)

ref. https://github.com/rubygems/rubygems/issues/2762

[deivid (David Rodríguez)]

I had a look at this. I manage to reproduce the issue only when requiring openssl. In general, I think it can be reproduced when a ruby feature requires an dynamic library of the same name. In this case, require "openssl" resolves to requiring openssl.rb, which internally requires (among other stuff) openssl.so.

To reproduce, I required openssl a lot of times, expecting that after the first time the require would have no overhead. However,

$ time ruby --disable-gems -e '100000.times { require "openssl" }'

real	0m3,075s
user	0m1,732s
sys     0m1,301s

The problem can be workaround by explicitly specifying the file extension

$ time ruby --disable-gems -e '100000.times { require "openssl.rb" }'

real	0m0,137s
user	0m0,113s
sys     0m0,029s

I took a lot at fixing it and came up with this patch

diff --git a/load.c b/load.c
index 576464fb68..ae89f63820 100644
--- a/load.c
+++ b/load.c
@@ -908,6 +908,11 @@ search_required(VALUE fname, volatile VALUE *path, int safe_level, feature_func
        if (loading) *path = rb_filesystem_str_new_cstr(loading);
        return 'r';
     }
+    else if ((ft = rb_feature_p(ftptr, 0, FALSE, FALSE, &loading)) == 's') {
+       if (loading) *path = rb_filesystem_str_new_cstr(loading);
+       return 's';
+    }
+
     tmp = fname;
     type = rb_find_file_ext_safe(&tmp, loadable_ext, safe_level);
     switch (type) {

However, that breaks the following spec:

it "loads a .rb extensioned file when a C-extension file of the same name is loaded" do
  $LOADED_FEATURES << File.expand_path("load_fixture.bundle", CODE_LOADING_DIR)
  $LOADED_FEATURES << File.expand_path("load_fixture.dylib", CODE_LOADING_DIR)
  $LOADED_FEATURES << File.expand_path("load_fixture.so", CODE_LOADING_DIR)
  $LOADED_FEATURES << File.expand_path("load_fixture.dll", CODE_LOADING_DIR)
  path = File.expand_path "load_fixture", CODE_LOADING_DIR
  @object.require(path).should be_true
  ScratchPad.recorded.should == [:loaded]
end

I'm not sure that spec is expected behavior, though. It was introduced during this refactoring, but I think the refactoring changed the expectations, because the previous spec I think this spec comes from reads like this:

it "will load file.rb when given 'file' if it exists even if file.<ext> is loaded" do
  $LOADED_FEATURES << "require_spec_3.#{Config::CONFIG['DLEXT']}"
  require('require_spec_3.rb').should be_true
  $LOADED_FEATURES.grep(/require_spec_3\.rb/).should_not == []
end

and while the description is what the spec tests nowadays, the implementation explictly included a file extension (require_spec_3.rb), while the current spec does not (load_fixture).

Essentially I think it comes down to whether the correct behavior is the current one:

$ ruby --disable-gems -e 'puts require "openssl.so"; puts require "openssl"'
true
true

or the one after my patch:

$ ruby --disable-gems -e 'puts require "openssl.so"; puts require "openssl"'
true
false

If the expected behavior is the current one, then obviously my patch doesn't work.

[lamont (Lamont Granquist)]

Okay that explains what I was seeing, I just didn't realize that it was that subtle around .so loading, but I think I've verified that this is for those native libraries only.

I'd argue that your patch results in more correct and less surprising behavior, but I have no idea who is bug dependent upon it.

I'm going to wind up doing a large amount of work to bypass this problem, though, and decorating all our code with require "openssl" unless defined?(OpenSSL) old-school tactics from 8+ years ago as a workaround. I would definitely vote to change this behavior in core.

And I've already had users reading my code patches and I'm worried about I'm about to start a cargo cult of how to make ruby go fast.

[lamont (Lamont Granquist)]

For what its worth:

We went ahead and incorporated the prior patch into chef's shipping packages starting with Chef 15.5.9, and it will be incorporated into all our shipping products that bake in ruby (inspec, chefdk, chef workstation, supermarket, etc).

I'd like to encourage the consideration of accepting that patch for Ruby 3.0 and breaking that one use case in the ruby specs, assuming we don't turn up any issues by deploying it into "production".

[Eregon (Benoit Daloze)]

I agree caching require 'openssl' should be possible.
I'm OK with changing (or removing) that spec to specify the new behavior, but would like to hear others' opinions as I don't much about the history and rationale behind the current behavior.

[lamont (Lamont Granquist)]

I tracked it back to the initial commit in the ruby-spec repo:

https://github.com/ruby/spec/blob/6c1c34a6bbf28b55e59bc6a97a1211718082d3e7/1.8/core/kernel/require_spec.rb#L122-L126

That is from May 2008 and there's no history in git beyond that, or any note of why it is there.

Maybe someone else who knows the history of where that repo came from in the first place can dig up history even further back, but that's where the trail goes cold for me.

[Dan0042 (Daniel DeLorme)]

A quick search yields the following files that have both a rb and so version:

/opt/ruby/2.7/lib/ruby/gems/2.7.0/gems/redcarpet-3.5.0/lib
   redcarpet.so 

/opt/ruby/2.7/lib/ruby/gems/2.7.0/gems/debug_inspector-0.0.3/lib
   debug_inspector.so 

/opt/ruby/2.7/lib/ruby/2.7.0
   ripper.so		(required from ripper/core.so)
   bigdecimal/util.so	
   monitor.so
   pathname.so
   fiddle.so
   digest.so
   digest/sha2.so	(from digest/sha2.rb AND digest.rb)
   bigdecimal.so
   psych.so
   coverage.so
   socket.so
   readline.so
   openssl.so

Except for ripper and digest/sha2, the so is required from within the rb.

digest/sha2 is kinda interesting because it ties into Digest auto-loading. Using Digest::SHA256 will load "digest/sha2.so", and then if you use Digest::SHA2 that will attempt to load "digest/sha2". I think that would not work with the above patch.

[lamont (Lamont Granquist)]

So we've been shipping this patch for 8 months now and not seen any bug reports.

Not sure why we haven't seen any issues around sha2/sha256, but either we get sha256 from the openssl api and not digest or that's been working, because we definitely use sha256.

As a breaking change the "blast radius" of this seems relatively contained. Really this is a massive perf improvement, and it would be worth it IMO to put this into ruby 3.0 and break backwards compat over this issue to get the 10x+ perf increase on those requires. It would do a lot to address "bundler sucks and is slow" issues. Also "ruby is slow on windows" since the I/O hit from all this scanning is ten times worse on windows.

We also are littering our code with defensive idempotency checks, to make our gems run faster when people do use them under bundler:

https://github.com/chef/chef/commit/9dbdb769bfd963f82eb4bfea53c83501d0193766

I would love to stop doing that since it is horrible, but this is my "best-practice" recommendation today for ruby 2.7 bundler performance under Windows.

[sawa (Tsuyoshi Sawada)]

• Subject changed from Idempotent performance of Kernel.require with many activated gems is slow to Performance of redundant `Kernel.require` is slow when many gems are activated
• Description updated (diff)

Idempotency is a property of an operation within a system. require may be idempotent, its particular use is not. You mean redundant, not idempotent.

[Eregon (Benoit Daloze)]

Could the feature index track that both .rb and .so have been loaded and if so short-circuit the search?

It would still do a search every time if only the .so is loaded (like currently), but it seems features which only exist as .so and not as .rb are rather rare.

[Dan0042 (Daniel DeLorme)]

Without the patch:

require "digest"
p Digest::SHA256 #=> Digest::SHA256
p Digest::SHA2   #=> Digest::SHA2

With the patch:

require "digest"
p Digest::SHA256 #=> Digest::SHA256
p Digest::SHA2   #=> uninitialized constant Digest::SHA2

The fix in digest.rb is simple enough:

   def self.const_missing(name) # :nodoc:
     case name
     when :SHA256, :SHA384, :SHA512
-      lib = 'digest/sha2.so'
+      lib = 'digest/sha2.rb'
     else

[jeremyevans0 (Jeremy Evans)]

• Tracker changed from Bug to Feature
• ruby -v deleted (ruby 2.6.3p62 (2019-04-16 revision 67580) [x86_64-linux])
• Backport deleted (2.4: UNKNOWN, 2.5: UNKNOWN, 2.6: UNKNOWN)

This is still a performance issue in the master branch. I think it makes sense to fix the issue by using the approach recommended by @deivid (David Rodríguez) is best. In addition to being faster, is also makes the behavior for native libraries consistent with pure ruby libraries. However, because this breaks backwards compatibility, it must be considered a feature and not a bug. I've submitted a pull request to implement this feature: https://github.com/ruby/ruby/pull/4622. I've also submitted a pull request to digest to fix the issue identified by @Dan0042 (Daniel DeLorme): https://github.com/ruby/digest/pull/22. I'll add this to the discussion list for the next developer meeting.

[lamont (Lamont Granquist)]

We've still been using the David Rodriguez patch with no reported issues around it for the past ~2 years or so.

It is likely that we don't hit the Digest issue due to the way we already have to play games with that built-in gem due to fips.

We also don't do rails, though, so it could certainly break something very common in that use case and we'd have never seen it.

(More just reporting here that we're still using it and still have no problems to report).

[nobu (Nobuyoshi Nakada)]

• File 0001-Sort-feature-index-arrays-by-the-priority-of-file-ty.patch 0001-Sort-feature-index-arrays-by-the-priority-of-file-ty.patch added
• Tracker changed from Feature to Bug
• Backport set to 2.6: UNKNOWN, 2.7: REQUIRED, 3.0: REQUIRED

The feature index arrays seems to ignore the priority of file types.

[jeremyevans0 (Jeremy Evans)]

I've reviewed @nobu's patch and think that we should go with that approach. It avoids the backwards compatibility issues with @deivid's approach while still fixing the performance issue. I submitted a pull request for it: https://github.com/ruby/ruby/pull/4674

[nobu (Nobuyoshi Nakada)]

• Status changed from Assigned to Closed

Applied in changeset git|b360588cd3cbac5fb4f004aa53a8fdc715906719.

---

Sort feature index arrays by the priority of file types [Bug #15856]

When looking for libraries to load with a feature name without
extension, .rb files are given priority. However, since the
feature index arrays were not in that order of priority, but in
the order in which they were loaded, a lower priority extension
library might be returned. In that case, the .rb file had to be
searched for again from the $LOAD_PATH, resulting in poor
performance.

[deivid (David Rodríguez)]

Thanks for working on this and coming up with a 100% backwards compatible fix! <3

[nagachika (Tomoyuki Chikanaga)]

• Backport changed from 2.6: UNKNOWN, 2.7: REQUIRED, 3.0: REQUIRED to 2.6: UNKNOWN, 2.7: REQUIRED, 3.0: DONE

ruby_3_0 0dbb3c15dbe9b7693ea362c94ed8939d20cba083 merged revision(s) b360588cd3cbac5fb4f004aa53a8fdc715906719.

[usa (Usaku NAKAMURA)]

• Backport changed from 2.6: UNKNOWN, 2.7: REQUIRED, 3.0: DONE to 2.6: UNKNOWN, 2.7: DONE, 3.0: DONE

ruby_2_7 7d4d38f8838579592e70fb04a6a2f0162fe989c2 merged revision(s) b360588cd3cbac5fb4f004aa53a8fdc715906719.