Skip to content

Instantly share code, notes, and snippets.

@xaviershay
Created April 30, 2011 22:53
  • Star 0 You must be signed in to star a gist
  • Fork 0 You must be signed in to fork a gist
Star You must be signed in to star a gist
Save xaviershay/c8d0d422a9203e1fe492 to your computer and use it in GitHub Desktop.
`mkdir f`
10000.times do |x|
`touch f/bogus#{x}.rb`
end
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
@rdp
Copy link

rdp commented May 2, 2011

did you benchmark in linux, I presume?

@xaviershay
Copy link
Author

no this was OSX. If you have a linux box handy please do test, the initial investigation I've done shows that a large component of the slowdown in 1.9.2 is algorithmic though.

@rdp
Copy link

rdp commented May 2, 2011

I guess one could use virtualbox on OS X [that's what I use typically...]

@luislavena
Copy link

@xaviershay have you compared this against latest ruby trunk?

@xaviershay
Copy link
Author

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

@luislavena
Copy link

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

@xaviershay
Copy link
Author

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

@luislavena
Copy link

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

@xaviershay
Copy link
Author

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:

@headius
Copy link

headius commented May 14, 2011

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.

@xaviershay
Copy link
Author

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

@headius
Copy link

headius commented May 14, 2011

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.

@xaviershay
Copy link
Author

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)

@headius
Copy link

headius commented May 16, 2011

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.

@chaffeqa
Copy link

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

@xaviershay
Copy link
Author

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

Thanks for trying it out!

@chaffeqa
Copy link

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!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment