make_files.rb

`mkdir f`
10000.times do |x|
  `touch f/bogus#{x}.rb`
end

require_benchmark.rb

require 'rubygems'
$LOAD_PATH.unshift(File.expand_path('f'))

x = 0

require 'benchmark'

Benchmark.bm do |b|
  (1..5).each do |n|
    b.report("#{n * 500} requires") { (n*500).times { require "bogus#{x}"; x += 1 }}
  end
end

I think I did and it was roughly the same. I will add it to my graph.

Are you sure? Asking this because the other gist you gave to this issue here: https://gist.github.com/950154

Is still against 1.9.2...

So 1.9.3 is twice as bad as 1.9.2 again....

I see your bench script, but what is missing is the generator for the blank files. Please add it and I'll take a look to help you out debug this.

This sucks, but I was not able to reproduce this on Windows, or I least I think that...

Sorry my bad, I have added make_files.rb to the gist. Of interest, jruby sucks somewhat also. RBX isn't great but at least it's somewhat linear:

The increasing time in 1.9.3 and JRuby 1.6.1 may be partly due to the case insensitive require search. In order to prevent require 'date' and require 'DATE' requiring the same file twice on a case-insensitive filesystem, both JRuby and 1.9.3 will treat it as the same filename.

We definitely will want to look into this in JRuby, since there's clear evidence that something is nonlinear over time wrt require speed.

@headius if no one is already looking at it in jruby, I plan to jump ship and dive in after I've done what I can with MRI.

There's been some recent pull requests with require improvements...those are only landed on master (and maybe the 1.6 branch). I think they improve things in the neighborhood of 10%.

If you do start looking into it, there's a couple JRuby flags that will help:

-Xdebug.loadService=true turns on logging of what paths the load/require process is searching, along with what path it finally uses to load a resource. It will show how many searches are being done; we do more than 1.9 because we search for both .rb and .class (compiled script) on the filesystem...plus we search JVM classloader resources. That's likely why load/require file searches take longer in JRuby.

-Xdebug.loadService.timing=true will log how long files take to require/load, including child requires/loads. This mostly measures the time for individual files and how long they take to parse, but it can sometimes show file searching costs too (especially for classloader-located resources).

Let me know when you start poking around and I'll do what I can to help.

For those playing along at home, here is the latest progress update: http://redmine.ruby-lang.org/issues/show/3924
Turns out there's already a case-insensitive hash in MRI (st.h) which certainly made things easier.

(note this graph is versus 1.8.7 over a larger number of files)

I'm going to look into improving the LOADED_FEATURES array as well, probably by making it use a case-insensitive Set or Map for searches internally. I see now that's likely a primary bottleneck when lots of features are getting loaded, due to the O(N) search every time.

Well I wasn't able to open an issue on your ruby fork, but I ran your blog post scripts and got an error when trying to run rails s --debug (so using ruby-debug19)

Error:

