Details
-
Type:
Bug
-
Status:
Resolved
-
Priority:
Major
-
Resolution: Fixed
-
Affects Version/s: JRuby 1.6
-
Fix Version/s: JRuby 1.7.0.pre1
-
Component/s: None
-
Labels:None
-
Environment:Ubuntu Linux, running jRuby under RVM
-
Number of attachments :
Description
I have a script called "works.rb". It's code is pretty simple:
require 'jruby/profiler'
profile_data = JRuby::Profiler.profile do
1000.times do |n| Hash.new end
endprofile_printer = JRuby::Profiler::GraphProfilePrinter.new(profile_data)
profile_printer.printProfile(STDOUT)}}
If I run export JRUBY_OPTS="--profile.api" && ruby works.rb everything works as expected. Here's the output:
Profiling enabled; ^C shutdown will now dump profile info
Total time: 0.02
%total %self total self children calls name
---------------------------------------------------------------------------------------------------------
100% 0% 0.02 0.00 0.02 1 (top)
0.02 0.01 0.01 1/1 Fixnum#times
---------------------------------------------------------------------------------------------------------
0.02 0.01 0.01 1/1 (top)
100% 43% 0.02 0.01 0.01 1 Fixnum#times
0.01 0.01 0.00 1000/1000 Class#new
---------------------------------------------------------------------------------------------------------
0.01 0.01 0.00 1000/1000 Fixnum#times
56% 38% 0.01 0.01 0.00 1000 Class#new
0.00 0.00 0.00 1000/1000 Hash#initialize
---------------------------------------------------------------------------------------------------------
0.00 0.00 0.00 1000/1000 Class#new
18% 18% 0.00 0.00 0.00 1000 Hash#initialize
However, JRUBY_OPTS gets ignored when running "works.rb" inside a rake task. I have the following Rakefile:
task :fails do
ruby "works.rb"
end
Running export JRUBY_OPTS="--profile.api" && rake fails returns:
Profiling enabled; ^C shutdown will now dump profile info
(in /home/goncalossilva/Desktop)
- Invoke fails (first_time)
- Execute fails
/home/goncalossilva/.rvm/rubies/jruby-1.6.0/bin/jruby works.rbTotal time: 0.00
%total %self total self children calls name
---------------------------------------------------------------------------------------------------------
100% 100% 0.00 0.00 0.00 0 (top)
This is due to the way we process JRUBY_OPTS conflicting with how we typically launch "ruby" commands. JRUBY_OPTS is processed by the command that launches JRuby, which is either a bash script or an executable. Normally, "ruby" commands run by e.g. Kernel#system are launched in-process to avoid a full JVM startup hit. This means that when using Rake's "ruby", we're starting a second JRuby instance in the same JVM, bypassing the launcher.
We have debated turning off "in-process launching" for some time, but are concerned about the startup hit that may result (as well as the many applications that launch commands like `ruby blah.rb` which wouldnt' find the "jruby" command).
Workarounds for you for the moment:
Leaving this open for discussion about other workarounds and debate about turning off or reducing in-process launching.