slow rubygems?
rogerdpack
Even using faster_require (which basically provides us with omniscient
reads), this file in 1.9:
require 'rubygems'
Gem.bin_path 'redcar'
%self total self wait child calls name
47.65 2.17 2.17 0.00 0.00 98 <Class::IO>#read
28.12 1.40 1.28 0.00 0.12 96
Gem::Specification#initialize
6.14 1.95 0.28 0.00 1.67 110 Kernel#eval(d1)
4.14 0.19 0.19 0.00 0.00 9
Kernel#original_non_cached_require
3.64 0.17 0.17 0.00 0.00 240 <Class::Dir>#[]
1.64 3.93 0.07 0.00 3.85 96
<Class::Gem::SourceIndex>#load_specification
4s to load the specifications? what?
So there are two problems on doze, then...requires are slow and also
rubygems is just taking forever to bootstrap itself???
The latter problem has also been noted by jruby on Linux, since it
requires extra bootstrap time...hmm...
One possibility to fix might be (as Charles discovered) to cache the
gemspecs as Marshalled versions of themselves.
Another might be to only load gemspec files on demand (?)
Of course, you can get around it currently by using the
faster_rubygems package for 1.8, or (on 1.9) never calling
Gem.anything
But still, this feels messed.
-r
refs:
http://www.ruby-forum.com/topic/204926#new
http://www.ruby-forum.com/topic/204693#new
rogerdpack
> So there are two problems on doze, then...requires are slow and also
> rubygems is just taking forever to bootstrap itself???
>
> The latter problem has also been noted by jruby on Linux, since it
> requires extra bootstrap time...hmm...
>
> One possibility to fix might be (as Charles discovered) to cache the
> gemspecs as Marshalled versions of themselves.
>
> Another might be to only load gemspec files on demand (?)
threads (jruby, anyway),
to load the yaml library "on demand", to release a patched rubygems
that basically implements http://github.com/rdp/faster_gem_script by
default...
-rp
Charles Oliver Nutter
to the number of gems you have installed, which I feel is a RubyGems
flaw. The more gems, the more specifications have to be scanned, the
more directories get searched for plugins, and so on. The fastest way
to improve your RubyGems startup is to remove all your gems.
Threading might help a bit on systems with multiple cores if the
specifications can be loaded in parallel, but the "one big serialized
aggregate specification" is still the fastest option.
I talked again with Yehuda about the various attempts he's made at
hacking in such a "master" index, and we may revisit it only for JRuby
since it doesn't seem like it would get into RubyGems proper.
rogerdpack
> to the number of gems you have installed, which I feel is a RubyGems
> flaw. The more gems, the more specifications have to be scanned, the
> more directories get searched for plugins, and so on. The fastest way
> to improve your RubyGems startup is to remove all your gems.
that's not enough for windows, it might be with jruby.
Bigger gems, like rdoc-data take something like 1.3 seconds to *load
the specification* for me on windows. Wow.
I had toyed with the idea of "lazy loading" specifications...
Another possible idea might be to not scan directories for plugins--
the specification already lists the files.
> Threading might help a bit on systems with multiple cores if the
> specifications can be loaded in parallel, but the "one big serialized
> aggregate specification" is still the fastest option.
core box with jruby?
> I talked again with Yehuda about the various attempts he's made at
> hacking in such a "master" index, and we may revisit it only for JRuby
> since it doesn't seem like it would get into RubyGems proper.
releasing my own version, too...
-rp
Charles Oliver Nutter
>> I'm playing with it a bit this evening. It's definitely very sensitive
>> to the number of gems you have installed, which I feel is a RubyGems
>> flaw. The more gems, the more specifications have to be scanned, the
>> more directories get searched for plugins, and so on. The fastest way
>> to improve your RubyGems startup is to remove all your gems.
>
> Agreed. And to never load rubygems in the first place, really...except
> that's not enough for windows, it might be with jruby.
>
> Bigger gems, like rdoc-data take something like 1.3 seconds to *load
> the specification* for me on windows. Wow.
>
> I had toyed with the idea of "lazy loading" specifications...
>
> Another possible idea might be to not scan directories for plugins--
> the specification already lists the files.
Ideally RubyGems would do all the spec-loading and dir-scanning as
each gem is installed or removed, saving the result off to a single
marshalable file it can load for normal startup. It shouldn't ever
have to re-load specs or re-scan dirs from disk, since nobody should
ever be twiddling the guts of gems in-place.
If we could shunt all that processing to install time, startup would
be a lot better. My timings show that there's two major jumps in time
when JRuby's loading RubyGems:
* Loading libraries related to RubyGems, especially yaml, which pulls
in date. This is simple JRuby file parsing and execution speed, and
there's only so much we can do to improve it. JRuby's just not fast at
these things during the first few seconds of execution (nothing's
jitted even at the Java level yet).
* Loading all the specs. This is also file parsing and execution time
plus some filesystem-walking time. In my run with around 250
locally-installed gems, it adds up to around 1.2-1.5s to load the
specifications (and this may include the dir globbing and filesystem
walking as well). Basically all of this could go away.
>> Threading might help a bit on systems with multiple cores if the
>> specifications can be loaded in parallel, but the "one big serialized
>> aggregate specification" is still the fastest option.
>
> Faster than "two big serialized aggregates in two threads" on a multi
> core box with jruby?
If we had it down to a serialized aggregate, the main bottleneck
becomes marshalling from disk. Parallelizing that might help a little,
but it's still mostly just reading data from disk and creating objects
in memory...very little actual CPU used.
>> I talked again with Yehuda about the various attempts he's made at
>> hacking in such a "master" index, and we may revisit it only for JRuby
>> since it doesn't seem like it would get into RubyGems proper.
>
> Yeah I've definitely toyed with the idea of forking rubygems and
> releasing my own version, too...
Well, maybe that's the direction we need to go, at least for
alternative impls. We should poke Yehuda to release some of his
patches and try to refine them. He never tried to get them into
RubyGems because they break RubyGems own tests that depend on the old
behavior, but I think it's time to do something about it.
- Charlie
Roger Pack
> each gem is installed or removed, saving the result off to a single
> marshalable file it can load for normal startup. It shouldn't ever
> have to re-load specs or re-scan dirs from disk, since nobody should
> ever be twiddling the guts of gems in-place.
Agreed.
> If we could shunt all that processing to install time, startup would
> be a lot better. My timings show that there's two major jumps in time
> when JRuby's loading RubyGems:
>
> * Loading libraries related to RubyGems, especially yaml, which pulls
> in date. This is simple JRuby file parsing and execution speed, and
> there's only so much we can do to improve it. JRuby's just not fast at
> these things during the first few seconds of execution (nothing's
> jitted even at the Java level yet).
So you think you can avoid this phase as well?
It seems that rubygems currently loads *every piece of rubygems* when
I just do a
require 'rubygems'
in 1.8.6:
>> require 'rubygems'
=> true
>> $LOADED_FEATURES.grep /rubygems/
=> ["rubygems/defaults.rb", "rubygems/exceptions.rb",
"rubygems/version.rb", "rubygems/requirement.rb",
"rubygems/dependency.rb", "rubygems/gem_path_searcher.rb",
"rubygems/user_interaction.rb", "rubygems/platform.rb",
"rubygems/specification.rb", "rubygems/source_index.rb",
"rubygems/builder.rb", "rubygems/config_file.rb",
"rubygems/custom_require.rb", "rubygems/command.rb",
"rubygems/command_manager.rb", "rubygems/commands/migrate.rb",
"rubygems/commands/tumble.rb", "rubygems/local_remote_options.rb",
"rubygems/remote_fetcher.rb", "rubygems/gemcutter_utilities.rb",
"rubygems/commands/webhook.rb", "rubygems/version_option.rb",
"rubygems/commands/yank.rb",
"rubygems/commands/specific_install_command.rb", "rubygems.rb"]
I don't even *need* remote_fetcher, or migrate, or gemcutter, or any
plugins. I just want to use gems, not create...and each of those
requires in windows takes awhile.
gem_prelude does help, in this regard, at least, but breaks in other
ways for 1.9
Another assumption we could build in is that "after install time, no
new files will be added to gems" or what not. That might be
reasonable. Or if not, to provide something like
$ gem update--indexes
or what not.
In reality, I'm not even sure why the gemspecs keep their file list
around, though I suppose the list of binary files is useful...the list
of lib files doesn't matter because at uninstall time it's just an "rm
-rf folder_name"...
I guess we could move this discussion to the rubygems-developers list,
except that the two times I've tried to join for some reason it hasn't
worked. Like Eric hasn't checked his email and allowed me access or
something. I'll assume it's because he just hasn't seen the emails.
> * Loading all the specs. This is also file parsing and execution time
> plus some filesystem-walking time. In my run with around 250
> locally-installed gems, it adds up to around 1.2-1.5s to load the
> specifications (and this may include the dir globbing and filesystem
> walking as well). Basically all of this could go away.
Yeah that should definitely be avoidable.
I'm starting to like yours/Yehuda's idea of storing it in a DB.
Assuming of course that the ultimate result somehow causes load times
to be less :)
>>> Threading might help a bit on systems with multiple cores if the
>>> specifications can be loaded in parallel, but the "one big serialized
>>> aggregate specification" is still the fastest option.
>>
>> Faster than "two big serialized aggregates in two threads" on a multi
>> core box with jruby?
>
> If we had it down to a serialized aggregate, the main bottleneck
> becomes marshalling from disk. Parallelizing that might help a little,
> but it's still mostly just reading data from disk and creating objects
> in memory...very little actual CPU used.
Are you using java serialization or Ruby marshal serialization?
> Well, maybe that's the direction we need to go, at least for
> alternative impls. We should poke Yehuda to release some of his
> patches and try to refine them. He never tried to get them into
> RubyGems because they break RubyGems own tests that depend on the old
> behavior, but I think it's time to do something about it.
Yeah. If I could get on the rubygems developers list I'd ask about
it. Barring that...
My latest thought has been to release a somewhat optimized version of
rubygems with the windows installers, but maybe some collaboration
would be nice.
I'd even be happy to work on something that basically rewrites gems
from scratch, like:
require 'lightweight_rubygems'
or what not.
The only functionality actually needed for just runtime use is (AFAIK)
gem 'xxx', '>= 0.9'
Gem.bin_path 'gem_name', 'binary_name'
Though you can avoid that last one if you assume absolute or relative
paths...which I think you can in Linux, at least?
That might be easy to implement something that does just that.
If they use something like
Gem.dependency 'abc'
Then they can load full blown gems.
I could almost see this as a rubygem plugin.
Gem.post_uninstall { |gem_installer_instance|
LightGems.rebuild_index! # or just add this one...
}
Maybe something that you install like
$ gem update --system
$ gem install light_weight_rubygems # overwrites a few gem files :)
?
-rp
Caleb Clausen
> Bigger gems, like rdoc-data take something like 1.3 seconds to *load
> the specification* for me on windows. Wow.
it takes to read that file, or is parsing somehow slow too? In other
words, does
File.read("rdoc-data.gemspec")
also take 1.3 seconds?
Charles Oliver Nutter wrote:
> Well, maybe that's the direction we need to go, at least for
> alternative impls. We should poke Yehuda to release some of his
> patches and try to refine them. He never tried to get them into
> RubyGems because they break RubyGems own tests that depend on the old
> behavior, but I think it's time to do something about it.
http://github.com/wycats/rubygems
Charles Oliver Nutter
>> If we could shunt all that processing to install time, startup would
>> be a lot better. My timings show that there's two major jumps in time
>> when JRuby's loading RubyGems:
>>
>> * Loading libraries related to RubyGems, especially yaml, which pulls
>> in date. This is simple JRuby file parsing and execution speed, and
>> there's only so much we can do to improve it. JRuby's just not fast at
>> these things during the first few seconds of execution (nothing's
>> jitted even at the Java level yet).
>
> So you think you can avoid this phase as well?
>
> It seems that rubygems currently loads *every piece of rubygems* when
> I just do a
> require 'rubygems'
> in 1.8.6:
Yup, that's a big problem; RubyGems just isn't sliced up nicely to
only load what you actually need at normal runtime.
At the bottom of this mail I've pasted in load timings for all
libraries that get pulled in during jruby -rubygems -e 1.
> Another assumption we could build in is that "after install time, no
> new files will be added to gems" or what not. That might be
> reasonable. Or if not, to provide something like
> $ gem update--indexes
> or what not.
>
> In reality, I'm not even sure why the gemspecs keep their file list
> around, though I suppose the list of binary files is useful...the list
> of lib files doesn't matter because at uninstall time it's just an "rm
> -rf folder_name"...
I think this would be a totally reasonably expectation. Almost nobody
modifies installed gems, so re-scanning every time is penalizing the
majority for no good reason.
>> * Loading all the specs. This is also file parsing and execution time
>> plus some filesystem-walking time. In my run with around 250
>> locally-installed gems, it adds up to around 1.2-1.5s to load the
>> specifications (and this may include the dir globbing and filesystem
>> walking as well). Basically all of this could go away.
>
> Yeah that should definitely be avoidable.
> I'm starting to like yours/Yehuda's idea of storing it in a DB.
> Assuming of course that the ultimate result somehow causes load times
> to be less :)
Deserializing the data should be faster than parsing and executing all
those files and walking all those dirs. If it's not, we're doing
something wrong :)
>> If we had it down to a serialized aggregate, the main bottleneck
>> becomes marshalling from disk. Parallelizing that might help a little,
>> but it's still mostly just reading data from disk and creating objects
>> in memory...very little actual CPU used.
>
> Are you using java serialization or Ruby marshal serialization?
I figured we'd just use Marshal, so it would be compatible with any Ruby impl.
> My latest thought has been to release a somewhat optimized version of
> rubygems with the windows installers, but maybe some collaboration
> would be nice.
> I'd even be happy to work on something that basically rewrites gems
> from scratch, like:
>
> require 'lightweight_rubygems'
>
> or what not.
> The only functionality actually needed for just runtime use is (AFAIK)
>
> gem 'xxx', '>= 0.9'
>
> Gem.bin_path 'gem_name', 'binary_name'
>
> Though you can avoid that last one if you assume absolute or relative
> paths...which I think you can in Linux, at least?
>
> That might be easy to implement something that does just that.
> If they use something like
> Gem.dependency 'abc'
>
> Then they can load full blown gems.
>
> I could almost see this as a rubygem plugin.
>
> Gem.post_uninstall { |gem_installer_instance|
> LightGems.rebuild_index! # or just add this one...
> }
>
> Maybe something that you install like
> $ gem update --system
> $ gem install light_weight_rubygems # overwrites a few gem files :)
Perhaps. I know that part of Bundler's reason for existing is to cut
RubyGems out of loading, so Yehuda and Carl will obviously have a lot
of thoughts on this. I know they've both considered forking RubyGems
or building a "new RubyGems" too.
Here's that load timing...note that although this adds up to more than
on MRI (cold JRuby parses and loads files somewhat slowly) it's still
only 0.5-1s of the whole process. The "Gem.load_plugins" line at the
bottom of rubygems.rb triggers the biggest hit since it loads all the
specs and whatnot:
~/projects/jruby ➔ jruby -J-Djruby.debug.loadService.timing=true -rubygems -e 1
-> enumerator
<- enumerator - 12ms
-> rubygems
-> rubygems/defaults
<- rubygems/defaults - 6ms
-> thread
<- thread - 5ms
-> etc
<- etc - 3ms
-> rbconfig
<- rbconfig - 97ms
-> rubygems/exceptions
<- rubygems/exceptions - 5ms
-> rubygems/version
<- rubygems/version - 10ms
-> rubygems/requirement
-> rubygems/version
<- rubygems/version - 0ms
<- rubygems/requirement - 6ms
-> rubygems/dependency
-> rubygems/requirement
<- rubygems/requirement - 0ms
<- rubygems/dependency - 14ms
-> rubygems/gem_path_searcher
<- rubygems/gem_path_searcher - 2ms
-> rubygems/source_index
-> rubygems/user_interaction
<- rubygems/user_interaction - 7ms
-> rubygems/specification
-> rubygems/version
<- rubygems/version - 0ms
-> rubygems/requirement
<- rubygems/requirement - 0ms
-> rubygems/platform
<- rubygems/platform - 5ms
<- rubygems/specification - 78ms
<- rubygems/source_index - 97ms
-> rubygems/platform
<- rubygems/platform - 0ms
-> rubygems/builder
-> rubygems/user_interaction
<- rubygems/user_interaction - 0ms
<- rubygems/builder - 3ms
-> rubygems/defaults/operating_system
<- rubygems/defaults/operating_system - 4ms
-> rubygems/defaults/jruby
-> rubygems/config_file
-> Win32API
-> rbconfig
<- rbconfig - 0ms
<- Win32API - 3ms
<- rubygems/config_file - 8ms
-> rbconfig
<- rbconfig - 0ms
-> rubygems/source_index
<- rubygems/source_index - 0ms
-> rubygems/defaults/jruby_native
<- rubygems/defaults/jruby_native - 1ms
<- rubygems/defaults/jruby - 12ms
-> rubygems/config_file
<- rubygems/config_file - 0ms
-> rubygems/custom_require
-> rubygems
<- rubygems - 0ms
<- rubygems/custom_require - 3ms
-> yaml
-> stringio
<- stringio - 100ms
-> yaml/compat
<- yaml/compat - 1ms
-> yaml/error
<- yaml/error - 0ms
-> yaml/yecht
-> yecht
<- yecht - 94ms
-> yaml/basenode
-> yaml/ypath
<- yaml/ypath - 1ms
<- yaml/basenode - 7ms
<- yaml/yecht - 102ms
-> yaml/tag
<- yaml/tag - 1ms
-> yaml/stream
<- yaml/stream - 1ms
-> yaml/constants
<- yaml/constants - 1ms
-> yaml/rubytypes
-> date
-> rational
<- rational - 6ms
-> date/format
-> rational
<- rational - 0ms
<- date/format - 28ms
<- date - 69ms
-> yaml/compat
<- yaml/compat - 0ms
<- yaml/rubytypes - 94ms
-> yaml/types
-> yaml/compat
<- yaml/compat - 0ms
<- yaml/types - 6ms
<- yaml - 319ms
-> yaml
<- yaml - 0ms
-> jruby/util
<- jruby/util - 2ms
-> time
-> parsedate
-> date/format
<- date/format - 1ms
<- parsedate - 1ms
<- time - 27ms
-> time
<- time - 0ms
-> time
<- time - 0ms
-> time
<- time - 0ms
-> time
<- time - 0ms
-> time
<- time - 0ms
-> time
<- time - 0ms
-> time
<- time - 0ms
-> time
<- time - 0ms
-> time
<- time - 1ms
-> rubygems/command_manager
-> timeout
<- timeout - 7ms
-> rubygems/command
-> optparse
<- optparse - 24ms
-> rubygems/user_interaction
<- rubygems/user_interaction - 0ms
<- rubygems/command - 34ms
-> rubygems/user_interaction
<- rubygems/user_interaction - 0ms
<- rubygems/command_manager - 44ms
<- rubygems - 1854ms
- Charlie
Caleb Clausen
> On Fri, Jun 11, 2010 at 1:36 PM, Roger Pack <roger...@gmail.com> wrote:
>> It seems that rubygems currently loads *every piece of rubygems* when
>> I just do a
>> require 'rubygems'
>> in 1.8.6:
>
> Yup, that's a big problem; RubyGems just isn't sliced up nicely to
> only load what you actually need at normal runtime.
Charlie, couldn't you cache the results of parsing/compiling a ruby file
so that it doesn't need to be so expensive on subsequent loads? Similar
to what rubinius does with its .rbc files? In fact, I'm a bit surprised
that you aren't doing this already, so maybe you are...
rogerdpack
> -> yecht
> <- yecht - 94ms
> -> yaml/basenode
> -> yaml/ypath
> <- yaml/ypath - 1ms
> <- yaml/basenode - 7ms
> <- yaml/yecht - 102ms
> <- rubygems - 1854ms
> it's still only 0.5-1s of the whole process. The "Gem.load_plugins" line at the
> bottom of rubygems.rb triggers the biggest hit since it loads all the
> specs and whatnot:
load_plugins when it loads the specs"
Bundler looks interesting. Looks like it basically "vendorifies"
gems, allows you to download them very concisely (and reproducibly),
and also, as a side-note, allows you to avoid using rubygems when
desired since it already has computed requirements for you. Not a
perfect match but that last part looks interesting and in common...
I'm starting to think that a rubygems wrapper might work quite well...
-r
rogerdpack
> I'm starting to think that a rubygems wrapper might work quite well...
The three things it needs to cover are:
Gem.bin_path 'xxx', 'yyy', 'version'
gem 'xxx', 'version'
and
require 'some_gems_filename'
I think we could handle these cases by writing a small cacheing
wrapper over the top of rubygems.
we can cache the Gem.bin_path results (easily, based on parameters)
gem 'xxx', 'yyy'
if uncached, load real rubygems, do some
gem 'xxx', 'yyy' on previously loaded, then run it again for current,
and cache the diff of $:
for
require 'file_in_lib_folder'
we can try the require, if it fails, check if we have it cached as a
valid gem lib file. If so, load that gem's lib paths, re-require. If
not, load full rubygems, re-try the require, cache the result.
So it's basically cache everything that gems does, and eventually you
won't need gems.
Benefits:
doesn't need a database, so quite cross platform.
Relies on normal rubygems, so we basically don't have to do much
version comparison or analysis.
I did something like this for faster_rubygems (gem prelude also does
something like this).
http://github.com/rdp/faster_rubygems
So it is possible.
I almost wish we *could* roll this into real rubygems somehow, as the
current speed for "those that don't have it" is really quite bad.
in 1.9 on windows:
> Benchmark.realtime { 100.times {begin; require 'nonex'; rescue LoadError; end } }
=> 4.34677600860596
I also ran into this: http://github.com/fabien/minigems
Interesting.
-rp
Charles Oliver Nutter
> What is yecht used for again?
yecht is our port of syck, the YAML parser.
>
>> <- rubygems - 1854ms
>
>> it's still only 0.5-1s of the whole process. The "Gem.load_plugins" line at the
>> bottom of rubygems.rb triggers the biggest hit since it loads all the
>> specs and whatnot:
>
> So this 1854ms includes the above load times "plus a lot on
> load_plugins when it loads the specs"
Correct.
Charles Oliver Nutter
> Charlie, couldn't you cache the results of parsing/compiling a ruby file
> so that it doesn't need to be so expensive on subsequent loads? Similar
> to what rubinius does with its .rbc files? In fact, I'm a bit surprised
> that you aren't doing this already, so maybe you are...
We used to do this in the days when our parser was a lot slower than
it is now. At some point, the parser speed passed the deserialization
speed and we opted to remove the feature.
However, that serialization was using the default JVM serialization
mechanism, which can be pretty slow. There's a more user-driven
mechanism that can be significantly faster but requires more code
(every object type you want to serialize needs a small snippit of code
to dump/load its fields). It's possible that using this faster
mechanism would again beat parse performance, so I'm going to look
into that possibility.
At the end of the day we're always going to have *something* running
slowly at startup, however, since almost all our code needs to be
jitted (as opposed to MRI and Rubinius, which have large amounts of
already-compiled C/C++ code, including the parser). The only solution
would be a C parser that produces JRuby AST (heh...not likely to
happen), or the hope that this other serialization mechanism would
warm up much sooner and run faster than parsing.
We'd also want a solution to the ".rbc turd" problem; I don't want to
start littering people's systems with pre-parsed dump files.
- Charlie
Charles Oliver Nutter
Yes, this sounds like the right direction, but I'm not a RubyGems
internals expert. Yehuda (for example) would know much better than I
(and so too, probably, would you).
> in 1.9 on windows:
>
>> Benchmark.realtime { 100.times {begin; require 'nonex'; rescue LoadError; end } }
> => 4.34677600860596
>
> I also ran into this: http://github.com/fabien/minigems
>
> Interesting.
This is actually a different but related problem: RubyGems causes
excessive load/require searching. Even for libraries that are *found*,
there's a massive amount of overhead in looking through all the
various paths and extensions. Here is more logging from JRuby showing
all paths searched just to load "active_support":
(Note that in JRuby we're also looking for precompiled .class files,
which adds to the overhead. Note also this is Rails 3, and I think it
may be using autoload for a lot of libraries eagerly-loaded before)
~/projects/jruby ➔ jruby -J-Djruby.debug.loadService=true -rubygems -e
"require 'active_support'"
LoadService: trying builtinLib: enumerator.class
LoadService: trying builtinLib: enumerator.rb
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/site_ruby/1.8/enumerator.class'
false false
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/site_ruby/1.8/enumerator.rb'
false false
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/site_ruby/shared/enumerator.class'
false false
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/site_ruby/shared/enumerator.rb'
false false
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/1.8/enumerator.class' false
false
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/1.8/enumerator.rb' false false
LoadService: trying resourceFromCWD:
/Users/headius/projects/jruby/enumerator.class
LoadService: trying resourceFromCWD: /Users/headius/projects/jruby/enumerator.rb
LoadService: trying builtinLib: enumerator.jar
LoadService: found builtinLib: enumerator.jar
LoadService: trying builtinLib: ubygems.class
LoadService: trying builtinLib: ubygems.rb
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/site_ruby/1.8/ubygems.class'
false false
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/site_ruby/1.8/ubygems.rb' true
true
LoadService: found:
file:/Users/headius/projects/jruby/lib/ruby/site_ruby/1.8/ubygems.rb
LoadService: trying builtinLib: rubygems.class
LoadService: trying builtinLib: rubygems.rb
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/site_ruby/1.8/rubygems.class'
false false
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/site_ruby/1.8/rubygems.rb'
true true
LoadService: found:
file:/Users/headius/projects/jruby/lib/ruby/site_ruby/1.8/rubygems.rb
LoadService: trying builtinLib: rubygems/defaults.class
LoadService: trying builtinLib: rubygems/defaults.rb
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/site_ruby/1.8/rubygems/defaults.class'
false false
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/site_ruby/1.8/rubygems/defaults.rb'
true true
LoadService: found:
file:/Users/headius/projects/jruby/lib/ruby/site_ruby/1.8/rubygems/defaults.rb
LoadService: trying builtinLib: thread.class
LoadService: trying builtinLib: thread.rb
LoadService: found builtinLib: thread.rb
LoadService: trying builtinLib: etc.class
LoadService: trying builtinLib: etc.rb
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/site_ruby/1.8/etc.class' false
false
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/site_ruby/1.8/etc.rb' false
false
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/site_ruby/shared/etc.class'
false false
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/site_ruby/shared/etc.rb' false
false
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/1.8/etc.class' false false
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/1.8/etc.rb' false false
LoadService: trying resourceFromCWD: /Users/headius/projects/jruby/etc.class
LoadService: trying resourceFromCWD: /Users/headius/projects/jruby/etc.rb
LoadService: trying builtinLib: etc.jar
LoadService: found builtinLib: etc.jar
LoadService: trying builtinLib: rbconfig.class
LoadService: trying builtinLib: rbconfig.rb
LoadService: found builtinLib: rbconfig.rb
LoadService: trying builtinLib: rubygems/exceptions.class
LoadService: trying builtinLib: rubygems/exceptions.rb
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/site_ruby/1.8/rubygems/exceptions.class'
false false
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/site_ruby/1.8/rubygems/exceptions.rb'
true true
LoadService: found:
file:/Users/headius/projects/jruby/lib/ruby/site_ruby/1.8/rubygems/exceptions.rb
LoadService: trying builtinLib: rubygems/version.class
LoadService: trying builtinLib: rubygems/version.rb
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/site_ruby/1.8/rubygems/version.class'
false false
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/site_ruby/1.8/rubygems/version.rb'
true true
LoadService: found:
file:/Users/headius/projects/jruby/lib/ruby/site_ruby/1.8/rubygems/version.rb
LoadService: trying builtinLib: rubygems/requirement.class
LoadService: trying builtinLib: rubygems/requirement.rb
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/site_ruby/1.8/rubygems/requirement.class'
false false
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/site_ruby/1.8/rubygems/requirement.rb'
true true
LoadService: found:
file:/Users/headius/projects/jruby/lib/ruby/site_ruby/1.8/rubygems/requirement.rb
LoadService: trying builtinLib: rubygems/dependency.class
LoadService: trying builtinLib: rubygems/dependency.rb
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/site_ruby/1.8/rubygems/dependency.class'
false false
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/site_ruby/1.8/rubygems/dependency.rb'
true true
LoadService: found:
file:/Users/headius/projects/jruby/lib/ruby/site_ruby/1.8/rubygems/dependency.rb
LoadService: trying builtinLib: rubygems/gem_path_searcher.class
LoadService: trying builtinLib: rubygems/gem_path_searcher.rb
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/site_ruby/1.8/rubygems/gem_path_searcher.class'
false false
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/site_ruby/1.8/rubygems/gem_path_searcher.rb'
true true
LoadService: found:
file:/Users/headius/projects/jruby/lib/ruby/site_ruby/1.8/rubygems/gem_path_searcher.rb
LoadService: trying builtinLib: rubygems/source_index.class
LoadService: trying builtinLib: rubygems/source_index.rb
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/site_ruby/1.8/rubygems/source_index.class'
false false
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/site_ruby/1.8/rubygems/source_index.rb'
true true
LoadService: found:
file:/Users/headius/projects/jruby/lib/ruby/site_ruby/1.8/rubygems/source_index.rb
LoadService: trying builtinLib: rubygems/user_interaction.class
LoadService: trying builtinLib: rubygems/user_interaction.rb
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/site_ruby/1.8/rubygems/user_interaction.class'
false false
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/site_ruby/1.8/rubygems/user_interaction.rb'
true true
LoadService: found:
file:/Users/headius/projects/jruby/lib/ruby/site_ruby/1.8/rubygems/user_interaction.rb
LoadService: trying builtinLib: rubygems/specification.class
LoadService: trying builtinLib: rubygems/specification.rb
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/site_ruby/1.8/rubygems/specification.class'
false false
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/site_ruby/1.8/rubygems/specification.rb'
true true
LoadService: found:
file:/Users/headius/projects/jruby/lib/ruby/site_ruby/1.8/rubygems/specification.rb
LoadService: trying builtinLib: rubygems/platform.class
LoadService: trying builtinLib: rubygems/platform.rb
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/site_ruby/1.8/rubygems/platform.class'
false false
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/site_ruby/1.8/rubygems/platform.rb'
true true
LoadService: found:
file:/Users/headius/projects/jruby/lib/ruby/site_ruby/1.8/rubygems/platform.rb
LoadService: trying builtinLib: rubygems/builder.class
LoadService: trying builtinLib: rubygems/builder.rb
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/site_ruby/1.8/rubygems/builder.class'
false false
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/site_ruby/1.8/rubygems/builder.rb'
true true
LoadService: found:
file:/Users/headius/projects/jruby/lib/ruby/site_ruby/1.8/rubygems/builder.rb
LoadService: trying builtinLib: rubygems/defaults/operating_system.class
LoadService: trying builtinLib: rubygems/defaults/operating_system.rb
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/site_ruby/1.8/rubygems/defaults/operating_system.class'
false false
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/site_ruby/1.8/rubygems/defaults/operating_system.rb'
false false
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/site_ruby/shared/rubygems/defaults/operating_system.class'
false false
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/site_ruby/shared/rubygems/defaults/operating_system.rb'
false false
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/1.8/rubygems/defaults/operating_system.class'
false false
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/1.8/rubygems/defaults/operating_system.rb'
false false
LoadService: trying resourceFromCWD:
/Users/headius/projects/jruby/rubygems/defaults/operating_system.class
LoadService: trying resourceFromCWD:
/Users/headius/projects/jruby/rubygems/defaults/operating_system.rb
LoadService: trying builtinLib: rubygems/defaults/operating_system.jar
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/site_ruby/1.8/rubygems/defaults/operating_system.jar'
false false
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/site_ruby/shared/rubygems/defaults/operating_system.jar'
false false
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/1.8/rubygems/defaults/operating_system.jar'
false false
LoadService: trying resourceFromCWD:
/Users/headius/projects/jruby/rubygems/defaults/operating_system.jar
LoadService: trying fileInClasspath: ./rubygems/defaults/operating_system.class
LoadService: trying fileInClasspath: rubygems/defaults/operating_system.class
LoadService: trying fileInClasspath: ./rubygems/defaults/operating_system.rb
LoadService: trying fileInClasspath: rubygems/defaults/operating_system.rb
LoadService: trying fileInClasspath: ./rubygems/defaults/operating_system.jar
LoadService: trying fileInClasspath: rubygems/defaults/operating_system.jar
LoadService: trying builtinLib: rubygems/defaults/jruby.class
LoadService: trying builtinLib: rubygems/defaults/jruby.rb
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/site_ruby/1.8/rubygems/defaults/jruby.class'
false false
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/site_ruby/1.8/rubygems/defaults/jruby.rb'
true true
LoadService: found:
file:/Users/headius/projects/jruby/lib/ruby/site_ruby/1.8/rubygems/defaults/jruby.rb
LoadService: trying builtinLib: rubygems/config_file.class
LoadService: trying builtinLib: rubygems/config_file.rb
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/site_ruby/1.8/rubygems/config_file.class'
false false
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/site_ruby/1.8/rubygems/config_file.rb'
true true
LoadService: found:
file:/Users/headius/projects/jruby/lib/ruby/site_ruby/1.8/rubygems/config_file.rb
LoadService: trying builtinLib: Win32API.class
LoadService: trying builtinLib: Win32API.rb
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/site_ruby/1.8/Win32API.class'
false false
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/site_ruby/1.8/Win32API.rb'
false false
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/site_ruby/shared/Win32API.class'
false false
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/site_ruby/shared/Win32API.rb'
false false
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/1.8/Win32API.class' false
false
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/1.8/Win32API.rb' true true
LoadService: found: file:/Users/headius/projects/jruby/lib/ruby/1.8/Win32API.rb
LoadService: trying builtinLib: rubygems/defaults/jruby_native.class
LoadService: trying builtinLib: rubygems/defaults/jruby_native.rb
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/site_ruby/1.8/rubygems/defaults/jruby_native.class'
false false
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/site_ruby/1.8/rubygems/defaults/jruby_native.rb'
true true
LoadService: found:
file:/Users/headius/projects/jruby/lib/ruby/site_ruby/1.8/rubygems/defaults/jruby_native.rb
LoadService: trying builtinLib: rubygems/custom_require.class
LoadService: trying builtinLib: rubygems/custom_require.rb
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/site_ruby/1.8/rubygems/custom_require.class'
false false
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/site_ruby/1.8/rubygems/custom_require.rb'
true true
LoadService: found:
file:/Users/headius/projects/jruby/lib/ruby/site_ruby/1.8/rubygems/custom_require.rb
LoadService: trying builtinLib: yaml.class
LoadService: trying builtinLib: yaml.rb
LoadService: found builtinLib: yaml.rb
LoadService: trying builtinLib: stringio.class
LoadService: trying builtinLib: stringio.rb
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/site_ruby/1.8/stringio.class'
false false
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/site_ruby/1.8/stringio.rb'
false false
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/site_ruby/shared/stringio.class'
false false
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/site_ruby/shared/stringio.rb'
false false
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/1.8/stringio.class' false
false
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/1.8/stringio.rb' false false
LoadService: trying resourceFromCWD:
/Users/headius/projects/jruby/stringio.class
LoadService: trying resourceFromCWD: /Users/headius/projects/jruby/stringio.rb
LoadService: trying builtinLib: stringio.jar
LoadService: found builtinLib: stringio.jar
LoadService: trying builtinLib: yaml/compat.class
LoadService: trying builtinLib: yaml/compat.rb
LoadService: found builtinLib: yaml/compat.rb
LoadService: trying builtinLib: yaml/error.class
LoadService: trying builtinLib: yaml/error.rb
LoadService: found builtinLib: yaml/error.rb
LoadService: trying builtinLib: yaml/yecht.class
LoadService: trying builtinLib: yaml/yecht.rb
LoadService: found builtinLib: yaml/yecht.rb
LoadService: trying builtinLib: yecht.class
LoadService: trying builtinLib: yecht.rb
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/site_ruby/1.8/yecht.class'
false false
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/site_ruby/1.8/yecht.rb' false
false
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/site_ruby/shared/yecht.class'
false false
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/site_ruby/shared/yecht.rb'
false false
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/1.8/yecht.class' false false
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/1.8/yecht.rb' false false
LoadService: trying resourceFromCWD: /Users/headius/projects/jruby/yecht.class
LoadService: trying resourceFromCWD: /Users/headius/projects/jruby/yecht.rb
LoadService: trying builtinLib: yecht.jar
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/site_ruby/1.8/yecht.jar' false
false
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/site_ruby/shared/yecht.jar'
true true
LoadService: found:
file:/Users/headius/projects/jruby/lib/ruby/site_ruby/shared/yecht.jar
LoadService: trying builtinLib: yaml/basenode.class
LoadService: trying builtinLib: yaml/basenode.rb
LoadService: found builtinLib: yaml/basenode.rb
LoadService: trying builtinLib: yaml/ypath.class
LoadService: trying builtinLib: yaml/ypath.rb
LoadService: found builtinLib: yaml/ypath.rb
LoadService: trying builtinLib: yaml/tag.class
LoadService: trying builtinLib: yaml/tag.rb
LoadService: found builtinLib: yaml/tag.rb
LoadService: trying builtinLib: yaml/stream.class
LoadService: trying builtinLib: yaml/stream.rb
LoadService: found builtinLib: yaml/stream.rb
LoadService: trying builtinLib: yaml/constants.class
LoadService: trying builtinLib: yaml/constants.rb
LoadService: found builtinLib: yaml/constants.rb
LoadService: trying builtinLib: yaml/rubytypes.class
LoadService: trying builtinLib: yaml/rubytypes.rb
LoadService: found builtinLib: yaml/rubytypes.rb
LoadService: trying builtinLib: date.class
LoadService: trying builtinLib: date.rb
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/site_ruby/1.8/date.class'
false false
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/site_ruby/1.8/date.rb' false
false
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/site_ruby/shared/date.class'
false false
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/site_ruby/shared/date.rb'
false false
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/1.8/date.class' false false
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/1.8/date.rb' true true
LoadService: found: file:/Users/headius/projects/jruby/lib/ruby/1.8/date.rb
LoadService: trying builtinLib: rational.class
LoadService: trying builtinLib: rational.rb
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/site_ruby/1.8/rational.class'
false false
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/site_ruby/1.8/rational.rb'
false false
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/site_ruby/shared/rational.class'
false false
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/site_ruby/shared/rational.rb'
false false
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/1.8/rational.class' false
false
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/1.8/rational.rb' true true
LoadService: found: file:/Users/headius/projects/jruby/lib/ruby/1.8/rational.rb
LoadService: trying builtinLib: date/format.class
LoadService: trying builtinLib: date/format.rb
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/site_ruby/1.8/date/format.class'
false false
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/site_ruby/1.8/date/format.rb'
false false
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/site_ruby/shared/date/format.class'
false false
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/site_ruby/shared/date/format.rb'
false false
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/1.8/date/format.class' false
false
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/1.8/date/format.rb' true true
LoadService: found:
file:/Users/headius/projects/jruby/lib/ruby/1.8/date/format.rb
LoadService: trying builtinLib: yaml/types.class
LoadService: trying builtinLib: yaml/types.rb
LoadService: found builtinLib: yaml/types.rb
LoadService: trying builtinLib: jruby/util.class
LoadService: trying builtinLib: jruby/util.rb
LoadService: found builtinLib: jruby/util.rb
LoadService: trying builtinLib: time.class
LoadService: trying builtinLib: time.rb
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/site_ruby/1.8/time.class'
false false
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/site_ruby/1.8/time.rb' false
false
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/site_ruby/shared/time.class'
false false
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/site_ruby/shared/time.rb'
false false
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/1.8/time.class' false false
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/1.8/time.rb' true true
LoadService: found: file:/Users/headius/projects/jruby/lib/ruby/1.8/time.rb
LoadService: trying builtinLib: parsedate.class
LoadService: trying builtinLib: parsedate.rb
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/site_ruby/1.8/parsedate.class'
false false
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/site_ruby/1.8/parsedate.rb'
false false
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/site_ruby/shared/parsedate.class'
false false
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/site_ruby/shared/parsedate.rb'
false false
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/1.8/parsedate.class' false
false
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/1.8/parsedate.rb' true true
LoadService: found: file:/Users/headius/projects/jruby/lib/ruby/1.8/parsedate.rb
LoadService: trying builtinLib:
/Users/headius/projects/jruby/lib/ruby/gems/1.8/gems/maven_gem-0.0.2/lib/rubygems_plugin.class
LoadService: trying builtinLib:
/Users/headius/projects/jruby/lib/ruby/gems/1.8/gems/maven_gem-0.0.2/lib/rubygems_plugin.rb
LoadService: trying builtinLib:
/Users/headius/projects/jruby/lib/ruby/gems/1.8/gems/maven_gem-0.0.2/lib/rubygems_plugin.class
LoadService: trying builtinLib:
/Users/headius/projects/jruby/lib/ruby/gems/1.8/gems/maven_gem-0.0.2/lib/rubygems_plugin.rb
LoadService: trying resourceAsIs:
/Users/headius/projects/jruby/lib/ruby/gems/1.8/gems/maven_gem-0.0.2/lib/rubygems_plugin.class
LoadService: trying resourceAsIs:
/Users/headius/projects/jruby/lib/ruby/gems/1.8/gems/maven_gem-0.0.2/lib/rubygems_plugin.rb
LoadService: found:
file:/Users/headius/projects/jruby/lib/ruby/gems/1.8/gems/maven_gem-0.0.2/lib/rubygems_plugin.rb
LoadService: trying builtinLib: rubygems/command_manager.class
LoadService: trying builtinLib: rubygems/command_manager.rb
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/site_ruby/1.8/rubygems/command_manager.class'
false false
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/site_ruby/1.8/rubygems/command_manager.rb'
true true
LoadService: found:
file:/Users/headius/projects/jruby/lib/ruby/site_ruby/1.8/rubygems/command_manager.rb
LoadService: trying builtinLib: timeout.class
LoadService: trying builtinLib: timeout.rb
LoadService: found builtinLib: timeout.rb
LoadService: trying builtinLib: rubygems/command.class
LoadService: trying builtinLib: rubygems/command.rb
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/site_ruby/1.8/rubygems/command.class'
false false
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/site_ruby/1.8/rubygems/command.rb'
true true
LoadService: found:
file:/Users/headius/projects/jruby/lib/ruby/site_ruby/1.8/rubygems/command.rb
LoadService: trying builtinLib: optparse.class
LoadService: trying builtinLib: optparse.rb
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/site_ruby/1.8/optparse.class'
false false
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/site_ruby/1.8/optparse.rb'
false false
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/site_ruby/shared/optparse.class'
false false
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/site_ruby/shared/optparse.rb'
false false
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/1.8/optparse.class' false
false
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/1.8/optparse.rb' true true
LoadService: found: file:/Users/headius/projects/jruby/lib/ruby/1.8/optparse.rb
LoadService: trying builtinLib: active_support.class
LoadService: trying builtinLib: active_support.rb
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/site_ruby/1.8/active_support.class'
false false
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/site_ruby/1.8/active_support.rb'
false false
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/site_ruby/shared/active_support.class'
false false
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/site_ruby/shared/active_support.rb'
false false
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/1.8/active_support.class'
false false
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/1.8/active_support.rb' false
false
LoadService: trying resourceFromCWD:
/Users/headius/projects/jruby/active_support.class
LoadService: trying resourceFromCWD:
/Users/headius/projects/jruby/active_support.rb
LoadService: trying builtinLib: active_support.jar
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/site_ruby/1.8/active_support.jar'
false false
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/site_ruby/shared/active_support.jar'
false false
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/1.8/active_support.jar' false
false
LoadService: trying resourceFromCWD:
/Users/headius/projects/jruby/active_support.jar
LoadService: trying fileInClasspath: ./active_support.class
LoadService: trying fileInClasspath: active_support.class
LoadService: trying fileInClasspath: ./active_support.rb
LoadService: trying fileInClasspath: active_support.rb
LoadService: trying fileInClasspath: ./active_support.jar
LoadService: trying fileInClasspath: active_support.jar
LoadService: trying builtinLib: active_support.class
LoadService: trying builtinLib: active_support.rb
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/gems/1.8/gems/activesupport-3.0.0.beta4/bin/active_support.class'
false false
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/gems/1.8/gems/activesupport-3.0.0.beta4/bin/active_support.rb'
false false
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/gems/1.8/gems/activesupport-3.0.0.beta4/lib/active_support.class'
false false
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/gems/1.8/gems/activesupport-3.0.0.beta4/lib/active_support.rb'
true true
LoadService: found:
file:/Users/headius/projects/jruby/lib/ruby/gems/1.8/gems/activesupport-3.0.0.beta4/lib/active_support.rb
LoadService: trying builtinLib: active_support/dependencies/autoload.class
LoadService: trying builtinLib: active_support/dependencies/autoload.rb
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/gems/1.8/gems/activesupport-3.0.0.beta4/bin/active_support/dependencies/autoload.class'
false false
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/gems/1.8/gems/activesupport-3.0.0.beta4/bin/active_support/dependencies/autoload.rb'
false false
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/gems/1.8/gems/activesupport-3.0.0.beta4/lib/active_support/dependencies/autoload.class'
false false
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/gems/1.8/gems/activesupport-3.0.0.beta4/lib/active_support/dependencies/autoload.rb'
true true
LoadService: found:
file:/Users/headius/projects/jruby/lib/ruby/gems/1.8/gems/activesupport-3.0.0.beta4/lib/active_support/dependencies/autoload.rb
LoadService: trying builtinLib: active_support/inflector/methods.class
LoadService: trying builtinLib: active_support/inflector/methods.rb
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/gems/1.8/gems/activesupport-3.0.0.beta4/bin/active_support/inflector/methods.class'
false false
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/gems/1.8/gems/activesupport-3.0.0.beta4/bin/active_support/inflector/methods.rb'
false false
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/gems/1.8/gems/activesupport-3.0.0.beta4/lib/active_support/inflector/methods.class'
false false
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/gems/1.8/gems/activesupport-3.0.0.beta4/lib/active_support/inflector/methods.rb'
true true
LoadService: found:
file:/Users/headius/projects/jruby/lib/ruby/gems/1.8/gems/activesupport-3.0.0.beta4/lib/active_support/inflector/methods.rb
LoadService: trying builtinLib: active_support/lazy_load_hooks.class
LoadService: trying builtinLib: active_support/lazy_load_hooks.rb
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/gems/1.8/gems/activesupport-3.0.0.beta4/bin/active_support/lazy_load_hooks.class'
false false
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/gems/1.8/gems/activesupport-3.0.0.beta4/bin/active_support/lazy_load_hooks.rb'
false false
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/gems/1.8/gems/activesupport-3.0.0.beta4/lib/active_support/lazy_load_hooks.class'
false false
LoadService: trying resourceFromLoadPath:
'/Users/headius/projects/jruby/lib/ruby/gems/1.8/gems/activesupport-3.0.0.beta4/lib/active_support/lazy_load_hooks.rb'
true true
LoadService: found:
file:/Users/headius/projects/jruby/lib/ruby/gems/1.8/gems/activesupport-3.0.0.beta4/lib/active_support/lazy_load_hooks.rb
- Charlie
Caleb Clausen
> On Fri, Jun 11, 2010 at 8:40 PM, Caleb Clausen <ca...@inforadical.net> wrote:
>> Charlie, couldn't you cache the results of parsing/compiling a ruby file
>> so that it doesn't need to be so expensive on subsequent loads? Similar
>> to what rubinius does with its .rbc files? In fact, I'm a bit surprised
>> that you aren't doing this already, so maybe you are...
>
> We used to do this in the days when our parser was a lot slower than
> it is now. At some point, the parser speed passed the deserialization
> speed and we opted to remove the feature.
The further down the compiler pipeline you can cache the output, the
more it will help you. Java code would be better than your asts, JVM
bytecode better than that, and native code (ha! yeah, right) best of
all. (Maybe I'm misremembering the stages of jruby's pipeline here.)
> However, that serialization was using the default JVM serialization
> mechanism, which can be pretty slow. There's a more user-driven
> mechanism that can be significantly faster but requires more code
> (every object type you want to serialize needs a small snippit of code
> to dump/load its fields). It's possible that using this faster
> mechanism would again beat parse performance, so I'm going to look
> into that possibility.
>
> At the end of the day we're always going to have *something* running
> slowly at startup, however, since almost all our code needs to be
> jitted (as opposed to MRI and Rubinius, which have large amounts of
> already-compiled C/C++ code, including the parser). The only solution
> would be a C parser that produces JRuby AST (heh...not likely to
If I ever solve redparse's speed problems, maybe you could use that. I
bet I could get it to emit your asts without a terrible lot of work.
Speaking of slow parsers... redparse is embarassingly bad.
> happen), or the hope that this other serialization mechanism would
> warm up much sooner and run faster than parsing.
Warning: opinions offensive to java fans coming:
The fact that java code has to 'warm up' seems just kinda... dumb to me.
Java goes to all this work to produce (eventually) fast native code, but
it all gets thrown away when the process exits. Why doesn't java have a
way to save that hard-won native code for the next run? And it would be
nice if you could even move these jit result caches from one machine to
another. Oh, wait, that starts to look too much like a real compiler,
doesn't it?
> We'd also want a solution to the ".rbc turd" problem; I don't want to
> start littering people's systems with pre-parsed dump files.
Oh, that's easy. Put it all in ~/.jruby or something instead of right
next to the .rb file. I had to do something very much like this for
redparse. If you want to borrow some code, take a look at
http://github.com/coatl/redparse/raw/master/lib/redparse/cache.rb. Who
knows, it might be useful to you.
Roger Pack
> Java goes to all this work to produce (eventually) fast native code, but
> it all gets thrown away when the process exits. Why doesn't java have a
> way to save that hard-won native code for the next run? And it would be
> nice if you could even move these jit result caches from one machine to
> another. Oh, wait, that starts to look too much like a real compiler,
> doesn't it?
Agreed. I work in java and I feel like half of my work flow is
something repeated over and over and over...except that's probably
more maven's fault than anything...
-r
Roger Pack
>> current speed for "those that don't have it" is really quite bad.
>
> Yes, this sounds like the right direction, but I'm not a RubyGems
> internals expert. Yehuda (for example) would know much better than I
> (and so too, probably, would you).
Yeah I almost think (like you) that something like a database per gem
folder would be best. Though I suppose a marshalled version of
gemspecs might be just as good (it would only need to include the name
and require_paths, really).
another option might be to complement Builder to have something like a
'cached' mode or something...then never need to load full rubygems
even if you use some...or does it do this already?
>> I also ran into this: http://github.com/fabien/minigems
>>
>> Interesting.
>
> This is actually a different but related problem: RubyGems causes
> excessive load/require searching. Even for libraries that are *found*,
> there's a massive amount of overhead in looking through all the
> various paths and extensions. Here is more logging from JRuby showing
> all paths searched just to load "active_support":
Interesting. Yeah all that searching is where my faster_require gem
comes in (just caches the locations after their first discovery).
Windows especially suffers when you do File stat's
Like miserably.
1.9 with gem prelude on windows is truly slow. Of course, so is
loading rubygems.
My original idea was to make a wrapper over rubygems that would make
it 'omniscient' as to which gems you want to require.
But aparently with rails there is still *so many* require paths that
it might still be slow in windows.
ex: with jruby
>> gem 'rails'
>> Benchmark.realtime{ 100.times { begin; require 'nonex';rescue LoadError; end }}
=> 3.03
That is quite a long time...
So basically we can almost say that with an omniscient rubyems
replacement, ruby might still be slow on windows. Not Linux, though,
it takes 0.4s compared to 3.03s, above, for the same requires, so
that's probably reasonable. Sigh.
I could refactor faster_rubygems to also handle Gem.bin_path and also
"requires for things not on the load path"
hmm...it might work for jruby...
-rpo
Charles Oliver Nutter
> The further down the compiler pipeline you can cache the output, the
> more it will help you. Java code would be better than your asts, JVM
> bytecode better than that, and native code (ha! yeah, right) best of
> all. (Maybe I'm misremembering the stages of jruby's pipeline here.)
You'd think this is always true, but it isn't necessarily.
So far the fastest way to load code on JRuby is still to simply parse
into AST and start executing. JRuby executes directly against the AST,
so there's no additional compile step required to start running, which
makes this path's cost entirely parse time.
My original experiment with serializing the AST was much slower,
mostly because I used the default Java serialization. That
serialization logic uses a lot of reflection to maintain encapsulation
of the serialized objects.
My second experiment was to use Java serialization but with the
Externalizable interface, which provides (and requires) finer-grained,
per-class load/dump logic. This came very close to beating
serialization, and it *was* much faster to deserialize than to parse.
But the serialized AST takes up about ten times as much space on disk,
and ultimately it seems the parse-performance gains were lost due to
IO and remaining Java serialization overhead (like reading class names
out of the file and still reflectively instantiating them).
If I have the energy for a third experiment, it would be to just
serialize the AST as a custom structure, bypassing Java's
serialization entirely. It's a testament to our parser (and to Tom
Enebo's constant work to speed it up) that I have not been able to
find a no-parse solution that loads faster.
>> At the end of the day we're always going to have *something* running
>> slowly at startup, however, since almost all our code needs to be
>> jitted (as opposed to MRI and Rubinius, which have large amounts of
>> already-compiled C/C++ code, including the parser). The only solution
>> would be a C parser that produces JRuby AST (heh...not likely to
...
> Warning: opinions offensive to java fans coming:
> The fact that java code has to 'warm up' seems just kinda... dumb to me.
> Java goes to all this work to produce (eventually) fast native code, but
> it all gets thrown away when the process exits. Why doesn't java have a
> way to save that hard-won native code for the next run? And it would be
> nice if you could even move these jit result caches from one machine to
> another. Oh, wait, that starts to look too much like a real compiler,
> doesn't it?
So much of what Java does with its dynamic optimizations depends on
things that are in memory with specific structures, addresses, and so
on. I've talked to the JVM guys about this, and while they would love
to do it, it's a very, very hard problem. Other systems like
Microsoft's CLR don't do dynamic, in-memory optimizations, so they're
able to save off their static optimizations to disk. Any of the newer
Ruby runtimes that do profile-driven optimizations will also be
hard-pressed to save anything to disk. The challenges boil down to the
following items:
* Process-specific details like object/class identities, memory locations, etc
* Need to know whether previously-optimized code is still valid under
new runtime conditions; most optimistic optimizations in Hotspot, for
example, depend on being able to flag a compiled body of code *in
memory* as being "not entrant", so it will get thrown away
* Maintaining a good relationship with code that ran previously, so if
it changes we know which saved optimizations we need to throw out
The JVM engineers did say there might be a way to save off the
pre-assembly optimization graphs and strategies, but it's unclear how
much you'd save and how you could tell it's no longer valid for the
new execution run.
If it were easy to save off the runtime-optimized results of a Java
program executing, I'm sure someone would have done it by now. In
fact, I don't know a single mainstream profile or type-driven
optimizer that does this.
>> We'd also want a solution to the ".rbc turd" problem; I don't want to
>> start littering people's systems with pre-parsed dump files.
>
> Oh, that's easy. Put it all in ~/.jruby or something instead of right
> next to the .rb file. I had to do something very much like this for
> redparse. If you want to borrow some code, take a look at
> http://github.com/coatl/redparse/raw/master/lib/redparse/cache.rb. Who
> knows, it might be useful to you.
Actually the idea I had was to calculate a SHA1 hash of the source and
use that as the ".rbj" filename. So loading the pre-parsed content (or
pre-compiled content...I already have this support in JRuby for
.class-compiled code) would involve a fast read, a SHA1 calculation,
and then we have the right file to grab to avoid parsing. But would it
be faster?
- Charlie
Charles Oliver Nutter
<hea...@headius.com> wrote:
> On Sat, Jun 12, 2010 at 12:37 PM, Caleb Clausen <ca...@inforadical.net> wrote:
>> The further down the compiler pipeline you can cache the output, the
>> more it will help you. Java code would be better than your asts, JVM
>> bytecode better than that, and native code (ha! yeah, right) best of
>> all. (Maybe I'm misremembering the stages of jruby's pipeline here.)
>
> You'd think this is always true, but it isn't necessarily.
Oh, and I forgot the primary point I wanted to make here... even
precompiling to Java code isn't faster than parsing, because in
addition to parsing the class file, the JVM also does a rigorous set
of verifications of compiled bytecode that actually costs *more* than
parsing the original Ruby code.
- Charlie
Charles Oliver Nutter
> Yeah I almost think (like you) that something like a database per gem
> folder would be best. Though I suppose a marshalled version of
> gemspecs might be just as good (it would only need to include the name
> and require_paths, really).
>
> another option might be to complement Builder to have something like a
> 'cached' mode or something...then never need to load full rubygems
> even if you use some...or does it do this already?
It does do that already. If you use Bundler you can run entirely
independent of RubyGems after "installing" all dependencies. The JRuby
support for Google AppEngine uses this right now to avoid the
intrinsic costs of RubyGems itself.
>> This is actually a different but related problem: RubyGems causes
>> excessive load/require searching. Even for libraries that are *found*,
>> there's a massive amount of overhead in looking through all the
>> various paths and extensions. Here is more logging from JRuby showing
>> all paths searched just to load "active_support":
>
> Interesting. Yeah all that searching is where my faster_require gem
> comes in (just caches the locations after their first discovery).
> Windows especially suffers when you do File stat's
> Like miserably.
> 1.9 with gem prelude on windows is truly slow. Of course, so is
> loading rubygems.
>
> My original idea was to make a wrapper over rubygems that would make
> it 'omniscient' as to which gems you want to require.
>
> But aparently with rails there is still *so many* require paths that
> it might still be slow in windows.
Sure...part of the problem is that it's re-searching everything every
time. There's no nicely-structured database of what file comes from
where. In JRuby, that can end up being even slower since we're
searching for .class, .rb, and .jar files PLUS searching classloader
resources too. I'll paste a log of failed requires with RubyGems
active and you can see what I mean.
> ex: with jruby
>>> gem 'rails'
>>> Benchmark.realtime{ 100.times { begin; require 'nonex';rescue LoadError; end }}
> => 3.03
>
> That is quite a long time...
>
> So basically we can almost say that with an omniscient rubyems
> replacement, ruby might still be slow on windows. Not Linux, though,
> it takes 0.4s compared to 3.03s, above, for the same requires, so
> that's probably reasonable. Sigh.
>
> I could refactor faster_rubygems to also handle Gem.bin_path and also
> "requires for things not on the load path"
>
> hmm...it might work for jruby...
At this point I'm pretty well desperate for anything. The amount of
searching and re-searching happening is a tremendous waste of time.
Here's that trace of a failed require with RubyGems active (the
relevant part, where it's actually searching for 'nonex'):
http://gist.github.com/439371
- Charlie
rogerdpack
> At this point I'm pretty well desperate for anything. The amount of
> searching and re-searching happening is a tremendous waste of time.
attempt at something.
I noticed that with 1.9's gem_prelude, each binary ruby script says
something like
...
gem 'xxx', '>= 0'
load Gem.bin_path('xxx', 'some_executable_name', '>= 0')
The latter line, unfortunately, causes a forced full loading of
rubygems.
So I updated faster_rubygems (my gem prelude for 1.8) to do that
without full loading.
http://github.com/rdp/faster_rubygems
I also added a way for it to "override" normal rubygems, i.e.
require 'rubygems' # now actually loads faster_rubygems
check the README.
Anyway installing this into jruby caused the time it took for a simple
script of mine to go from
4s (normal rubygems) to
2.6s (faster_rubygems).
With MRI 1.8, it was
0.83s normal rubygems
0.28s faster_rubygems
with MRI 1.9 it was
3.8s normal rubygems
0.65 faster_rubygems
That last number is still a bit disconcerting to me, making me wonder
if I've fixed the root cause of it or not, yet.
Anyway give it a shot.
http://github.com/rdp/faster_rubygems
-rp
Roger Pack
serialized list of its gems' files, in the root, like
gems/1.9/list_of_all_files.marshal
Then gem_prelude can use that to determine which gems to activate, and
everything is happy, because it can keep the load path ($:) small,
while still loading gems without loading full rubygems.
Thoughts?
-rp
Roger Pack
All righty I've just pushed faster_rubygems v 0.9.3, which implements
this (cached file lists, use them to activate gems).
This seems to speed up 1.9.x splendidly for everything except rails.
A couple of jruby benchmarks can be seen
http://github.com/rdp/faster_rubygems/blob/master/benchmarks.txt
where it comes down from 2.3 seconds to the manageable 1.11s to startup.
Give it a shot.
To install it try:
$ gem install faster_rubygems
$ jruby -S irb
>> require 'rubygems'
>> require 'faster_rubygems/override'
See the README for more details:
http://github.com/rdp/faster_rubygems/blob/master/README
Enjoy.
-r
Roger Pack
> this (cached file lists, use them to activate gems).
> This seems to speed up 1.9.x splendidly for everything except rails.
>
> A couple of jruby benchmarks can be seen
> http://github.com/rdp/faster_rubygems/blob/master/benchmarks.txt
>
> where it comes down from 2.3 seconds to the manageable 1.11s to startup.
All righty pushed another version that is slightly faster, and
auto-installs itself over rubygems when installed (and uninstalls
itself when uninstalled).
Let me know how it goes...
-r
Charles Oliver Nutter
to make to RubyGems proper over the years (though my efforts have all
been cursory hacks).
Here's a gist of -rubygems and rake -V before and after:
Roger Pack
> to make to RubyGems proper over the years (though my efforts have all
> been cursory hacks).
Yeah it's like pseudo rubygems, but works all right...
> Here's a gist of -rubygems and rake -V before and after:
for me its
jruby -rubygems -e 1
2.36 -> 0.94
rake -V
2.48 -> 1.42
jruby -e 1
0.68 (constant).
I'm not sure if that's as good as it can get or not.
Also there's some bug with it on jruby that I hope to squash in the
near future. Looking into it.
-r
Roger Pack
> near future. Looking into it.
Looks like it was a cache problem so we're good there.
Also note that if you run it in verbose mode, it will tell you how
long it took to load "faster_rubygems"
for me it takes 0.21s in jruby (39K file), 0.04s in 1.9 (100K file),
and 0.02s in 1.8 (50K file). Currently it does iterate overall gem
folder names at startup, so that might be able to be improved.
Another optimization available would be to "lazy load" the cached
files, so if you never used a gem installed file, it would be faster.
How often do people use jruby and not use a gem file?
Some more timing info (jruby):
jruby -S rake -V (rubygems installed rake): 1.50s
jruby rake -V (with rake installed into site_ruby): 1.41s
So faster_rubygems doesn't appear to be costing much. That last one
doesn't load gems at all.
Feedback welcome.
-r
Charles Oliver Nutter
> for me it takes 0.21s in jruby (39K file), 0.04s in 1.9 (100K file),
> and 0.02s in 1.8 (50K file). Currently it does iterate overall gem
> folder names at startup, so that might be able to be improved.
I wouldn't expect that to be too bad unless you get into having
thousands of gems installed. We could break it out and see if it's
adding a lot, but your numbers below show we're pretty close to zero.
> Another optimization available would be to "lazy load" the cached
> files, so if you never used a gem installed file, it would be faster.
> How often do people use jruby and not use a gem file?
Do you mean use JRuby plus load RubyGems but not use a gem file? I
think that would be a pretty small portion of users...perhaps only
those physically building a new gem.
> Some more timing info (jruby):
>
> jruby -S rake -V (rubygems installed rake): 1.50s
> jruby rake -V (with rake installed into site_ruby): 1.41s
>
> So faster_rubygems doesn't appear to be costing much. That last one
> doesn't load gems at all.
Considering that the non-faster_rubygems rake -V time is in the 2.5s
range, this is something close to a 10-fold increase. And of course it
will be a larger increase the more gems you have installed. Have you
posted recently about faster_rubygems (and faster_require) on the
JRuby user list? Seems like it's getting closer to being generally
useful.
I also don't think we've ever talked about faster_require. How does it
speed up Rails loading?
- Charlie
Roger Pack
>> and 0.02s in 1.8 (50K file). Currently it does iterate overall gem
>> folder names at startup, so that might be able to be improved.
>
> I wouldn't expect that to be too bad unless you get into having
> thousands of gems installed. We could break it out and see if it's
> adding a lot, but your numbers below show we're pretty close to zero.
True it would be less cost if you had less gems installed.
I added some more benchmarking and it appears that there is a bit of
startup overhead still...
faster_rubygems: took 0.03s to load the cache files (50K)
faster_rubygems: took 0.113s to scan the dirs for versions
faster_rubygems total load time:0.203
Obviously it did some other stuff, too, like a few requires etc.
So it seems to me that about 50% of the faster_rubygems time currently
could be avoided.
Going back to the rake example, that "might" mean that you can run rake in
1.45s instead of 1.5s
I'm not sure if this is worth chasing down or not...(low percentage,
already close to zero), though I suppose if they had lots of gems it
might get unwieldy, so I'll probably look at it eventually. More
speed is always better, right?
> I also don't think we've ever talked about faster_require. How does it
> speed up Rails loading?
I haven't tried it with jruby loading rails...that would be interesting.
What it does is basically override require to query a cache *first*
for file location, then if it's not there, query the load path (which
is what original require does).
def require file_name
begin
if cache_contains?(file_name)
load cache[file_name]
$LOADED_FEATURES << cache[file_name]
else
old_require file_name
cache[file_name] = $LOADED_FEATURES.shift
save_cache!
end
end
Unfortunately I did some more stuff than that (like using on the
filename that called the require, etc.) so it gets a bit more ugly
than that.
Basically it's cache_contains?(file_name + caller line)
It speeds up 1.8 pretty good, and also works well with 1.9
Unfortunately there are still a few bugs with it in 1.8, so I haven't
released it yet, since I only use 1.9 and don't do rails much. I
suppose I should though...
You can try it out if you'd like to get feedback...
-r
Caleb Clausen
<hea...@headius.com> wrote:
> On Sat, Jun 12, 2010 at 12:37 PM, Caleb Clausen <ca...@inforadical.net>
> wrote:
> > The further down the compiler pipeline you can cache the output, the
> > more it will help you. Java code would be better than your asts, JVM
> > bytecode better than that, and native code (ha! yeah, right) best of
> > all. (Maybe I'm misremembering the stages of jruby's pipeline here.)
>
> You'd think this is always true, but it isn't necessarily.
>
> So far the fastest way to load code on JRuby is still to simply parse
> into AST and start executing. JRuby executes directly against the AST,
> so there's no additional compile step required to start running, which
> makes this path's cost entirely parse time.
deserialization. I wouldn't expect it to be the fastest one, tho.
> > Warning: opinions offensive to java fans coming:
> > The fact that java code has to 'warm up' seems just kinda... dumb to me.
> > Java goes to all this work to produce (eventually) fast native code, but
> > it all gets thrown away when the process exits. Why doesn't java have a
> > way to save that hard-won native code for the next run? And it would be
> > nice if you could even move these jit result caches from one machine to
> > another. Oh, wait, that starts to look too much like a real compiler,
> > doesn't it?
>
> So much of what Java does with its dynamic optimizations depends on
> things that are in memory with specific structures, addresses, and so
> on. I've talked to the JVM guys about this, and while they would love
> to do it, it's a very, very hard problem. Other systems like
> Microsoft's CLR don't do dynamic, in-memory optimizations, so they're
> able to save off their static optimizations to disk. Any of the newer
> Ruby runtimes that do profile-driven optimizations will also be
> hard-pressed to save anything to disk. The challenges boil down to the
> following items:
>
> * Process-specific details like object/class identities, memory
> locations, etc
the
same address they had originally. Why should this be such a big deal?
That's the way native executables (actual programs, not .so/.dll)
normally work anyway. (The code/data sections are always loaded at the
same address.)
> * Need to know whether previously-optimized code is still valid under
> new runtime conditions; most optimistic optimizations in Hotspot, for
> example, depend on being able to flag a compiled body of code *in
> memory* as being "not entrant", so it will get thrown away
(de)serialized.
> * Maintaining a good relationship with code that ran previously, so if
> it changes we know which saved optimizations we need to throw out
I have to grant you that this is at least a fairly difficult problem,
and I don't understand the details even as well as you do.
> The JVM engineers did say there might be a way to save off the
> pre-assembly optimization graphs and strategies, but it's unclear how
> much you'd save and how you could tell it's no longer valid for the
> new execution run.
>
> If it were easy to save off the runtime-optimized results of a Java
> program executing, I'm sure someone would have done it by now. In
> fact, I don't know a single mainstream profile or type-driven
> optimizer that does this.
after the first time it starts up... I don't really know much about
it,
but I think it saves the current memory image, lock stock and barrel,
out to disk in the format of an executable file. On subsequent runs,
you
just load up that and start running it.
I'm sure the elisp interpreter is no where near as advanced as a jvm,
and I'm not trying to suggest that it is.
> Oh, and I forgot the primary point I wanted to make here... even
> precompiling to Java code isn't faster than parsing, because in
> addition to parsing the class file, the JVM also does a rigorous set
> of verifications of compiled bytecode that actually costs *more* than
> parsing the original Ruby code.
> >> We'd also want a solution to the ".rbc turd" problem; I don't want to
> >> start littering people's systems with pre-parsed dump files.
> >
> > Oh, that's easy. Put it all in ~/.jruby or something instead of right
> > next to the .rb file. I had to do something very much like this for
> > redparse. If you want to borrow some code, take a look at
> > http://github.com/coatl/redparse/raw/master/lib/redparse/cache.rb. Who
> > knows, it might be useful to you.
>
> Actually the idea I had was to calculate a SHA1 hash of the source and
> use that as the ".rbj" filename. So loading the pre-parsed content (or
> pre-compiled content...I already have this support in JRuby for
> .class-compiled code) would involve a fast read, a SHA1 calculation,
> and then we have the right file to grab to avoid parsing. But would it
> be faster?
You also want to include the checksum of the parser as part of the
hash key, else you risk having weird problems where you fix a bug or
make a change in the parser, and then can't see the effect of that
when you re-parse things that are in the cache.
Charles Oliver Nutter
> Well, when you think about it, parsing is just a form of ast
> deserialization. I wouldn't expect it to be the fastest one, tho.
Right, and I'm sure with a hand-written serializer I could beat the
parser. But I haven't gone that far yet.
>> * Process-specific details like object/class identities, memory
>> locations, etc
>
> Ok, so some things (both code and data) have to be deserialized into
> the
> same address they had originally. Why should this be such a big deal?
> That's the way native executables (actual programs, not .so/.dll)
> normally work anyway. (The code/data sections are always loaded at the
> same address.)
One reason it might be a big deal is that JVM heaps are frequently
hundreds of megabytes. I'm not sure what portion of that could be
omitted when dumping runtime state (at least code and what data it
needs) to disk. And of course it may be optimistic to say you can only
dump a portion; code would need class data, and class data often
references (and is referenced by) objects in memory...
>> * Need to know whether previously-optimized code is still valid under
>> new runtime conditions; most optimistic optimizations in Hotspot, for
>> example, depend on being able to flag a compiled body of code *in
>> memory* as being "not entrant", so it will get thrown away
>
> Sounds like these flags are additional data that need to be
> (de)serialized.
>
>> * Maintaining a good relationship with code that ran previously, so if
>> it changes we know which saved optimizations we need to throw out
>
> Not sure exactly what that means, to be honest.
I just mean it would need to know how to cross-reference
previously-optimized code in the cache with code on disk, to know that
if certain files change, the related cached code is no longer valid.
>> Oh, and I forgot the primary point I wanted to make here... even
>> precompiling to Java code isn't faster than parsing, because in
>> addition to parsing the class file, the JVM also does a rigorous set
>> of verifications of compiled bytecode that actually costs *more* than
>> parsing the original Ruby code.
>
> Again, I have to wonder why this isn't cached.
On Java ME (and Android) devices, they do run verification
ahead-of-time and rewrite the .class/.jar files to indicate they're
good to go. I don't know of any desktop/server JVMs that support
anything like this, however.
>> Actually the idea I had was to calculate a SHA1 hash of the source and
>> use that as the ".rbj" filename. So loading the pre-parsed content (or
>> pre-compiled content...I already have this support in JRuby for
>> .class-compiled code) would involve a fast read, a SHA1 calculation,
>> and then we have the right file to grab to avoid parsing. But would it
>> be faster?
>
> This is almost exactly what I did in RedParse::Cache.
>
> You also want to include the checksum of the parser as part of the
> hash key, else you risk having weird problems where you fix a bug or
> make a change in the parser, and then can't see the effect of that
> when you re-parse things that are in the cache.
Yes, I figured I'd include a version header in the sha1-hashed content.
- Charlie
Charles Oliver Nutter
> I added some more benchmarking and it appears that there is a bit of
> startup overhead still...
>
> faster_rubygems: took 0.03s to load the cache files (50K)
> faster_rubygems: took 0.113s to scan the dirs for versions
> faster_rubygems total load time:0.203
>
> Obviously it did some other stuff, too, like a few requires etc.
>
> So it seems to me that about 50% of the faster_rubygems time currently
> could be avoided.
>
> Going back to the rake example, that "might" mean that you can run rake in
>
> 1.45s instead of 1.5s
>
> I'm not sure if this is worth chasing down or not...(low percentage,
> already close to zero), though I suppose if they had lots of gems it
> might get unwieldy, so I'll probably look at it eventually. More
> speed is always better, right?
It certainly can't hurt, but you're right...rapidly diminishing
returns at this point.
>> I also don't think we've ever talked about faster_require. How does it
>> speed up Rails loading?
>
> I haven't tried it with jruby loading rails...that would be interesting.
> What it does is basically override require to query a cache *first*
> for file location, then if it's not there, query the load path (which
> is what original require does).
...
> It speeds up 1.8 pretty good, and also works well with 1.9
>
> Unfortunately there are still a few bugs with it in 1.8, so I haven't
> released it yet, since I only use 1.9 and don't do rails much. I
> suppose I should though...
>
> You can try it out if you'd like to get feedback...
I'll try to test it out this week. Anything to get Rails booting
faster for JRuby users suffering today :)
- Charlie