/home/jenny/.rvm/gems/ruby-head-patched/bundler/gems/rails-62d5ef0c17b4/activesupport/lib/active_support/dependencies.rb:236:in `require': /home/jenny/.rvm/gems/ruby-head-patched/gems/ruby-debug-base19-0.11.25/lib/ruby_debug.so: undefined symbol: ruby_thread_data_type - /home/jenny/.rvm/gems/ruby-head-patched/gems/ruby-debug-base19-0.11.25/lib/ruby_debug.so (LoadError)
from /home/jenny/.rvm/gems/ruby-head-patched/bundler/gems/rails-62d5ef0c17b4/activesupport/lib/active_support/dependencies.rb:236:in `block in require'
from /home/jenny/.rvm/gems/ruby-head-patched/bundler/gems/rails-62d5ef0c17b4/activesupport/lib/active_support/dependencies.rb:222:in `block in load_dependency'
from /home/jenny/.rvm/gems/ruby-head-patched/bundler/gems/rails-62d5ef0c17b4/activesupport/lib/active_support/dependencies.rb:616:in `new_constants_in'
from /home/jenny/.rvm/gems/ruby-head-patched/bundler/gems/rails-62d5ef0c17b4/activesupport/lib/active_support/dependencies.rb:222:in `load_dependency'
from /home/jenny/.rvm/gems/ruby-head-patched/bundler/gems/rails-62d5ef0c17b4/activesupport/lib/active_support/dependencies.rb:236:in `require'
from /home/jenny/.rvm/gems/ruby-head-patched/gems/ruby-debug-base19-0.11.25/lib/ruby-debug-base.rb:1:in `<top (required)>'
from /home/jenny/.rvm/gems/ruby-head-patched/bundler/gems/rails-62d5ef0c17b4/activesupport/lib/active_support/dependencies.rb:236:in `require'
from /home/jenny/.rvm/gems/ruby-head-patched/bundler/gems/rails-62d5ef0c17b4/activesupport/lib/active_support/dependencies.rb:236:in `block in require'
from /home/jenny/.rvm/gems/ruby-head-patched/bundler/gems/rails-62d5ef0c17b4/activesupport/lib/active_support/dependencies.rb:222:in `block in load_dependency'
from /home/jenny/.rvm/gems/ruby-head-patched/bundler/gems/rails-62d5ef0c17b4/activesupport/lib/active_support/dependencies.rb:616:in `new_constants_in'
from /home/jenny/.rvm/gems/ruby-head-patched/bundler/gems/rails-62d5ef0c17b4/activesupport/lib/active_support/dependencies.rb:222:in `load_dependency'
from /home/jenny/.rvm/gems/ruby-head-patched/bundler/gems/rails-62d5ef0c17b4/activesupport/lib/active_support/dependencies.rb:236:in `require'
from /home/jenny/.rvm/gems/ruby-head-patched/gems/ruby-debug19-0.11.6/cli/ruby-debug.rb:5:in `<top (required)>'
from /home/jenny/.rvm/gems/ruby-head-patched/gems/bundler-1.0.14/lib/bundler/runtime.rb:68:in `require'
from /home/jenny/.rvm/gems/ruby-head-patched/gems/bundler-1.0.14/lib/bundler/runtime.rb:68:in `block (2 levels) in require'
from /home/jenny/.rvm/gems/ruby-head-patched/gems/bundler-1.0.14/lib/bundler/runtime.rb:66:in `each'
from /home/jenny/.rvm/gems/ruby-head-patched/gems/bundler-1.0.14/lib/bundler/runtime.rb:66:in `block in require'
from /home/jenny/.rvm/gems/ruby-head-patched/gems/bundler-1.0.14/lib/bundler/runtime.rb:55:in `each'
from /home/jenny/.rvm/gems/ruby-head-patched/gems/bundler-1.0.14/lib/bundler/runtime.rb:55:in `require'
from /home/jenny/.rvm/gems/ruby-head-patched/gems/bundler-1.0.14/lib/bundler.rb:120:in `require'
from /home/jenny/Projects/GoldenCMS/config/application.rb:7:in `<top (required)>'
from /home/jenny/.rvm/gems/ruby-head-patched/bundler/gems/rails-62d5ef0c17b4/railties/lib/rails/commands.rb:56:in `require'
from /home/jenny/.rvm/gems/ruby-head-patched/bundler/gems/rails-62d5ef0c17b4/railties/lib/rails/commands.rb:56:in `block in <top (required)>'
from /home/jenny/.rvm/gems/ruby-head-patched/bundler/gems/rails-62d5ef0c17b4/railties/lib/rails/commands.rb:53:in `tap'
from /home/jenny/.rvm/gems/ruby-head-patched/bundler/gems/rails-62d5ef0c17b4/railties/lib/rails/commands.rb:53:in `<top (required)>'
from script/rails:6:in `require'
from script/rails:6:in `<main>'

(Same error occurs just running 'rails s')

At this point I wish I was more knowledgeable in ruby, but I'm afraid I don't have the time at the moment to dive into the issue. Maybe later today after I get some work done.

As a side note, this same rails project runs fine using:

• MRI 1.9.2
• rails3.1
• ruby-debug19
• ect...

Only differences in environment to trigger the code:

• MRI-1.9.2 <--> MRI-1.9.3
• Your patch

urgh that doesn't look friendly. Are you able to try on 1.9.3 without my patch?

Thanks for trying it out!

Ah yep... the same error occurred using straight 1.9.3dev.
Well in a strange sense I'm pumped your patch still looks good! Thanks for all the work your putting into this!

Cheers!