Bugs item #29116, was opened at 2011-04-05 15:01
You can respond by visiting:
http://rubyforge.org/tracker/?func=detail&atid=575&aid=29116&group_id=126
Category: #gem and #require methods
Group: None
Status: Open
Resolution: None
Priority: 3
Submitted By: Sam Goldstein (samgoldstein)
Assigned to: Ryan Davis (zenspider)
Summary: Mega slowness in custom require
Initial Comment:
I recently upgraded to rubygems 1.6.5 and started experiencing a major slowdown
loading the environment for a Rails 2.3 application.
I traced the problem back to the Kernel.require (custom_require.rb) and
Gem.loaded_path?. It seems that searching $LOADED_FEATURES repeatedly is
inefficient and results in a 4x slowdown in my specific case.
I've downgraded to rubygems 1.3.5 which doesn't suffer from this problem. This
is a major hurdle to developing in ruby, as it takes me ~45 seconds to load the
environment and run one test.
Below is some console output demonstrating the problem.
/www/aboutus/app_root [master] $ time rake environment
(in /www/aboutus/app_root)
real 0m11.407s
user 0m8.787s
sys 0m2.552s
/www/aboutus/app_root [master] $ sudo gem update --system
Updating RubyGems
Updating rubygems-update
Successfully installed rubygems-update-1.7.1
Updating RubyGems to 1.7.1
Installing RubyGems 1.7.1
RubyGems 1.7.1 installed
=== 1.7.1 / 2011-03-32
* 1 bug fix:
* Fixed missing file in Manifest.txt. (Also a bug in hoe was fixed where
`rake check_manifest` showing a diff would not exit with an error.)
------------------------------------------------------------------------------
RubyGems installed the following executables:
/usr/local/bin/gem
/www/aboutus/app_root [master] $ time rake environment
(in /www/aboutus/app_root)
NOTE: SourceIndex.new(hash) is deprecated; From
/www/aboutus/app_root/config/../vendor/rails/railties/lib/rails/vendor_gem_source_index.rb:100:in
`new'.
real 0m46.707s
user 0m41.200s
sys 0m5.394s
Thanks!
----------------------------------------------------------------------
Comment By: Dan Peterson (dpiddy)
Date: 2011-06-01 09:31
Message:
Here's what my test case looks like with 1.5.2, 1.8.5 and master after Evan's
change:
# 1.5.2
eye help 1.26s user 0.26s system 99% cpu 1.526 total
# 1.8.5
eye help 9.85s user 0.61s system 100% cpu 10.455 total
# master
eye help 5.44s user 0.51s system 100% cpu 5.947 total
----------------------------------------------------------------------
Comment By: Evan Phoenix (evan)
Date: 2011-06-01 03:53
Message:
I've moved the regexp creation outside the find block. Could someone who's
seeing the issue report back how much of a difference it made?
----------------------------------------------------------------------
Comment By: Nick Rogers (tsp435cds)
Date: 2011-05-30 18:47
Message:
I am experiencing the same problem with my rails 2.3.11 application, recently
upgraded from rubygems 1.3.7 to 1.7.2. Time to initialize rails is an abysmal
average of 30s instead of 5s, and I use only a handful of gems.
~/rxg/console: rake gems
(in /Users/nick/rxg/console)
- [F] attr_encrypted
- [F] eigenclass >= 1.1.1
- [F] encryptor >= 1.1.0
- [F] mocha >= 0.9.8
- [R] rake
- [F] log4r
- [F] netaddr
- [F] ntp
- [F] hoe >= 1.2.0
- [F] rubyforge >= 2.0.4
- [R] json_pure >= 1.1.7
- [R] rake >= 0.8.7
- [F] SystemTimer
- [F] rack
- [F] savon
- [F] builder >= 2.1.2
- [F] crack >= 0.1.4
- [F] surpass
I = Installed
F = Frozen
R = Framework (loaded before rails starts)
~/rxg/console:
I concur that the problem is with custom_require, specifically Gem#loaded_path?
and possibly elsewhere.
Glancing at rubygems.rb, there are a number of careless instances of what
should be loop invariant variables being re-computed within a loop. For
example, the following change yielded a 50% performance increase to my rails
app load time, however it was still not as good as under rubygems 1.3.7.
*** rubygems-1.7.2-original/lib/rubygems.rb 2011-04-05 16:59:14.000000000
-0400
--- rubygems-1.7.2/lib/rubygems.rb 2011-05-30 17:20:56.000000000 -0400
***************
*** 1086,1093 ****
def self.loaded_path? path
# TODO: ruby needs a feature to let us query what's loaded in 1.8 and 1.9
$LOADED_FEATURES.find { |s|
! s =~ /(^|\/)#{Regexp.escape path}#{Regexp.union(*Gem.suffixes)}$/
}
end
--- 1086,1095 ----
def self.loaded_path? path
# TODO: ruby needs a feature to let us query what's loaded in 1.8 and 1.9
+ escaped_path = Regexp.escape(path)
+ union_suffixes = Regexp.union(*Gem.suffixes)
$LOADED_FEATURES.find { |s|
! s =~ /(^|\/)#{escaped_path}#{union_suffixes}$/
}
end
----------------------------------------------------------------------
Comment By: Ryan Davis (zenspider)
Date: 2011-05-23 21:32
Message:
More data, this time with a bit more cleanup and working against rails 2.3.12
(coming RSN) so that deprecations are cleaned up:
repo=before-clean repo=after-clean
number of gems: 280 number of gems: 175
1.3.7
real 0m2.113s real 0m1.901s
user 0m1.762s user 0m1.582s
sys 0m0.339s sys 0m0.314s
1.7.2
real 0m7.269s real 0m1.639s
user 0m6.836s user 0m1.405s
sys 0m0.417s sys 0m0.222s
1.8.2
real 0m7.947s real 0m1.920s
user 0m7.488s user 0m1.680s
sys 0m0.413s sys 0m0.228s
Kinda scary how much those 105 gems affect stuff.
----------------------------------------------------------------------
Comment By: Ryan Davis (zenspider)
Date: 2011-05-23 20:47
Message:
Much of this slowdown occurred as a result of us fixing complex gem dependency
resolution bugs. Unfortunately, we're not in a good place to do too much to
address this issue right now. I will point out that in both old (< 1.4)
rubygems and newer, that the time is going to be proportional to the amount of
gems installed. Keeping around a bunch of old stuff you're not using will only
harm you in any version.
I did get a repro using MOST of what Sam reported. I couldn't install some gems
because I didn't have requisite libraries (eg I never use mysql, so it couldn't
build) and some of his gems are not in the main gem repo. Of his 287 gems
(WOW!) I was able to install 273 of them.
Until I tried out a rails app, EVERY timing I tried to do wound up at least 25%
faster in 1.7/1.8 over 1.3.7. Once we got to really complex graphs of
activation (read: rails), I was able to get a repro where 1.7/1.8 was slower. I
got the following times while loading a rails 2.3.4 config/environment.rb file:
repo=xxx; before 'gem clean'
number of gems: 273
1.3.7
real 0m1.492s
user 0m1.230s
sys 0m0.256s
1.7.2
real 0m3.533s
user 0m3.281s
sys 0m0.242s
1.8.2
real 0m3.998s
user 0m3.731s
sys 0m0.261s
I copied that repo and ran gem clean on it (and reinstalled rails 2.3.4 because
rails 3 wiped it out on cleanup!) and got the following MUCH better times:
repo=yyy; after 'gem clean'
number of gems: 183
1.3.7
real 0m1.288s
user 0m1.054s
sys 0m0.231s
1.7.2
real 0m1.106s
user 0m0.932s
sys 0m0.169s
1.8.2
real 0m1.365s
user 0m1.181s
sys 0m0.179s
So... that's the workaround for now. I'll do what I can to profile and
optimize, but I can't promise much for the next release, partially because we
don't have enough test coverage on this aspect of rubygems.
----------------------------------------------------------------------
Comment By: Dan Peterson (dpiddy)
Date: 2011-05-23 12:20
Message:
This is still happening in 1.8.3.
----------------------------------------------------------------------
Comment By: Dan Peterson (dpiddy)
Date: 2011-05-04 22:42
Message:
I have seen this as well for something non-Rails. Using `rvm rubygems` I saw
the slowness started with 1.6.0. Haven't had a chance to really dig into it
more yet.
----------------------------------------------------------------------
Comment By: Sam Goldstein (samgoldstein)
Date: 2011-04-05 15:07
Message:
More info on gem dependencies and installed gems.
$ rake gems
(in /www/aboutus/compostus/compost)
- [F] thrift_client ~> 0.4.3
- [I] thrift
- [I] thrift = 0.2.0.4
- [F] simple_uuid = 0.1.1
- [F] cassandra = 0.8.2
- [F] thrift_client >= 0.4.0
- [I] thrift
- [I] json
- [R] rake
- [F] simple_uuid >= 0.1.0
- [F] rack ~> 1.0.0
- [F] diff-lcs = 1.1.2
- [I] ffi ~> 0.6.0
- [R] rake >= 0.8.7
- [F] haml
- [I] libxml-ruby
- [I] hpricot >= 0.8.1
- [I] json
- [I] mysql = 2.8.1
- [F] net-ssh
- [F] ya2yaml = 0.26
- [F] ruby-openid = 2.1.6
- [F] mechanize = 1.0.0
- [I] nokogiri >= 1.2.1
- [I] nokogiri
- [F] composite_primary_keys = 2.2.2
- [R] activerecord >= 2.2.0
- [F] aws-s3 = 0.6.2
- [F] xml-simple
- [F] builder
- [F] mime-types
- [F] right_aws
- [F] right_http_connection >= 1.2.4
- [F] fastercsv = 1.5.0
- [I] levenshtein
- [F] newrelic_rpm = 2.13.4
- [F] after_commit ~> 1.0.7
- [R] activerecord
- [F] less = 1.2.21
- [F] treetop >= 1.4.2
- [F] polyglot >= 0.3.1
- [F] mutter >= 0.4.2
- [F] treetop = 1.4.8
- [F] polyglot >= 0.3.1
- [F] mime-types = 1.16
- [I] curb = 0.7.8
I = Installed
F = Frozen
R = Framework (loaded before rails starts)
$ gem list
abstract (1.0.0)
actionmailer (3.0.5, 3.0.3, 2.3.4, 2.2.2)
actionpack (3.0.5, 3.0.3, 2.3.4, 2.2.2)
activemodel (3.0.5, 3.0.3)
activerecord (3.0.5, 3.0.3, 2.3.4, 2.2.2)
activeresource (3.0.5, 3.0.3, 2.3.4, 2.2.2)
activesupport (3.0.5, 3.0.3, 2.3.11, 2.3.8, 2.3.7, 2.3.5,
2.3.4, 2.2.2)
acts_as_commentable (3.0.1, 2.0.2)
addressable (2.2.4)
after_commit (1.0.7, 1.0.5)
amatch (0.2.3)
amazon_sdb (0.6.7)
amqp (0.6.0)
ar-extensions (0.8.0)
arel (2.0.9, 2.0.8)
au_document_parser (0.5.3, 0.4.3, 0.4.2, 0.4.1, 0.4.0,
0.3.2, 0.3.1, 0.3.0, 0.2.4)
autotest-growl (0.1.7)
aws-s3 (0.6.2)
babel (0.1.4)
builder (2.1.2)
bundler (1.0.10)
capistrano (2.5.5)
capybara (0.3.0)
carmen (0.2.5)
cassandra (0.7.2, 0.6)
cgi_multipart_eof_fix (2.5.0)
cheat (1.2.1)
chronic (0.3.0, 0.2.3)
clearance (0.10.3.2, 0.8.8, 0.8.3)
compass (0.8.17)
compass-960-plugin (0.9.11)
composite_primary_keys (2.2.2)
configuration (1.1.0)
crack (0.1.4)
cucumber (0.10.2, 0.6.3, 0.6.2)
cucumber-rails (0.3.2, 0.2.4, 0.2.3)
culerity (0.2.6)
curb (0.7.8, 0.7.7.1, 0.7.1)
daemons (1.0.10)
database_cleaner (0.4.3)
diesel (0.1.4)
diff-lcs (1.1.2)
differ (0.1.1)
diffy (2.0.1)
dirb (1.0.0, 0.1.1, 0.1.0)
duration (0.1.0)
erubis (2.6.6)
eventmachine (0.12.10)
factory_girl (1.2.3)
fakefs (0.2.1)
faker (0.3.1)
faraday (0.5.7)
fastercsv (1.5.0)
fastthread (1.0.7)
ffi (0.6.3, 0.5.4, 0.5.3)
file-tail (1.0.4)
fixjour (0.1.6)
flexmock (0.8.6)
gem_plugin (0.2.3)
gemcutter (0.5.0)
geminstaller (0.5.4)
geokit (1.5.0)
getopt-declare (1.28)
gherkin (2.3.5)
git (1.2.5)
gltail (0.1.8)
gravatar (1.0)
grit (2.0.0, 1.1.1)
haml (3.0.25, 3.0.13, 2.2.19, 2.2.9)
heroku (1.9.8)
highline (1.5.1)
hoe (2.3.3)
hpricot (0.8.1)
httparty (0.5.0)
i18n (0.5.0)
icalendar (1.1.2, 1.1.0)
jeweler (1.4.0)
jm81-whois (0.5.0)
json (1.4.6, 1.2.0, 1.1.6)
json_pure (1.2.0)
launchy (0.3.3)
less (1.2.21)
levenshtein (0.2.0)
libxml-ruby (1.1.3)
log4r (1.1.9)
lorem (0.1.2)
macaddr (1.0.0)
mail (2.2.15, 1.5.2)
maruku (0.6.0)
mechanize (1.0.0, 0.9.3)
memcache-client (1.7.4)
micronaut (0.3.0)
mime-types (1.16)
mkrf (0.2.3)
mocha (0.9.8)
mongrel (1.1.5)
more (0.1.1)
multi_json (0.0.5)
multipart-post (1.1.0)
mutter (0.5.3)
mysql (2.8.1)
needle (1.3.0)
net-scp (1.0.2)
net-sftp (2.0.4, 1.1.0)
net-ssh (2.0.15, 1.1.4, 1.0.10)
net-ssh-gateway (1.0.1)
newrelic_rpm (2.14.0, 2.9.9, 2.9.8, 2.9.3)
nkallen-cache-money (0.2.5)
nokogiri (1.4.0)
open4 (1.0.1)
paperclip (2.3.1.1)
parseexcel (0.5.2)
polyglot (0.3.1, 0.3.0, 0.2.9)
rack (1.2.2, 1.2.1, 1.0.1)
rack-mount (0.6.14, 0.6.13)
rack-rewrite (1.0.2)
rack-test (0.5.7, 0.5.3)
rails (3.0.5, 3.0.3, 2.3.4, 2.2.2)
railties (3.0.5, 3.0.3)
rake (0.8.7, 0.8.3)
rcov (0.9.6)
RedCloth (4.2.2)
redis (2.1.1)
redis-namespace (0.10.0)
resque (1.13.0)
rest-client (1.4.2)
riddle (1.0.11, 1.0.8)
right_aws (1.10.0)
right_http_connection (1.2.4)
rpx_now (0.6.11)
rspec (2.5.0, 1.3.0, 1.2.9, 1.2.7)
rspec-core (2.5.1)
rspec-expectations (2.5.0)
rspec-mocks (2.5.0)
rspec-rails (2.5.0, 1.3.2, 1.2.9, 1.2.7)
ruby-aws (1.2.0)
ruby-graphviz (0.9.21)
ruby-ole (1.2.10.1)
ruby-opengl (0.60.1)
ruby-openid (2.1.6)
ruby-prof (0.9.2, 0.8.1)
rubyforge (2.0.4, 2.0.3)
rubygems-update (1.7.1, 1.6.2)
RubyInline (3.8.1)
rufus-tokyo (0.1.14)
rvm (0.0.98)
selenium-webdriver (0.0.14)
sequel (3.14.0, 3.9.0, 3.6.0)
simple_uuid (0.0.2)
sinatra (1.2.1, 1.1.2, 1.0, 0.9.5)
slave (1.2.1)
smurf (1.0.3)
snailgun (1.0.6)
spork (0.7.5)
spreadsheet (0.6.4.1)
sqlite3 (1.3.3)
sqlite3-ruby (1.3.3, 1.2.5)
stemmer (1.0.1)
syntax (1.0.0)
technicalpickles-jeweler (1.2.1)
term-ansicolor (1.0.5, 1.0.4)
Text (1.1.2)
thinking-sphinx (1.3.18, 1.3.14)
thor (0.14.6)
thoughtbot-factory_girl (1.2.2)
thrift (0.2.0.4)
thrift_client (0.3.3, 0.3.1)
tilt (1.2.2)
timetrap (1.7.4, 1.4.0, 1.3.0, 1.2.1, 1.2.0, 1.1.3, 1.1.2)
treetop (1.4.9, 1.4.8, 1.4.2)
tzinfo (0.3.26, 0.3.25, 0.3.24)
uuid (2.1.0, 2.0.1)
uuidtools (2.1.2, 2.1.1)
vegas (0.1.8)
vlad (1.3.2)
webrat (0.7.0, 0.6.0, 0.4.4)
will_paginate (2.3.11)
xhtmldiff (1.0.0)
xml-simple (1.0.14, 1.0.12)
xmpp4r (0.4)
ya2yaml (0.26)
ZenTest (4.1.4)
----------------------------------------------------------------------
Comment By: Sam Goldstein (samgoldstein)
Date: 2011-04-05 15:02
Message:
BTW the first environment load was with gem version 1.3.5
----------------------------------------------------------------------
You can respond by visiting:
http://rubyforge.org/tracker/?func=detail&atid=575&aid=29116&group_id=126
_______________________________________________
Rubygems-developers mailing list
http://rubyforge.org/projects/rubygems
Rubygems-developers@rubyforge.org
http://rubyforge.org/mailman/listinfo/rubygems-developers
