Project

General

Profile

Bug #15856

Performance of redundant `Kernel.require` is slow when many gems are activated

Added by lamont (Lamont Granquist) over 1 year ago. Updated 3 months ago.

Status:
Assigned
Priority:
Normal
Assignee:
hsbt (Hiroshi SHIBATA)
Target version:
-
ruby -v:
ruby 2.6.3p62 (2019-04-16 revision 67580) [x86_64-linux]
Backport:
2.4: UNKNOWN, 2.5: UNKNOWN, 2.6: UNKNOWN
[ruby-core:92686]
Tags:
core, perf

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).

#1 [ruby-core:92690]

Updated by hsbt (Hiroshi SHIBATA) over 1 year ago

  • Assignee set to hsbt (Hiroshi SHIBATA)
  • Status changed from Open to Assigned
#2 [ruby-core:92730]

Updated by deivid (David Rodríguez) over 1 year 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.

#3 [ruby-core:92749]

Updated by lamont (Lamont Granquist) over 1 year 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.

#4 [ruby-core:95943]

Updated by lamont (Lamont Granquist) about 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".

#5 [ruby-core:95945]

Updated by Eregon (Benoit Daloze) about 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.

#6 [ruby-core:96130]

Updated by lamont (Lamont Granquist) 12 months ago

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.

#7 [ruby-core:96148]

Updated by Dan0042 (Daniel DeLorme) 12 months 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.

#8 [ruby-core:99619]

Updated by lamont (Lamont Granquist) 3 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.

#9 [ruby-core:99620]

Updated by sawa (Tsuyoshi Sawada) 3 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.

#10 [ruby-core:99623]

Updated by Eregon (Benoit Daloze) 3 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.

#11 [ruby-core:99675]

Updated by Dan0042 (Daniel DeLorme) 3 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

Also available in: Atom PDF