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!
This ticket was migrated from http://rubyforge.org/tracker/?func=detail&atid=575&aid=29116&group_id=126
Comments From RubyForge Ticket Below
Date: 2011-06-01 08:31
Sender: Dan Peterson
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
Date: 2011-06-01 02:53
Sender: Evan Phoenix
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?
Date: 2011-05-30 17:47
Sender: Nick Rogers
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
- [F] log4r
- [F] netaddr
- [F] ntp
- [F] hoe >= 1.2.0
- [F] rubyforge >= 2.0.4
- [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
Date: 2011-05-23 20:32
Sender: Ryan Davis
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.
Date: 2011-05-23 19:47
Sender: Ryan Davis
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.
Date: 2011-05-23 11:20
Sender: Dan Peterson
This is still happening in 1.8.3.
Date: 2011-05-04 21:42
Sender: Dan Peterson
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.
Date: 2011-04-05 14:07
Sender: Sam Goldstein
More info on gem dependencies and installed gems.
$ rake gems
(in /www/aboutus/compostus/compost)
- [F] thrift_client ~> 0.4.3
- [I] thrift = 0.2.0.4
- [F] simple_uuid = 0.1.1
- [F] cassandra = 0.8.2
- [F] thrift_client >= 0.4.0
- [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
- [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
- [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
- [F] less = 1.2.21
- [F] treetop >= 1.4.2
- [F] mutter >= 0.4.2
- [F] treetop = 1.4.8
- [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)
Date: 2011-04-05 14:02
Sender: Sam Goldstein
BTW the first environment load was with gem version 1.3.5