Bug #15856
open
Performance of redundant `Kernel.require` is slow when many gems are activated
Description
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).
Updated by hsbt (Hiroshi SHIBATA) almost 2 years ago
- Assignee set to hsbt (Hiroshi SHIBATA)
- Status changed from Open to Assigned
Updated by deivid (David RodrÃguez) almost 2 years ago
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.
Updated by lamont (Lamont Granquist) almost 2 years ago
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.
Updated by lamont (Lamont Granquist) over 1 year ago
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".
Updated by Eregon (Benoit Daloze) over 1 year ago
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.
Updated by lamont (Lamont Granquist) over 1 year ago
I tracked it back to the initial commit in the ruby-spec repo:
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.
Updated by Dan0042 (Daniel DeLorme) over 1 year ago
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.
Updated by lamont (Lamont Granquist) 9 months ago
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.
Updated by sawa (Tsuyoshi Sawada) 9 months ago
- Description updated (diff)
- 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
Idempotency is a property of an operation within a system. require may be idempotent, its particular use is not. You mean redundant, not idempotent.
Updated by Eregon (Benoit Daloze) 9 months ago
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.
Updated by Dan0042 (Daniel DeLorme) 8 months ago
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